I’ll show how to set up a Powershell deployment script that makes all progress messages and error details available from within Release Management, and the Powershell streams and pipeline intricacies involved in this.

Introduction

In MS Release Management’s vNext model, you define a release template with one or more components on it. During the deployment of a component, MSRM takes care of copying the component’s files for you to the target server, but you have to provide your own Powershell script to perform the actual installation of these files. The output of this deployment script is then reported back as the detail log for the component.

However, If you’ve ever written your own Powershell deployment script for MSRM, you’ve probably found that things are not quite that easy: Where does MSRM copy the component files to, and why is this not the same as my current working folder? Why doesn’t my detail log contain any output? Why do I only see a stack trace if my deployment fails, instead of the progress up to the point of error? We’ll tackle each of these points in turn.

I’m using MS Release Management update 4 in an on-premise environment, in combination with Powershell 4.

Getting output from a deployment script

I’ve created a very simple Release Template with a “Hello World – Website” component on it, which consists of the acual website (website.zip) and the script to deploy it (Deploy.ps1).

To start off easy, I don’t want the deployment script to deploy anything, I just want it to print a message.  So I define the script as:

Write-Output "Hello world!"

After running a release with this component however, the detail log doesn’t even contain that, only:

Copying recursively from rmserverDeliverablesHelloWorldAppv1.0 to C:WindowsDtlDownloadsHello World - Website succeeded.

What gives? Well, MSRM doesn’t do anything with the pipeline output, but only includes the Verbose stream in the detail log. That is, in order to get some output, we should do:

Write-Verbose "Hello world!" -Verbose

This time, we do get our message in the detail log:

Copying recursively from rmserverDeliverablesHelloWorldAppv1.0 to C:WindowsDtlDownloadsHello World - Website succeeded.

Hello world!

This would be fine if all we wanted to log were our own messages, but most Cmdlets and commandline executables also produce information which is useful to include in the detail log. Rather than piping each individual invocation to Write-Verbose (which quickly gets tedious), we can use the Powershell pipeline for this: We’ll perform all installation actions inside a Deploy() function, and pipe its (regular, i.e. stdout) output to the Verbose stream when we invoke this function:

function Deploy()
{
    Write-Output "Hello world!"

    # Example of an executable that only produces stdout output
    tracert 127.0.0.1
}

# Invoke, and redirect all output to the Verbose stream
Deploy | Write-Verbose -Verbose

Output:

Copying recursively from rmserverDeliverablesHelloWorldAppv1.0 to C:WindowsDtlDownloadsHello World - Website succeeded.

Hello world!



Tracing route to TargetServer [127.0.0.1]

over a maximum of 30 hops:



  1    <1 ms    <1 ms    <1 ms  TargetServer [127.0.0.1] 



Trace complete.

As you can see, this is a great way to get all stdout output logged while keeping your actual deployment logic free from clutter. The only thing that’s not so nice is the number of empty lines – it appears that MSRM outputs an extra newline for every string in the Verbose stream.

This can be countered by using the Out-String cmdlet, which, according to MSDN “converts the objects that Windows PowerShell manages into an array of strings. By default, Out-String accumulates the strings and returns them as a single string“:

Deploy | Out-String | Write-Verbose -Verbose

Because the result of “Deploy | Out-String” is now a single string with newline characters rather than an array of strings, MSRM adds its own newline character only at the end of the combined string rather than inserting an empty line after every string:

Copying recursively from rmserverDeliverablesHelloWorldAppv1.0 to C:WindowsDtlDownloadsHello World - Website succeeded.

Hello world!

Tracing route to TargetServer [127.0.0.1]
over a maximum of 30 hops:

  1    <1 ms    <1 ms    <1 ms  TargetServer [127.0.0.1] 

Trace complete.

Accessing the deployment files

When you want to access your component files from within the deployment script, for example to copy or extract them:

function Deploy()
{
    Write-Output "Hello world!"
    copy Website.zip C:inetpubwwwroot
}

Deploy | Out-String | Write-Verbose -Verbose

…you’ll run into the following problem:

Cannot find path 'C:UsersLeonAppDataLocalTemplocalhost_5985Website.zip' because it does not exist.

Apparently, the location where MSRM copies the component files to is not the same as the working directory from where your deployment script is started. As can be seen from the logs, the files are always copied to C:WindowsDtlDownloads<component name>, whereas your script is run from a Temp directory inside the profile folder of the user that makes the PSRemoting connection.

Luckily, MSRM passes in a lot of system variables when it runs your deployment script, one of them being $Global:ApplicationPath which contains the directory where the component files have been copied to. I like my Deploy() function to be able to access the component files from the current working dir, so I usually set $pwd prior to invoking Deploy():

function Deploy()
{
    Write-Output "Hello world!"
    copy Website.zip C:inetpubwwwroot
}

# Change $pwd to C:WindowsDtlDownloadsHello World - Website
pushd $Global:ApplicationPath
Deploy | Out-String | Write-Verbose -Verbose
popd	# Revert working dir.

Now the files can be accessed successfully.

Note that the Global variable scope is not required per se, but it allows you to access this particular value if you’ve also created a local variable with the name name which then “shadows” the global variable.

Stopping on the first error while keeping your detail log

By default, the deployment script is run with $ErrorActionPreference set to Continue, which means that any error is reported, but the script continues to run.

I find that, when creating a deployment script, a lot of operations depend on the success of the operations prior to it. Once something goes wrong (for example, the website that should be updated doesn’t exist in IIS yet) there is usually little point in continuing with the rest of the script, and may in fact do more harm than good.

Fortunately, this behaviour can be altered by setting $ErrorActionPreference to Stop at the start of your script:

function Deploy()
{
    $ErrorActionPreference = "Stop"

    Write-Output "Step 1..."
    Write-Output "Step 2..."
    copy XYZ:ThisDriveDoesntExist.txt .

    Write-Output "Step 3..."
    md "Step3"
}

pushd $Global:ApplicationPath
Deploy | Out-String | Write-Verbose -Verbose
popd

With this $ErrorActionPreference set, the script will now throw an Exception on the copy statement and Step 3 will never be executed, which is what we wanted. However, the detail log now only contains a stack trace with the error, but none of the progress messages written so far. So even though you know what went wrong, you have to guess where it happened in your script – this can be a serious handicap, especially with larger deployment scripts:

System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.AggregateException: One or more errors occurred. ---> Microsoft.TeamFoundation.Release.Common.Helpers.OperationFailedException: Copying recursively from rmserverDeliverablesHelloWorldAppv1.0 to C:WindowsDtlDownloadsHello World - Website succeeded.

System.AggregateException: Failed to execute the powershell script. Consult the logs below for details of the error.
System.Management.Automation.ActionPreferenceStopException: The running command stopped because the preference variable "ErrorActionPreference" or common parameter is set to Stop: Cannot find drive. A drive with the name 'XYZ' does not exist.
   at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input)
   at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke)
   ...

The reason that none of the progress messages were written to the Verbose stream lies in the use of Out-String, which collects all output from the Deploy() function before producing its own result – if an Exception is generated before that moment, Out-String never gets to complete its result and nothing is passed on to Write-Verbose.
(Conversely, if we were to leave out Out-String, or use it with the -Stream option, each object produced by Deploy() would be sent immediately down the pipeline, via Output-String to Write-Verbose, without waiting for the Deploy() function to finish – in this case, everything up to this point would be available in the detail log, but we would have back the empty lines after every string.)

The solution is to still let the Exception be raised so that processing is halted, but to catch it before it leaves the Deploy() function:

function Deploy()
{
    $ErrorActionPreference = "Stop"

    try
    {
        Write-Output "Step 1..."
        Write-Output "Step 2..."
        copy XYZ:ThisDriveDoesntExist.txt .

        Write-Output "Step 3..."
        md "Step3"
    }
    catch
    {
        # Powershell tracks all Exceptions that occured so far in $Error.
        Write-Output "$Error"
    }
}

pushd $Global:ApplicationPath
Deploy | Out-String | Write-Verbose -Verbose
popd

With this, both the Verbose messages and the error get logged, which is good, but now MSRM thinks that the deployment was successful (because it hasn’t seen any Exceptions) and marks the release as Succeeded – which is clearly wrong.

But next to letting MSRM catch an Exception, you can also signal a failed deployment to MSRM by writing a message to the Error stream:

catch
{
    # Powershell tracks all Exceptions that occured so far in $Error, log these
    Write-Output "$Error"

    # Signal failure to MSRM:
    $ErrorActionPreference = "Continue"
    Write-Error "Error: $Error"
}

This way, MSRM correctly identifies that the deployment script has failed, without losing any of the progress messages.

Note that it’s important that $ErrorActionPreference is set to Continue prior to invoking Write-Error; without it, invoking Write-Error will cause it to raise its own Exception, causing Out-String to not pass anything on to Write-Verbose and putting us back on square one.

Also note that although both the Verbose and the Error stream are included in the detail log, their messages are reported as separate blocks of text rather than being printed in the order they were generated. By also writing the $Error to the Verbose stream, it gets printed right after the last successful progress message, which makes more sense.

Conclusion

After all the things we’ve seen and tried, the final script is almost deceivingly simple – but also deceivingly difficult to get right if you’re not a Powershell veteran and you just want to change “this one thing” in the output. If nothing else, I hope that this post has given you some understanding of how Powershell’s streams and pipeline behave when you change some of these things.

For future reference, the final script template has become this:

function Deploy()
{
    $ErrorActionPreference = "Stop"

    try
    {
    	#
    	# Deployment actions go here.
    	#
    }
    catch
    {
        # Powershell tracks all Exceptions that occured so far in $Error
        Write-Output "$Error"

        # Signal failure to MSRM:
        $ErrorActionPreference = "Continue"
        Write-Error "Error: $Error"
    }
}

pushd $Global:ApplicationPath
Deploy | Out-String | Write-Verbose -Verbose
popd

Cheers!