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:
 

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.
 

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:
 

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.
 

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:
 

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

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:
 

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:
 

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:
 

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

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:
 

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:
 

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:
 

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

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.
 

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

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.