Tools for Troubleshooting PowerShell Remoting and WinRM (Part 2)

InPart 1 of this series, I introduced you to the PSDiagnostics module that's included with Windows PowerShell. I explained how to use it to write WinRM and Remoting trace events to an event log, and how to access the events in that log to help diagnose WinRM issues. Specifically, I focused on the Operational log, which is the human-readable log produced by the diagnostics system.

In this part, we're going to dig a bit deeper. If you want to follow along, you'll need to download a PSDiagnostics demo script, which was created by Microsoft, as well as a script called Construct-PSRemoteDataObject.ps1, also created by Microsoft (and provided to me by them, and posted with permission - thanks to the PowerShell team for making that happen). Obviously, because both these scripts and the PSDiagnostics module itself are, well, scripts, you're going to need to run these in a shell that has an ExecutionPolicy that permits scripting.

I'm not actually going to focus on the demo script - that's for your reference. You can download them from my site at http://concentratedtech.com/download. Just look for "PSDiagnostics.zip" in the file list (you'll also find past slide decks and demo scripts from conferences where Concentrated Technology has presented - help yourself to whatever you like). Note that the demo script is pretty informal - it uses a lot of cmdlet aliases. If you use PrimalScript, you can open the script and (from the Edit menu) convert those aliases to full cmdlet names to make it a bit easier to follow. 

First, load the PSDiagnostics module. I'm also going to dot-source the Construct-PSRemoteDataObject.ps1 script, bringing its functions into the global shell. I've put that script into a folder called C:PSDiagnostics, so I'll run these two commands:
 

PS C:UsersAdministrator> cd

PS C:> import-module psdiagnostics

PS C:> . C:PSDiagnosticsConstruct-PSRemoteDataObject.ps1

This should work on any machine where PowerShell v2 is installed, and where you've downloaded the Construct-PSRemoteDataObject.ps1 script, which is included in the ZIP file I referenced above.

First, keep in mind that we're going to use both the Operational and Analytic logs, so I want to quickly check them.
 

Get-LogProperties Microsoft-Windows-PowerShell/Operational

Get-LogProperties Microsoft-Windows-PowerShell/Analytic

I found that my Operational log was Enabled, but that the Analytic log was not. Which makes sense - it isn't listed in the graphical Event Viewer snap-in, either. I really struggled with this - but then I remembered the demo the PowerShell team gave us at the 2011 MVP Summit. Here's the trick: In the Event Viewer (which is in the Server Manager application in the Server OS), right-click the Event Viewer node, select View, and select "Show Analytic and Debug Logs." Then browse to the logs:
 

Applications and Services Logs > Microsoft > Windows > PowerShell

Applications and Services Logs > Microsoft > Windows > Windows Remote Management

You should now see the Analytic logs for both Windows PowerShell and Windows Remote Management. Right-click them to find the option to Enable them. Now, back in the shell, enable a trace. This actually turns on logging.
 

PS C:> Enable-PSWSManCombinedTrace

C:UsersAdministratorAppDataLocalTemptmp416E.tmp

The command completed successfully.

Now you can start trying to do WinRM stuff, and whatever you do will be logged in fairly excruciating detail. For example, I'll invoke a simple command on a remote computer:
 

PS C:> invoke-command -ScriptBlock { dir c: } -ComputerName SERVER-R2

    Directory: C:

Mode                LastWriteTime     Length Name           PSComputerName

----                -------------     ------ ----           --------------

d----        11/21/2009  10:02 AM            inetpub        server-r2

d----         7/13/2009   8:20 PM            PerfLogs       server-r2

d-r--        11/21/2009  12:21 PM            Program Files  server-r2

d-r--        11/21/2009  11:51 AM            Program Files  server-r2

                                             (x86)

d----         3/19/2011   7:32 AM            PSDiagnostics  server-r2

d-r--        11/21/2009  10:04 AM            Users          server-r2

d----        12/11/2009  11:44 AM            Windows        server-r2

-a---         3/14/2011   8:27 AM    9771448 baseline.xml   server-r2

-a---         3/15/2011  12:36 PM    1679464 day1-morning.t server-r2

                                             xt

-a---         3/14/2011   6:41 AM       3154 dir.txt        server-r2

-a---         3/14/2011   8:03 AM     102328 output.html    server-r2

-a---         3/14/2011   8:20 AM    2341628 service.xml    server-r2

-a---         3/14/2011   8:20 AM      36337 services.csv   server-r2

-a---         3/15/2011  12:30 PM         32 test.ps1       server-r2

-a---         3/14/2011  11:42 AM        151 users.csv      server-r2

Now I'll disable tracing, which stops new events from being written to the logs:
 

PS C:> Disable-PSWSManCombinedTrace

The command completed successfully.

The command completed successfully.

Now we can go into the Operational log, as in Part 1 of this series, and see what happened. But far more interestingly, we can go into the Analytic log as well. Unfortunately it's full of gibberish - I said earlier that this wasn't intended to be human-readable, and it isn't. You can also retrieve trace information directly from the ETL file, which is stored in PowerShell's installation folder:
 

PS C:> get-winevent -path $pshometracespstrace.etl -oldest

TimeCreated                   ProviderName                                             Id Message

-----------                   ------------                                             -- -------

3/19/2011 7:45:55 AM          Microsoft-Windows-WinRM                                 255 Activity Transfer

3/19/2011 7:47:47 AM          Microsoft-Windows-PowerShell                          12035 ComputerName resolved to S...

3/19/2011 7:47:47 AM          Microsoft-Windows-PowerShell                          12038 Connection Paramters are ...

3/19/2011 7:47:47 AM          Microsoft-Windows-PowerShell                           8193 Creating Runspace object ...

3/19/2011 7:47:47 AM          Microsoft-Windows-PowerShell                           8194 Creating RunspacePool obje...

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                 257 Initializing WSMan API

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                   2 Initializing WSMan API

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                 293 Initialization of WSMan AP...

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                  29 Initialization of WSMan AP...

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                 261 Creating WSMan Session. Th...

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                   6 Creating WSMan Session. Th...

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                 295 WSMan Create Session opera...

3/19/2011 7:47:47 AM          Microsoft-Windows-WinRM                                  31 WSMan Create Session opera...

That's awesomely-detailed information about what's happening, both at the PowerShell level and at the underlying WinRM level. In fact, let's look at some of those messages in more detail:
 

PS C:> get-winevent -path $pshometracespstrace.etl -oldest | select -expand message -first 10

Activity Transfer

ComputerName resolved to SERVER-R2

Connection Paramters are

 Connection URI: http://server-r2/wsman

 Resource URI: http://schemas.microsoft.com/powershell/Microsoft.PowerShell

 User: current user

 OpenTimeout: 180000

 IdleTimeout: 240000

 CancelTimeout: 60000

 AuthenticationMechanism: 0

 Thumb Print: no thumb print

 MaxUriRedirectionCount: 0

 MaxReceivedDataSizePerCommand: -1

 MaxReceivedObjectSize: -1

Creating Runspace object

         Instance Id: ef4446c2-6eac-4b8f-a827-f73191c6a7a5

Creating RunspacePool object

         InstanceId 5edead1e-b5ed-49d8-9f1a-1408828bd960

         MinRunspaces 1

         MaxRunspaces 1

Initializing WSMan API

Initializing WSMan API

Initialization of WSMan API completed successfuly

Initialization of WSMan API completed successfuly

Creating WSMan Session. The connection string is: SERVER-R2/wsman?PSVersion=2.0

Good grief, have you ever seen anything so granular and clear? I can see exactly what's happening. But you'll sometimes run across messages that contain gibberish:
 

PS C:> get-winevent -path $pshometracespstrace.etl -oldest | ? { $_.id -eq '32868' } | select -expand message

Sent remoting fragment.

         Object Id: 1

         Fragment Id: 0

         Start Flag: 1

         End Flag: 1

         Payload Length: 892

         Payload Data: 0x02000000020001001EADDE5EEDB5D8499F1A1408828BD96000000000000000000000000000000000EFBBBF3C4F626A

05265

6649643D2230223E3C4D533E3C56657273696F6E204E3D2270726F746F636F6C76657273696F6E223E322E313C2F56657273696F6E3E3C566572736

96F6E204E3D22505356657273696F6E223E322E303C2F56657273696F6E3E3C56657273696F6E204E3D2253657269616C697A6174696F6E56657273

696F6E223E312E312E302E313C2F56657273696F6E3E3C4241204E3D2254696D655A6F6E65223E414145414141442F2F2F2F2F41514141414141414

1414145415141414142785465584E305A57307551335679636D567564464E356333526C62565270625756616232356C424141414142647458304E68

5932686C5A455268655778705A32683051326868626D646C63773174583352705932747A54325A6D63325630446D316663335268626D5268636D524

F5957316C446D31665A47463562476C6E6148524F5957316C417741424152785465584E305A573075513239736247566A64476C76626E4D75534746

7A61485268596D786C43516B4341414141414D446338627A2F2F2F384B436751434141414148464E356333526C62533544623278735A574E3061573

9756379354959584E6F644746696247554841414141436B78765957524759574E3062334948566D567963326C76626768446232317759584A6C6368

424959584E6F5132396B5A56427962335A705A47567943456868633268546158706C4245746C65584D47566D46736457567A4141414441774146425

1734948464E356333526C62533544623278735A574E30615739756379354A51323974634746795A58496B55336C7A644756744C6B4E766247786C59

3352706232357A4C6B6C4959584E6F5132396B5A56427962335A705A475679434F78524F4438424141414143676F4C4141414143514D414141414A4

2414141414241444141414141514141414167493277634141424145414141414151414141416B4641414141424155414141416855336C7A64475674

4C6B647362324A6862476C3659585270623234755247463562476C6E614852556157316C417741414141647458334E3059584A30425731665A57356

B423231665A475673644745414141414E445177413049682B4F612F4E694142513265772B6173364941476A45595167414141414C3C2F42413E3C2F

4D533E3C2F4F626A3E

Obviously, it isn't really gibberish - it's encoded data. This is where that script you downloaded will come in handy.
 

PS C:> get-winevent -path $pshometracespstrace.etl -oldest  | ? { $_.id -eq '32868' } | ForEach-Object { $idx = $_.message.indexof

("Payload Data: 0x"); $str = $_.message.substring($idx + ("Payload Data: 0x".length));Construct-PSRemoteDataObject $str

}

destination : Server

runspaceId  : 5edead1e-b5ed-49d8-9f1a-1408828bd960

messageType : SessionCapability

pipelineId  : 00000000-0000-0000-0000-000000000000

data        : Obj RefId="0">MS>Version N="protocolversion">2.1Version>Version N="PSVersion">2.0Version>Version

               N="SerializationVersion">1.1.0.1Version>BA N="TimeZone">AAEAAAD/////AQAAAAAAAAAEAQAAABxTeXN0ZW0uQ3Vyc

              mVudFN5c3RlbVRpbWVab25lBAAAABdtX0NhY2hlZERheWxpZ2h0Q2hhbmdlcw1tX3RpY2tzT2Zmc2V0Dm1fc3RhbmRhcmROYW1lDm1fZG

              F5bGlnaHROYW1lAwABARxTeXN0ZW0uQ29sbGVjdGlvbnMuSGFzaHRhYmxlCQkCAAAAAMDc8bz///8KCgQCAAAAHFN5c3RlbS5Db2xsZWN

              0aW9ucy5IYXNodGFibGUHAAAACkxvYWRGYWN0b3IHVmVyc2lvbghDb21wYXJlchBIYXNoQ29kZVByb3ZpZGVyCEhhc2hTaXplBEtleXMG

              VmFsdWVzAAADAwAFBQsIHFN5c3RlbS5Db2xsZWN0aW9ucy5JQ29tcGFyZXIkU3lzdGVtLkNvbGxlY3Rpb25zLklIYXNoQ29kZVByb3ZpZ

              GVyCOxROD8BAAAACgoLAAAACQMAAAAJBAAAABADAAAAAQAAAAgI2wcAABAEAAAAAQAAAAkFAAAABAUAAAAhU3lzdGVtLkdsb2JhbGl6YX

              Rpb24uRGF5bGlnaHRUaW1lAwAAAAdtX3N0YXJ0BW1fZW5kB21fZGVsdGEAAAANDQwA0Ih+Oa/NiABQ2ew+as6IAGjEYQgAAAALBA>

              MS>Obj>

The command at the top uses that script's Construct-PSRemoteDataObject function to decode the gibberish to a large degree. In fact, here's a better example:
 

destination : Client

runspaceId  : 00000000-0000-0000-0000-000000000000

messageType : SessionCapability

pipelineId  : 00000000-0000-0000-0000-000000000000

data        : Obj RefId="0">MS>Version N="protocolversion">2.1Version>Version N="PSVersion">2.0Version>Version

               N="SerializationVersion">1.1.0.1Version>MS>Obj>

destination : Client

runspaceId  : 5edead1e-b5ed-49d8-9f1a-1408828bd960

messageType : ApplicationPrivateData

pipelineId  : 00000000-0000-0000-0000-000000000000

data        : Obj RefId="0">MS>Obj N="ApplicationPrivateData" RefId="1">TN RefId="0">T>System.Management.Automatio

              n.PSPrimitiveDictionaryT>T>System.Collections.HashtableT>T>System.ObjectT>TN>DCT>En>S N="Key

              ">PSVersionTableS>Obj N="Value" RefId="2">TNRef RefId="0" />DCT>En>S N="Key">WSManStackVersionS>

              Version N="Value">2.0Version>En>En>S N="Key">PSCompatibleVersionsS>Obj N="Value" RefId="3">TN

              RefId="1">T>System.Version[]T>T>System.ArrayT>T>System.ObjectT>TN>LST>Version>1.0Version>

              Version>2.0Version>LST>Obj>En>En>S N="Key">SerializationVersionS>Version N="Value">1.1.0.1

              Version>En>En>S N="Key">BuildVersionS>Version N="Value">6.1.7600.16385Version>En>En>S N="Key

              ">PSVersionS>Version N="Value">2.0Version>En>En>S N="Key">CLRVersionS>Version N="Value">2.0.5

              0727.4927Version>En>En>S N="Key">PSRemotingProtocolVersionS>Version N="Value">2.1Version>En>

              DCT>Obj>En>DCT>Obj>MS>Obj>

What you're seeing is the raw XML transmitted back and forth by WinRM. Decoded like this, you can see that it's full of useful data - protocol versions and so forth. Other messages will include the data actually transmitted from the remote machine to you.

Now I'm going to break something in remoting on my machine - I won't tell you what, yet. Having done so, let's start fresh and try to invoke a command:
 

PS C:> Enable-PSWSManCombinedTrace

C:UsersAdministratorAppDataLocalTemptmpEBF0.tmp

The command completed successfully.

PS C:> invoke-command -ScriptBlock { ps } -ComputerName SERVER-R2

[server-r2] Connecting to remote server failed with the following error message : Access is denied.

n, see the about_Remote_Troubleshooting Help topic.

    + CategoryInfo          : OpenError: (:) [], PSRemotingTransportException

    + FullyQualifiedErrorId : PSSessionStateBroken

PS C:> Disable-PSWSManCombinedTrace

The command completed successfully.

The command completed successfully.

This is the most frustrating part about remoting, because "Access Denied" seems to be the only error message it wants to spew if anything goes wrong. That's partially because too-detailed an error could give an attacker information needed to compromise or further attack your environment. It's also partially because... well, I'm not sure everyone on the WinRM team really digs error messages. That said, let's see if the trace log got us anything more useful. Keep in mind that the trace was created on my client, and the server is the machine where I broke remoting somehow. First let's look at the PowerShell log:
 

PS C:> get-winevent -path $pshometracespstrace.etl -oldest | ? { $_.providername -match "powershell" } | select messa

ge

Message

-------

ComputerName resolved to SERVER-R2

Connection Paramters are ...

Creating Runspace object ...

Creating RunspacePool object ...

Opening RunspacePool

Sent remoting fragment. ...

Sent remoting fragment. ...

Runspace Id 01b5a4b0-9846-498b-b132-28872a2ab85a. Establishing a connection using WSMan Create Shell

Runspace Id 01b5a4b0-9846-498b-b132-28872a2ab85a. Callback received for WSMan Create Shell

Runspace Id: 01b5a4b0-9846-498b-b132-28872a2ab85a Pipeline Id: 00000000-0000-0000-0000-000000000000. WSMan reported ...

Runspace Id: 01b5a4b0-9846-498b-b132-28872a2ab85a Pipeline Id: 00000000-0000-0000-0000-000000000000. WSMan reported ...

Runspace Id: 01b5a4b0-9846-498b-b132-28872a2ab85a. Closing shell using WSManCloseShell

Runspace Id: 01b5a4b0-9846-498b-b132-28872a2ab85a. Callback received for WSManCloseShell

Most revealing are the two that say "WSMan reported..." - here they are in full:
 

Runspace Id 01b5a4b0-9846-498b-b132-28872a2ab85a. Callback received for WSMan Create Shell

Runspace Id: 01b5a4b0-9846-498b-b132-28872a2ab85a Pipeline Id: 00000000-0000-0000-0000-000000000000. WSMan reported an

error with error code: 5.

 Error message: Connecting to remote server failed with the following error message : Access is denied. For more inform

ation, see the about_Remote_Troubleshooting Help topic.

 StackTrace: null>

Runspace Id: 01b5a4b0-9846-498b-b132-28872a2ab85a Pipeline Id: 00000000-0000-0000-0000-000000000000. WSMan reported an

error with error code: 5.

 Error message: Connecting to remote server failed with the following error message : Access is denied. For more inform

ation, see the about_Remote_Troubleshooting Help topic.

 StackTrace: null>

Oh, joy - Access Denied. Well, that's what WinRM is telling PowerShell - so now we need to look at the WinRM log to see if it knows more than it's telling.
 

PS C:> get-winevent -path $pshometracespstrace.etl -oldest | ? { $_.providername -match "winrm" } | select -expand me

ssage

I'm going to pick and choose a few messages from the output, because there's a ton of it:
 

Initialization of WSMan API completed successfuly

Creating WSMan Session. The connection string is: SERVER-R2/wsman?PSVersion=2.0

WSMan Create Session operation completed successfuly

SOAP [client sending index 6 of 6 total chunks (189 bytes)] JTnVsbCI+ZmFsc2U8L0I+PEIgTj0iX2lzSG9zdFJhd1VJTnVsbCI+ZmFsc2

U8L0I+PEIgTj0iX3VzZVJ1bnNwYWNlSG9zdCI+ZmFsc2U8L0I+PC9NUz48L09iaj48L01TPjwvT2JqPg==creationXml>rsp:Shell>s:Body>

s:Envelope>

An error was encountered while processing an operation.

Error Code: 11001

The chosen authentication mechanism is Kerberos

Sending the request for operation CreateShell to destination machine and port SERVER-R2:5985

User COMPANYAdministrator authenticated successfully using Kerberos authentication

Authorizing the user

The authorization of the user was done successfully

Received the response from Network layer; status: 200 (HTTP_STATUS_OK)

Activity Transfer

An error was encountered while processing an operation.

Error Code: 5

Error String:f:WSManFault xmlns:f="http://schemas.microsoft.com/wbem/wsman/1/wsmanfault" Code="5" Machine="SERVER-R2">

f:Message>Access is denied. f:Message>f:WSManFault>

You have to put your detective hat on, here. You can see that my user successfully authenticated via Kerberos, and that communications across HTTP were successful (HTTP is what WinRM uses; you can see also that it uses port 5985 by default). I'm still showing "Access Denied," but this clearly isn't an authentication-type "Access Denied," like you might expect. This is something harder. So now we begin the troubleshooting. Is the port open in the firewall? Is the WinRM service started? A quick check shows that the firewall port was in fact closed - that's what I "broke." So our "Access denied" is "access through the firewall." Thanks to the log's detail, I didn't spend a long time troubleshooting permissions, which is what we tend to head for when we see "Access denied."

So let's be clear about something: Having a detailed log is not a substitute for knowing how the technology works. The log doesn't have a brain - it's just telling you what's happening. You still need to run all that data through a filter of intelligence that knows what should be happening - which is why I like to capture, and retain, traces of successful operations for later comparison. Call them my "baseline." I can then perform the exact same commands on a "broken" machine, and look for differences - that helps me pinpoint the problem more precisely.

I hope you'll find these tools useful. Again, thanks to the PowerShell team for making them available, and for a great demo on how to use them. In a future and final part to this article (which will be some time coming, unfortunately, due to my schedule), I'll look at some of the more common failure scenarios and show you what they look like in log form, so you'll be able to more easily spot them when you see them.