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:\Users\Administrator> cd \
PS C:\> import-module psdiagnostics
PS C:\> . C:\PSDiagnostics\Construct-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:\Users\Administrator\AppData\Local\Temp\tmp416E.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 $pshome\traces\pstrace.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 $pshome\traces\pstrace.etl -oldest | select -expand message -first 10
Activity Transfer
ComputerName resolved to SERVER-R2
Connection Paramters are
 Connection URI: <a href="http://server-r2/wsman">http://server-r2/wsman</a>
 Resource URI: <a href="http://schemas.microsoft.com/powershell/Microsoft.PowerShell">http://schemas.microsoft.com/powershell/Microsoft.PowerShell</a>
 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 $pshome\traces\pstrace.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 $pshome\traces\pstrace.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        : <code style="color: #006699; font-weight: bold;">Obj RefId="0"><code style="color: #006699; font-weight: bold;">MS><code style="color: #006699; font-weight: bold;">Version N="protocolversion">2.1Version><code style="color: #006699; font-weight: bold;">Version N="PSVersion">2.0Version><code style="color: #006699; font-weight: bold;">Version
               N="SerializationVersion">1.1.0.1Version><code style="color: #006699; font-weight: bold;">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        : <code style="color: #006699; font-weight: bold;">Obj RefId="0"><code style="color: #006699; font-weight: bold;">MS><code style="color: #006699; font-weight: bold;">Version N="protocolversion">2.1Version><code style="color: #006699; font-weight: bold;">Version N="PSVersion">2.0Version><code style="color: #006699; font-weight: bold;">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        : <code style="color: #006699; font-weight: bold;">Obj RefId="0"><code style="color: #006699; font-weight: bold;">MS><code style="color: #006699; font-weight: bold;">Obj N="ApplicationPrivateData" RefId="1"><code style="color: #006699; font-weight: bold;">TN RefId="0"><code style="color: #006699; font-weight: bold;">T>System.Management.Automatio
              n.PSPrimitiveDictionaryT><code style="color: #006699; font-weight: bold;">T>System.Collections.HashtableT><code style="color: #006699; font-weight: bold;">T>System.ObjectT>TN><code style="color: #006699; font-weight: bold;">DCT><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key
              ">PSVersionTableS><code style="color: #006699; font-weight: bold;">Obj N="Value" RefId="2"><code style="color: #006699; font-weight: bold;">TNRef RefId="0" /><code style="color: #006699; font-weight: bold;">DCT><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key">WSManStackVersionS>
              <code style="color: #006699; font-weight: bold;">Version N="Value">2.0Version>En><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key">PSCompatibleVersionsS><code style="color: #006699; font-weight: bold;">Obj N="Value" RefId="3"><code style="color: #006699; font-weight: bold;">TN
              RefId="1"><code style="color: #006699; font-weight: bold;">T>System.Version[]T><code style="color: #006699; font-weight: bold;">T>System.ArrayT><code style="color: #006699; font-weight: bold;">T>System.ObjectT>TN><code style="color: #006699; font-weight: bold;">LST><code style="color: #006699; font-weight: bold;">Version>1.0Version>
              Version>2.0Version>LST>Obj>En><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key">SerializationVersionS><code style="color: #006699; font-weight: bold;">Version N="Value">1.1.0.1
              Version>En><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key">BuildVersionS><code style="color: #006699; font-weight: bold;">Version N="Value">6.1.7600.16385Version>En><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key
              ">PSVersionS><code style="color: #006699; font-weight: bold;">Version N="Value">2.0Version>En><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key">CLRVersionS><code style="color: #006699; font-weight: bold;">Version N="Value">2.0.5
              0727.4927Version>En><code style="color: #006699; font-weight: bold;">En><code style="color: #006699; font-weight: bold;">S N="Key">PSRemotingProtocolVersionS><code style="color: #006699; font-weight: bold;">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:\Users\Administrator\AppData\Local\Temp\tmpEBF0.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 $pshome\traces\pstrace.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: <code style="color: #006699; font-weight: bold;">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: <code style="color: #006699; font-weight: bold;">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 $pshome\traces\pstrace.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 COMPANY\Administrator 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:<code style="color: #006699; font-weight: bold;">f:WSManFault xmlns:f="<a href="http://schemas.microsoft.com/wbem/wsman/1/wsmanfault">http://schemas.microsoft.com/wbem/wsman/1/wsmanfault</a>" Code="5" Machine="SERVER-R2">
<code style="color: #006699; font-weight: bold;">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.


 

Please or Register to post comments.

What's PowerShell with a Purpose Blog?

Don Jones demystifies Windows PowerShell.

Blog Archive

Sponsored Introduction Continue on to (or wait seconds) ×