Troubleshooting WinRM and PowerShell Remoting (Part 1)

One of the neat things about being an MVP Award recipient is the annual MVP Summit, where Microsoft invites its MVPs to the Redmond campus for a week of technical sessions, the occasional dinner out, and a lot of product feedback-gathering. Last week, I had the pleasure of spending most of the time with various members of the Windows PowerShell team. In addition to bouncing ideas off of us, talking about the issues we were seeing in the community, and so forth, we also got a great demo of how to troubleshoot WinRM.

The demo arose from our complaint that WinRM error messages tended to be vague ("access denied"), and that WinRM contained too many undocumented "moving parts" for us (or anyone) to accurately troubleshoot. One team member asked if we'd ever had any luck in using the PSDiagnostics module. After we stared blankly for a few minutes, he felt a demo was in order.

PSDiagnostics is a Microsoft-supplied module that's included with PowerShell v2. Unfortunately, it (unlike most Microsoft-shipped modules) contains zero documentation, so most of us have been a bit leery of trying it. Get started by running Import-Module PSDiagnostics. Essentially, you're going to turn on trace messages by running a command. Once tracing is turned on, you'll run whatever Remoting commands you want, and then check out the trace log for error messages and so forth. When you're finished, be sure to turn tracing back off again. Trace information goes into two of the new-style Windows event logs, which are viewable in the Event Viewer, or by running the Get-WinEvent command. Here's an example:
 

Import-Module PSDiagnostics

Enable-PsWsmanCombinedTrace

Invoke-Command -script { get-service } -computer SERVER-R2,NOTONLINE
Disable-PsWsmanCombinedTrace

One of those two computers is on my network; NOTONLINE is a bogus name. After running this, I popped open Server Manager. Under Event Viewer, go to "Applications and Services Logs" > Microsoft > Windows. From there, locate PowerShell and "Windows Remote Management." Both can contain two logs: Operational and Analysis. The Operational log is intended to be human-readable; the Analysis log contains more detailed information, but requires special Microsoft tools to decode. Here's a trick: Right-click a log and open its properties. Right at the top, you'll see its full name, such as Microsoft-Windows-PowerShell/Operational. You can use that with Get-WinEvent to query the log in PowerShell itself. After running the above, I found this:
 

PS C:> get-winevent -logname Microsoft-Windows-PowerShell/Operational -max 12 | select message

Message

-------

Modifying activity Id and correlating

Modifying activity Id and correlating

Modifying activity Id and correlating

Runspace Id: fecea362-466d-46f3-99f6-dd3557aa1112 Pipeline Id: 00000000-0000-0000-0000-000000000000. WSMan re...

Runspace Id: fecea362-466d-46f3-99f6-dd3557aa1112 Pipeline Id: 00000000-0000-0000-0000-000000000000. WSMan re...

Opening RunspacePool

Opening RunspacePool

Creating RunspacePool object ...

Creating Runspace object ...

Creating RunspacePool object ...

Creating Runspace object ...

Modifying activity Id and correlating

PS C:> get-winevent -logname Microsoft-Windows-WinRM/Operational -max 25 | select message

Message

-------

Closing WSMan Session completed successfuly

Closing WSMan Session

WSMan operation DeleteShell completed successfully

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

Sending response for operation DeleteShell

Sending response for operation Receive

Leaving the plugin for operation DeleteShell

Sending timeout response for operation: Receive

Entering the plugin for operation DeleteShell with a ResourceURI of http://schemas.microsoft.com/powershell/...

Processing client request for operation DeleteShell

Leaving the plugin for operation Signal

WSMan operation SignalShell failed, error code 995

Sending response for operation Signal

Entering the plugin for operation Signal with a ResourceURI of http://schemas.microsoft.com/powershell/Micro...

Processing client request for operation Signal

Authorizing the user

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

The authorization of the user was done successfully

Authorizing the user

User COMPANYAdministrator authenticated successfully using Kerberos authentication

Authorizing the user

The chosen authentication mechanism is Kerberos

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

Closing WSMan ReceiveShellOutput operation completed successfully

Closing WSMan operation

And that's just a subset - the WinRM log actually contained hundreds of messages. This is a LOT of detail, and can go a long way toward helping to troubleshoot WinRM operations. 

This should get you started, but in the next part of this article series I'll dive into the WinRM traffic log and explain what's going on with individual successful and failed connections. In later articles, I'll cover that Analysis log, and show you how to use a tool that can decode the information in it for an even more detailed look at what's happening in WinRM.