Anyone who has had anything to do with FIM will probably have experienced moments where you question what is taking place and ask yourself if you really understand what FIM is doing at a specific point in time. This is partly due to FIM’s extraordinarily unpredictable error handling and logging.
While working on a long running FIM 2010 R2 project where we chose to make heavy use of PowerShell within action and authorisation workflows. We chose to make use of some of the PowerShell extensions for FIM 2010 R2 at Codplex. In particular we made use of:
- FIM PowerShell Workflow Activity from <http://fimpowershellwf.codeplex.com/releases/view/103872>
- FIM PowerShell module from <https://fimpowershellmodule.codeplex.com/>
By enabling FIM to execute PowerShell it enabled us to get FIM to do all kinds of things it otherwise did not have an out of the box capability for. Furthermore it made FIM’s interactions with other systems what I like to call “System Administrator” friendly. Most system administrators these days are pretty comfortable with PowerShell and can at least follow the logic inside of a PowerShell ps1 script.
So, this worked well for us and allowed us to pick the “FIM Extensions PowerShell Activity” from inside of a workflow and execute our very own PowerShell Scripts as part of Action or Authorisation Workflows.
This is awesome until something unexpected happens inside your scripts. In a complex environment where many PowerShell scripts may exist within close proximity of each other troubleshooting can be a less than pleasant experience.
While the concept of logging is nothing new, we did experiment with a few methods before arriving at one that made working with FIM PowerShell Extension more friendly, predictable and requiring standard analytical / system administration skills rather than a specialty in clairvoyance. Originally we started logging to a custom application log inside the windows event-log. This however was slow and cumbersome to view, particularly during the development and testing stages of our project. In the end we found it more helpful to have a single PowerShell text file log, that captured the output of all our scripts activities as executed as part of FIM workflows, allowing for an easier to read view of what has taken place and importantly in what order.
So here my learnings from the field:
Start by creating a function library. Here you can stash any functions and reduce the requirement for repetitive code within your PowerShell scripts. we called our library “fimlib.ps1”
Inside the fimlib.ps1 we wrote a function for logging to a txt file. The function allows us to define a severity ($severity), event code ($code) and a message ($message)
$logfile = “c:\EPASS\Logs\PowerShell”+(get-date -f yyyy-MM-dd)+”.log”
$loginclude = @(“DEBUG”,”INFO”,”WARNING”,”ERROR”,”JOBINFO”,”JOBDEBUG”)
$handle = $pid.ToString() + “.” + (get-random -Minimum 1000 -Maximum 2000).ToString()
function fimlog($severity,$code,$message) {
if ($loginclude -contains $severity) {
$date = get-date -format u
$user = whoami
$msg = “{” + $handle + “} ” + $date + ” [” + (get-pscallstack)[1].Command + “/” + $code + “/” + $severity + ” as ” + $user + “] – ” + $message
add-content $logfile $msg
}
}
Take note of the use of the “$handle” variable, here we are creating a code to identify individual threads based on the current PID and a randomish number.
The end result is a text based log file with events like the following:
I like to use NotePad++ to view the log as it has some nice features like automatic notification when there are new entries inside the log. The handle I mentioned earlier makes it easy to sort the log and isolate individual activities by finding all occurrences of an handle. Typically each PowerShell Script executed as a result of a workflow will have a unique handle.
So how do you make this work:
Firstly you’ll need to reference your library at the start of each of your PowerShell scripts. Add something like this to the start of your script:
# Load FIMLib.ps1
. C:\Lib\FIMLib.ps1
Whenever you need to log something you can simply call your “fimlog” function as follows:
fimlog “JOBINFO” 100 “This is something I’d like to log”
While this is nothing revolutionary, it helped me understand what was actually taking place in reality. Hopefully it can help you too.