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 psdiagnosticsPS 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/OperationalGet-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 > PowerShellApplications 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-PSWSManCombinedTraceC:\Users\Administrator\AppData\Local\Temp\tmp416E.tmpThe 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-r2d---- 7/13/2009 8:20 PM PerfLogs server-r2d-r-- 11/21/2009 12:21 PM Program Files server-r2d-r-- 11/21/2009 11:51 AM Program Files server-r2 (x86)d---- 3/19/2011 7:32 AM PSDiagnostics server-r2d-r-- 11/21/2009 10:04 AM Users server-r2d---- 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-PSWSManCombinedTraceThe 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 -oldestTimeCreated ProviderName Id Message----------- ------------ -- -------3/19/2011 7:45:55 AM Microsoft-Windows-WinRM 255 Activity Transfer3/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 API3/19/2011 7:47:47 AM Microsoft-Windows-WinRM 2 Initializing WSMan API3/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 10Activity TransferComputerName resolved to SERVER-R2Connection Paramters are Connection URI: http://server-r2/wsman User: current user OpenTimeout: 180000 IdleTimeout: 240000 CancelTimeout: 60000 AuthenticationMechanism: 0 Thumb Print: no thumb print MaxUriRedirectionCount: 0 MaxReceivedDataSizePerCommand: -1 MaxReceivedObjectSize: -1Creating Runspace object Instance Id: ef4446c2-6eac-4b8f-a827-f73191c6a7a5Creating RunspacePool object InstanceId 5edead1e-b5ed-49d8-9f1a-1408828bd960 MinRunspaces 1 MaxRunspaces 1Initializing WSMan APIInitializing WSMan APIInitialization of WSMan API completed successfulyInitialization of WSMan API completed successfulyCreating 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 messageSent remoting fragment. Object Id: 1 Fragment Id: 0 Start Flag: 1 End Flag: 1 Payload Length: 892 Payload Data: 0x02000000020001001EADDE5EEDB5D8499F1A1408828BD96000000000000000000000000000000000EFBBBF3C4F626A052656649643D2230223E3C4D533E3C56657273696F6E204E3D2270726F746F636F6C76657273696F6E223E322E313C2F56657273696F6E3E3C56657273696F6E204E3D22505356657273696F6E223E322E303C2F56657273696F6E3E3C56657273696F6E204E3D2253657269616C697A6174696F6E56657273696F6E223E312E312E302E313C2F56657273696F6E3E3C4241204E3D2254696D655A6F6E65223E414145414141442F2F2F2F2F415141414141414141414145415141414142785465584E305A57307551335679636D567564464E356333526C62565270625756616232356C424141414142647458304E685932686C5A455268655778705A32683051326868626D646C63773174583352705932747A54325A6D63325630446D316663335268626D5268636D524F5957316C446D31665A47463562476C6E6148524F5957316C417741424152785465584E305A573075513239736247566A64476C76626E4D755347467A61485268596D786C43516B4341414141414D446338627A2F2F2F384B436751434141414148464E356333526C62533544623278735A574E30615739756379354959584E6F644746696247554841414141436B78765957524759574E3062334948566D567963326C76626768446232317759584A6C6368424959584E6F5132396B5A56427962335A705A47567943456868633268546158706C4245746C65584D47566D46736457567A41414144417741464251734948464E356333526C62533544623278735A574E30615739756379354A51323974634746795A58496B55336C7A644756744C6B4E766247786C593352706232357A4C6B6C4959584E6F5132396B5A56427962335A705A475679434F78524F4438424141414143676F4C4141414143514D414141414A42414141414241444141414141514141414167493277634141424145414141414151414141416B4641414141424155414141416855336C7A644756744C6B647362324A6862476C3659585270623234755247463562476C6E614852556157316C417741414141647458334E3059584A30425731665A57356B423231665A475673644745414141414E445177413049682B4F612F4E694142513265772B6173364941476A45595167414141414C3C2F42413E3C2F4D533E3C2F4F626A3E
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 : ServerrunspaceId : 5edead1e-b5ed-49d8-9f1a-1408828bd960messageType : SessionCapabilitypipelineId : 00000000-0000-0000-0000-000000000000data : 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 : ClientrunspaceId : 00000000-0000-0000-0000-000000000000messageType : SessionCapabilitypipelineId : 00000000-0000-0000-0000-000000000000data : Obj RefId="0">MS>Version N="protocolversion">2.1Version>Version N="PSVersion">2.0Version>Version N="SerializationVersion">1.1.0.1Version>MS>Obj>destination : ClientrunspaceId : 5edead1e-b5ed-49d8-9f1a-1408828bd960messageType : ApplicationPrivateDatapipelineId : 00000000-0000-0000-0000-000000000000data : 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-PSWSManCombinedTraceC:\Users\Administrator\AppData\Local\Temp\tmpEBF0.tmpThe 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 : PSSessionStateBrokenPS C:\> Disable-PSWSManCombinedTraceThe 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 messageMessage-------ComputerName resolved to SERVER-R2Connection Paramters are ...Creating Runspace object ...Creating RunspacePool object ...Opening RunspacePoolSent remoting fragment. ...Sent remoting fragment. ...Runspace Id 01b5a4b0-9846-498b-b132-28872a2ab85a. Establishing a connection using WSMan Create ShellRunspace Id 01b5a4b0-9846-498b-b132-28872a2ab85a. Callback received for WSMan Create ShellRunspace 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 WSManCloseShellRunspace 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 ShellRunspace Id: 01b5a4b0-9846-498b-b132-28872a2ab85a Pipeline Id: 00000000-0000-0000-0000-000000000000. WSMan reported anerror with error code: 5. Error message: Connecting to remote server failed with the following error message : Access is denied. For more information, 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 anerror with error code: 5. Error message: Connecting to remote server failed with the following error message : Access is denied. For more information, 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 $pshome\traces\pstrace.etl -oldest | ? { $_.providername -match "winrm" } | select -expand message
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 successfulyCreating WSMan Session. The connection string is: SERVER-R2/wsman?PSVersion=2.0WSMan Create Session operation completed successfulySOAP [client sending index 6 of 6 total chunks (189 bytes)] JTnVsbCI+ZmFsc2U8L0I+PEIgTj0iX2lzSG9zdFJhd1VJTnVsbCI+ZmFsc2U8L0I+PEIgTj0iX3VzZVJ1bnNwYWNlSG9zdCI+ZmFsc2U8L0I+PC9NUz48L09iaj48L01TPjwvT2JqPg==creationXml>rsp:Shell>s:Body>s:Envelope>An error was encountered while processing an operation.Error Code: 11001The chosen authentication mechanism is KerberosSending the request for operation CreateShell to destination machine and port SERVER-R2:5985User COMPANY\Administrator authenticated successfully using Kerberos authenticationAuthorizing the userThe authorization of the user was done successfullyReceived the response from Network layer; status: 200 (HTTP_STATUS_OK)Activity TransferAn error was encountered while processing an operation.Error Code: 5Error 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.
