Powershell events from .Net object out of order

Question

I am scripting the execution of SQL scripts using Sql Server SMO with Powershell scripts. We have found two problems:

1. Powershell's event handling is processing out of sequence
2. Control is being returned to the calling script before all events have been processed (which kind of makes sense, given they are supposed to be asynchronous).

Given this script:

    Add-Type -AssemblyName "Microsoft.SqlServer.SMO, Version=12.0.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91" | Out-Null
Add-Type -AssemblyName "Microsoft.SqlServer.ConnectionInfo, Version=12.0.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91" | Out-Null

(Get-Date -format "dd-MMM-yyyy HH:mm:ss.fff") + ": Starting Script" | Out-File -FilePath $sqlOutputFilename -Append

$serverConnection = New-Object ('Microsoft.SqlServer.Management.Common.ServerConnection') "FTS-DEVSERVER", "SA", "avid4uin)*"

$serverSMO = new-object ('Microsoft.SqlServer.Management.Smo.Server') $serverConnection    

$sqlOutputFilename = "output.log"

$serverMessage = { (Get-Date -format "dd-MMM-yyyy HH:mm:ss.fff") + ": " + $EventArgs.Error.Message | Out-File -FilePath $event.MessageData -Append;}

Register-ObjectEvent -InputObject $serverSMO.ConnectionContext -EventName "ServerMessage" -Action $serverMessage -MessageData $sqlOutputFilename | Out-Null

$script = "
    declare @counter int = 0

    WHILE @Counter < 100
    BEGIN
        PRINT @Counter

        SET @Counter = @Counter + 1
    END

    GO
"

$databaseSMO = $serverSMO.Databases["master"]

$databaseSMO.ExecuteNonQuery($script) | Out-Null


(Get-Date -format "dd-MMM-yyyy HH:mm:ss.fff") + ": We believe the script is completed" | Out-File -FilePath $sqlOutputFilename -Append

Produces this output (trimmed for brevity)

15-Nov-2016 16:03:29.501: Starting Script
15-Nov-2016 16:03:29.521: Changed database context to 'master'.
15-Nov-2016 16:03:29.523: 5
15-Nov-2016 16:03:29.528: 0
15-Nov-2016 16:03:29.529: 6
15-Nov-2016 16:03:29.530: 7
15-Nov-2016 16:03:29.531: 8
15-Nov-2016 16:03:29.530: We believe the script is completed
15-Nov-2016 16:03:29.532: 9
15-Nov-2016 16:03:29.534: 10
15-Nov-2016 16:03:29.537: 11
15-Nov-2016 16:03:29.539: 12
15-Nov-2016 16:03:29.548: 13
15-Nov-2016 16:03:29.549: 14

We've used SMO before in native .Net applications and not seen this behavior that I can recall. We've tried adding sleeps to the execution of the code (before the final print) and it does not change anything other than slow down the script including the handling of the events like it's only on a single thread.

Answer 1

Register-ObjectEvent uses PoSh's job system behind the scenes to perform its function. All of your script's code is completing before the job completes. This is why you're seeing your completion message in an unexpected location.

To fix this you need to assign a variable to your Register-ObjectEvent call and remove your pipe to Out-Null. This will give you a handle to the job that's running in the background.

You then need to monitor the progress of your job with a loop. Something to the effect of:

Do{

    Start-Sleep -Seconds 1
    $check = Get-Job -Id $RegisteredEvent.Id

}Until(($check.State -ne "Running") -or ($check -eq $null))

This will effectively pause the script until the job completes. It also handles the possibility that your job was never created in the first place (in case of error or other such reason). Since your completion message line trails this code your completion message should be at the end of your log.