# Tuesday, August 18, 2009

One thing that has been lamented frequently about PowerShell is that it is very difficult to log, if not impossible, to log all of the various types of streams it has to a single source. The legacy Windows shell CMD, and Unix shells like Bash, Ksh etc only deal with three streams: stdin, stdout and stderr for Input, Ouput and Error respectively. PowerShell has many more: Input, Output, Verbose, Warning, Debug, Progress and Error. Finally, the APIs in v2.0 offer enough hooks to unify the logging but you got to work a bit to make it come together. Well, to be honest, you got me doing the work. The rest is easy ;)

import-module .\scriptlogger.psm1 -force

$logger = New-ScriptLogger

# override error handler
$logger.ErrorHandler = {
    param($record)
    
    $record.tostring() >> scriptlog.txt
}

# override verbose handler
$logger.VerboseHandler = {
    param($record)
    
    $record.message >> scriptlog.txt
}

# run scriptblock with logging
$logger.Invoke(
    {
        $verbosepreference='continue';
        $erroractionpreference = 'continue';
        $debugpreference = 'continue';
        write-verbose "verbose";
        write-error "an error";
        write-warning "a warning"
        Write-debug "debug string"
        "this is output"
        1,2,3
    })
And here is the module; save it as ScriptLogger.psm1. By default, all logging goes to an attached debugger, like sysinternals DbgView. You can override any of the handlers like above and do what you want. Each handler receives one argument: a ErrorRecord, WarningRecord, VerboseRecord, DebugRecord or ProgressRecord. All of these Types are native powershell types and are documented on MSDN.
<#
    Name     : Universal Script Logging Module (ScriptLogger.psm1)
    Version  : 0.1
    Author   : Oisin Grehan (MVP)
    Site     : http://www.nivot.org/
#>
function New-ScriptLogger {
    New-Module -AsCustomObject -ScriptBlock {
        
        $script:ps              = [powershell]::Create()
        $script:ar              = $null
        $script:module          = $ExecutionContext.SessionState.Module
        
        [scriptblock]
        $script:ErrorHandler    = {
            param(
                [Management.Automation.ErrorRecord]
                $record
            )
            [diagnostics.debug]::writeline(
                "Error: " + $record.tostring());
        }
        [scriptblock]
        $script:WarningHandler  = {
            param(
                [Management.Automation.WarningRecord]
                $record
            )        
            [diagnostics.debug]::writeline(
                "Warning: " + $record.message);
        }
        [scriptblock]
        $script:VerboseHandler  = {
            param(
                [Management.Automation.VerboseRecord]
                $record
            )
            [diagnostics.debug]::writeline(
                "Verbose: " + $record.message);
        }
        [scriptblock]
        $script:DebugHandler    = {
            param(
                [Management.Automation.DebugRecord]
                $record
            )
            [diagnostics.debug]::writeline(
                "Debug: " + $record.message);
        }
        [scriptblock]
        $script:ProgressHandler = {
            param(
                [Management.Automation.ProgressRecord]
                $record
            )        
            [diagnostics.debug]::writeline(
                "Progress: " + $record);
        }
        
        $script:Handlers   = @{
            Error = Register-ObjectEvent $ps.Streams.Error DataAdded -Action {
                & $event.MessageData {& $ErrorHandler @args} $event.sender[$eventargs.index]
            } -MessageData $module #-SupportEvent
            
            Warning = Register-ObjectEvent $ps.Streams.Warning DataAdded -Action {
                & $event.MessageData {& $WarningHandler @args} $event.sender[$eventargs.index]
            } -MessageData $module #-SupportEvent
            
            Verbose = Register-ObjectEvent $ps.Streams.Verbose DataAdded -Action {
                & $event.MessageData {& $VerboseHandler @args} $event.sender[$eventargs.index]
            } -MessageData $module #-SupportEvent
            
            Debug = Register-ObjectEvent $ps.Streams.Debug DataAdded -Action {
                & $event.MessageData {& $DebugHandler @args} $event.sender[$eventargs.index]
            } -MessageData $module #-SupportEvent
            
            Progress = Register-ObjectEvent $ps.Streams.Progress DataAdded -Action {
                & $event.MessageData {& $ProgressHandler @args} $event.sender[$eventargs.index]
            } -MessageData $module #-SupportEvent
        }
        
        function Invoke {
            param(
                [validatenotnullorempty()]
                [scriptblock]$script
            )
            
            try {
            
                write-host -foreground green "Running"
                
                $ps.commands.clear()
                $command = new-object management.automation.runspaces.command $script, $true            
                $ps.commands.addcommand($command) > $null                
                $ps.invoke() # returns output                
            
            } catch {
            
                # oops-ee!
                write-host -foreground red "Unhandled terminating error: $_"
                $record = new-object management.automation.errorrecord $(
                    new-object exception $_.tostring()), "TerminatingError", "NotSpecified", $null
                & $ErrorHandler $record
            
            } finally {
            
                write-host -foreground green "Complete"
            
            }
        }
                
        Export-ModuleMember -Function Invoke -Variable ErrorHandler, WarningHandler, VerboseHandler, DebugHandler, ProgressHandler
    }
}

Have fun!

posted on Tuesday, August 18, 2009 10:58:24 PM (Eastern Daylight Time, UTC-04:00)  #    Comments [1] Trackback
# Friday, August 14, 2009

update: 2009-09-27 - removed usage of closures - turns out i hadn't tested that modification properly. oops.

Here’s a quick one – in order to sway excessive BASH jealously, I knocked this up to persist the last 100 history items between PowerShell sessions. It hooks the special engine (as opposed to object) event “poweshell.exiting” and runs a script to save history to an XML file using the universally useful Export-CliXML cmdlet. Another trick in there is to use a closure to capture the value of the $historyPath variable. I need to do this because powershell event handlers use their own runspace (and will lose the values of the variables in the current runspace). I also could have passed the value via the –MessageData parameter and done it that way, but I figured I’m already in v2 territory so lets use that feature ;-)

# save last 100 history items on exit
$historyPath = Join-Path (split-path $profile) history.clixml

# hook powershell's exiting event & hide the registration with -supportevent.
Register-EngineEvent -SourceIdentifier powershell.exiting -SupportEvent -Action {
    Get-History -Count 100 | Export-Clixml (Join-Path (split-path $profile) history.clixml) }

# load previous history, if it exists
if ((Test-Path $historyPath)) {
    Import-Clixml $historyPath | ? {$count++;$true} | Add-History
    Write-Host -Fore Green "`nLoaded $count history item(s).`n"
}

Dump this into your profile and have fun!

posted on Friday, August 14, 2009 9:28:58 PM (Eastern Daylight Time, UTC-04:00)  #    Comments [0] Trackback
# Thursday, August 13, 2009

I’ve been reliably informed (and double checked) and I’m happy to relay to you all that PowerShell 2.0 is available as part of the Windows Management Framework RC. This includes the following components:

  • WinRM 2.0
  • Windows PowerShell 2.0
  • BITS 4.0

This is the culmination of nearly three years’ of work to bring Windows to the cutting edge of automation technology. Grab it while it’s toasty from:

https://connect.microsoft.com/windowsmanagement/Downloads

Spread the word!

posted on Thursday, August 13, 2009 10:06:02 PM (Eastern Daylight Time, UTC-04:00)  #    Comments [0] Trackback
# Saturday, July 18, 2009

updated 2009/7/20: added link to PSEventing for v1.0 event handling
updated 2009/7/24: added link to Get-Delegate script for v1.0 callbacks

There have been some nice improvements made in the latest build of PowerShell with respect to interop with the "callback” pattern in .NET. What exactly are callbacks anyway? It’s exactly what it sounds like, pretty much. In .NET there are sometimes APIs you need to call that expect you to hand them delegates (pointers to methods) which that API will call some time in the future, usually based on certain conditions being fulfilled. If that sounds a bit like .NET events, you’d be right. An event is a much gussied-up callback - it’s just a way of permitting multiple methods to be invoked in response to some condition.

Synchronous Callbacks in PowerShell v1.0

In .NET there are two types of callbacks: Asynchronous (non-blocking) and synchronous (blocking). In PowerShell v1.0, the only callbacks that were catered for were for EventHandler Delegates. This is the method signature that most of the Windows Forms controls expect to call back to in response to button clicks etc. You may have seen code similar to:

$button = new-object system.windows.forms.button
$button.add_Click( { $form.Close() } )

This works because in PowerShell v1.0, there is specialized support for this kind of callback to methods with the EventHandler signature, that is to say, methods with parameters of (object sender, EventArgs e). PowerShell is able to run the ScriptBlock in response to the button being clicked and will even pass the two arguments to the scriptblock for you. When the form is shown from a PowerShell script, there is a single thread that is running the message loop for the application. It is this same thread that handles running the script. In the PowerShell engine, there is a pool of threads created at startup, and each of them has its own “Runspace” for running scripts. Because it is one of the PowerShell threads that is running the application, that same thread is able to run the ScriptBlocks in its Runspace when called upon to do so. Although it is in a slightly roundabout way, this is an example of a synchronous callback. This single application thread is effectively waiting (blocked) for the callback to occur in response to a button click (in reality, it’s doing other things while waiting, but it’s still waiting.)

Some rather creative folks, namely one of the primary developers of PowerShell, wrote a delegate/scriptblock binder in pure script some years ago which you can use to pass script to a .NET api to be called back to in a synchronous manner.  See: Creating arbitrary delegates to ScriptBlocks.

If you want to work with .NET events in version 1.0 of PowerShell, you’ll need an add-on, like my PSEventing Snap-In.

Synchronous Callbacks in PowerShell v2.0

In the latest and greatest version of PowerShell, v2.0 RC (which comes with the public Windows 7 RC), synchronous callbacks got a whole lot easier. PowerShell is now able to deal with pretty much ANY delegate signature, automatically. Lets test this by using the .NET 3.5 System.Func<T, TResult> delegate. This is a generic delegate which lets us pass a method to an API expecting a callback to a method which has one parameters of type T1, and will return type T2. Because it’s generic, we get to pick which parameters. Lets demo creating a ScriptBlock that will be passed a DateTime and returns a String:

add-type –assembly system.core # load .net 3.5
$callback = [system.func[datetime, string]] { param($date); "the date is $date" }
$callback.Invoke( [datetime]::now )
# returns
”the date is 2009/07/14 21:50:35”

We can even take advantage of PowerShell’s super-versatile parameter binder by passing it in a string and having it get coerced to DateTime with ne’er a Parse in sight!

$callback.Invoke(“1/1/2009”)
”the date is 2009/01/01 00:00:00”

So, what’s the point of all this? Why go to all that trouble? Why not just write a function? The point is that functions cannot be called by .NET directly. So when would you need a callback like this in a PowerShell script?

Calling Web Services with Invalid, Untrusted or Expired SSL Certificates

The title says it all – sometimes you need to do this. Usually it’s because you’re working with self-signed, expired or otherwise invalid certificates on a QA or Development system. The New-WebServiceProxy Cmdlet in v2.0 is great for calling Web Services, but it doesn’t have a switch to ignore invalid certificates. If you were writing .NET code in C# or VB.NET, the way go about this is to pass a callback method to an API that expects a RemoteCertificateValidationCallback Delegate. This delegate is designed to point to a method that is passed a handful of arguments describing the attempted connection, and is expected to return a boolean; that is to say, true or false. True means “sure, the connection looks fine – go for it.” A value of False being returned tells .NET to stop the connection before it happens.

The amount of .NET code needed to do this is not a ton, but it’s still a fair handful of lines. Check out this example here: http://blog.jameshiggs.com/2008/05/01/c-how-to-accept-an-invalid-ssl-certificate-programmatically/

Now let’s see how much PowerShell script is needed for this same task:

[System.Net.ServicePointManager]::ServerCertificateValidationCallback = { $true }

Bwahahahah! Eat that, Mr. C# coder! Again, PowerShell’s binder comes into play here and automatically casts our ScriptBlock to a RemoteCertificateValidateCallback delegate (it’s not really a cast – there is no conversion – it’s a sizeable chunk of code.) From this point on, any attempts to use the New-WebServiceProxy Cmdlet with dodgy SSL certificates will succeed without so much as a warning. In fact, pretty much any other classes, like WebRequest will behave the same way. It’s important to note that this only affects the current AppDomain, that is to say, the current PowerShell process. Other processes on the system will continue to stick their nose up at dodgy SSL certs. Quit PowerShell and restart it -- or set that ServerCertificateValidationCallback property to $null -- and all is right in the world again. This works as long as you use one of PowerShell’s threads to do the work of connecting; i.e. don’t use an asynchronous request. This ensures there is a Runspace available to execute this ScriptBlock.

Converting Synchronous Callbacks into Events

This is really quite straightforward. Taking the previous example, we would generate an event inside the scriptblock using New-Event, and then bind one or more event handlers using the Register-EngineEvent Cmdlet:

[System.Net.ServicePointManager]::ServerCertificateValidationCallback = {
		new-event -SourceIdentifier SslCheck -MessageData $args > $null
		$true
	}
# dump out arguments to cert validate callback
Register-EngineEvent -SourceIdentifier SslCheck -Action { write-output $args }
Next time, we'll get into some meatier stuff. Have fun!

In Part Two: Asynchronous Callbacks in PowerShell v1.0 and v2.0

posted on Saturday, July 18, 2009 4:22:00 AM (Eastern Daylight Time, UTC-04:00)  #    Comments [0] Trackback

update: missing backtick ` to escape the $verbosepreference variable

A question came up on stack overflow (you don’t know what that is? shame on you!) today from someone asking how they could capture the Verbose stream from a pipeline they ran in a C# program. As it turns out, the same technique is used in script, so I’ll give that example instead since I’m sure the C# guys and gals will have no problem converting the script.

The key is using the new (to v2.0) System.Management.Automation.PowerShell Type, which has a built-in Type Accelerator of [powershell]. It has a static method, Create, which is used to create an instance. This instance is pretty much ready to roll. It has a Streams property, which is of Type PSDataStreams. This Type has properties representing each collection of Error, Progress, Verbose, Debug and Warning.

$ps = [powershell]::create()
$ps.Commands.AddScript("`$verbosepreference='continue'; write-verbose 42")
$ps.invoke()
$ps.streams.verbose
Which yields the VerboseRecord that was written out:
Message InvocationInfo                              PipelineIterationInfo
------- --------------                              ---------------------
42      System.Management.Automation.InvocationInfo {0, 0}
What's important to note about the above example is that I had to set the $verbosepreference to at least "continue" (the default is silentlycontinue) in order for the verbose record to be written. Have fun!
posted on Saturday, July 18, 2009 12:02:53 AM (Eastern Daylight Time, UTC-04:00)  #    Comments [0] Trackback