Export (0) Print
Expand All

Troubleshooting DSC

Published: June 24, 2013

Updated: October 17, 2013

Applies To: Windows PowerShell 4.0

This topic describes methods for getting your Desired State Configuration (DSC) scripts to run without error. By using logs effectively to track down errors, and understanding how to recycle the cache to see the immediate results of your resource changes, you’ll be able to troubleshoot DSC more effectively. These technics are discussed in two sections:

  • My script won’t run: Using DSC logs to diagnose script errors

  • My resources won’t update: How to reset the cache

My script won’t run: Using DSC logs to diagnose script errors

Like all Windows software, DSC records errors and events in logs that can be viewed from the Event Viewer. Examining these logs can help you understand why a particular operation failed, and how to prevent failure in the future. Writing configuration scripts can be tricky, so to make tracking errors easier as you author, use the DSC Log resource to track the progress of your configuration in the DSC Analytic event log.

Where are DSC event logs?

In Event Viewer, DSC events are in: Applications and Services Logs/Microsoft/Windows/Desired State Configuration

The corresponding PowerShell cmdlet, Get-WinEvent, can also be run to view the event logs:

PS C:\Users> Get-WinEvent -LogName "Microsoft-Windows-Dsc/Operational"
   ProviderName: Microsoft-Windows-DSC
TimeCreated                     Id LevelDisplayName Message                                                                                                  
-----------                     -- ---------------- -------                                                                                                  
11/17/2014 10:27:23 PM        4102 Information      Job {02C38626-D95A-47F1-9DA2-C1D44A7128E7} : 

DSC Event Log

As shown above, DSC’s primary log name is Microsoft->Windows->DSC (other log names under Windows are not shown here for brevity). The primary name is appended to the channel name to create the complete log name. The DSC engine writes mainly into three types of logs: Operational, Analytic, and Debug logs. Since the analytic and debug logs are turned off by default, you should enable them in Event Viewer. To do this, open Event Viewer by typing eventvwr in Windows PowerShell; or, click the Start button, click Control Panel, click Administrative Tools, and then click Event Viewer. On the View menu in Event viewer, click Show Analytic and Debug Logs. The log name for the analytic channel is Microsoft-Windows-Dsc/Analytic, and the debug channel is Microsoft-Windows-Dsc/Debug. You could also use the wevtutil utility to enable the logs, as shown in the following example.

  PS C:\Users> wevtutil.exe set-log “Microsoft-Windows-Dsc/Analytic” /q:true /e:true

What do DSC logs contain?

DSC logs are split over the three log channels based on the importance of the message. The operational log in DSC contains all error messages, and can be used to identify a problem. The analytic log has a higher volume of events, and can identify where error(s) occurred. This channel also contains verbose messages (if any). The debug log contains logs that can help you understand how the errors occurred. DSC event messages are structured such that every event message begins with a job ID that uniquely represents a DSC operation. The example below attempts to obtain the message from the first event logged into the operational DSC log.

PS C:\Users> $AllDscOpEvents=get-winevent -LogName "Microsoft-Windows-Dsc/Operational"
PS C:\Users> $FirstOperationalEvent=$AllDscOpEvents[0]
PS C:\Users> $FirstOperationalEvent.Message
Job {02C38626-D95A-47F1-9DA2-C1D44A7128E7} : 
Consistency engine was run successfully. 

DSC events are logged in a particular structure that enables the user to aggregate events from one DSC job. The structure is as follows:

Job ID : <Guid>

<Event Message>

Gathering events from a single DSC operation

DSC event logs contain events generated by various DSC operations. However, you’ll usually be concerned with the detail about just one particular operation. All DSC logs can be grouped by the job ID property that is unique for every DSC operation. The job ID is displayed as the first property value in all DSC events. The following steps explain how to accumulate all events in a grouped array structure.

Gathering Events from a Single DSC Operation
<##########################################################################
 Step 1 : Enable analytic and debug DSC channels (Operational channel is enabled by default)
###########################################################################>
 
wevtutil.exe set-log “Microsoft-Windows-Dsc/Analytic” /q:true /e:true
wevtutil.exe set-log “Microsoft-Windows-Dsc/Debug” /q:True /e:true
 
<##########################################################################
 Step 2 : Perform the required DSC operation (Below is an example, you could run any DSC operation instead)
###########################################################################>
 
Get-DscLocalConfigurationManager
 
<##########################################################################
Step 3 : Collect all DSC Logs, from the Analytic, Debug and Operational channels
###########################################################################>
 
$DscEvents=[System.Array](Get-WinEvent "Microsoft-windows-dsc/operational") `
         + [System.Array](Get-WinEvent "Microsoft-Windows-Dsc/Analytic" -Oldest) `
         + [System.Array](Get-Winevent "Microsoft-Windows-Dsc/Debug" -Oldest)
 
 
<##########################################################################
 Step 4 : Group all logs based on the job ID
###########################################################################>
$SeparateDscOperations=$DscEvents | Group {$_.Properties[0].value}  

Here, the variable $SeparateDscOperations contains logs grouped by the job IDs. Each array element of this variable represents a group of events logged by a different DSC operation, allowing access to more information about the logs.

PS C:\> $SeparateDscOperations
 
Count Name                      Group                                                                     
----- ----                      -----                                                                     
   48 {1A776B6A-5BAC-11E3-BF... {System.Diagnostics.Eventing.Reader.EventLogRecord, System.Diagnostics....
   40 {E557E999-5BA8-11E3-BF... {System.Diagnostics.Eventing.Reader.EventLogRecord, System.Diagnostics....
PS C:\> $SeparateDscOperations[0].Group
   ProviderName: Microsoft-Windows-DSC
TimeCreated                     Id LevelDisplayName Message                                               
-----------                     -- ---------------- -------                                               
12/2/2013 3:47:29 PM          4115 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4198 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4114 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4102 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4098 Warning          Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4098 Warning          Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4176 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...      
12/2/2013 3:47:29 PM          4182 Information      Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : ...       

You can extract the data in the variable $SeparateDscOperations using Where-ObjectFollowing are five scenarios in which you might want to extract data for troubleshooting DSC:

1: Operations failures

All events have severity levels. This information can be used to identify the error events:

PS C:\> $SeparateDscOperations  | Where-Object {$_.Group.LevelDisplayName -contains "Error"}
Count Name                      Group                                                                     
----- ----                      -----                                                                     
   38 {5BCA8BE7-5BB6-11E3-BF... {System.Diagnostics.Eventing.Reader.EventLogRecord, System.Diagnostics....

2: Details of operations run in the last half hour

TimeCreated, a property of every Windows event, states the time the event was created. Comparing this property with a particular date/time object can be used to filter all events:

PS C:\> $DateLatest=(Get-date).AddMinutes(-30)
PS C:\> $SeparateDscOperations  | Where-Object {$_.Group.TimeCreated -gt $DateLatest}
Count Name                      Group                                                                     
----- ----                      -----                                                                     
    1 {6CEC5B09-5BB0-11E3-BF... {System.Diagnostics.Eventing.Reader.EventLogRecord}   

3: Messages from the latest operation

The latest operation is stored in the first index of the array group $SeparateDscOperations. Querying the group’s messages for index 0 returns all messages for the latest operation:

PS C:\> $SeparateDscOperations[0].Group.Message
Job {5BCA8BE7-5BB6-11E3-BF41-00155D553612} : 
Running consistency engine.
Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : 
Configuration is sent from computer NULL by user sid S-1-5-18.
Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : 
Displaying messages from built-in DSC resources:
 WMI channel 1 
 ResourceID:  
 Message : [INCH-VM]:                            [] Starting consistency engine.
Job {1A776B6A-5BAC-11E3-BF41-00155D553612} : 
Displaying messages from built-in DSC resources:
 WMI channel 1 
 ResourceID:  
 Message : [INCH-VM]:                            [] Consistency check completed. 

4: Error messages logged for recent failed operations

$SeparateDscOperations[0].Group contains a set of events for the latest operation. Run the Where-Object cmdlet to filter the events based on their level display name. Results are stored in the $myFailedEvent variable, which can be further dissected to get the event message:

PS C:\> $myFailedEvent=($SeparateDscOperations[0].Group | Where-Object {$_.LevelDisplayName -eq "Error"})
 
PS C:\> $myFailedEvent.Message
Job {5BCA8BE7-5BB6-11E3-BF41-00155D553612} : 
DSC Engine Error : 
 Error Message Current configuration does not exist. Execute Start-DscConfiguration command with -Path pa
rameter to specify a configuration file and create a current configuration first. 
Error Code : 1 

5: All events generated for a particular job ID.

$SeparateDscOperations is an array of groups, each of which has the name as the unique job ID. By running the Where-Object cmdlet, you can extract those groups of events that have a particular job ID:

PS C:\> ($SeparateDscOperations | Where-Object {$_.Name -eq $jobX} ).Group
 
 
   ProviderName: Microsoft-Windows-DSC
 
TimeCreated                     Id LevelDisplayName Message                                               
-----------                     -- ---------------- -------                                               
12/2/2013 4:33:24 PM          4102 Information      Job {847A5619-5BB2-11E3-BF41-00155D553612} : ...      
12/2/2013 4:33:24 PM          4168 Information      Job {847A5619-5BB2-11E3-BF41-00155D553612} : ...      
12/2/2013 4:33:24 PM          4146 Information      Job {847A5619-5BB2-11E3-BF41-00155D553612} : ...      
12/2/2013 4:33:24 PM          4120 Information      Job {847A5619-5BB2-11E3-BF41-00155D553612} : ...  

Using xDscDiagnostics to analyze DSC logs

xDscDiagnostics is a PowerShell module that consists of two simple operations that can help analyze DSC failures on your machine: Get-xDscOperation and Trace-xDscOperation. These functions can help you identify all local events from past DSC operations, or DSC events on remote computers (with valid credentials). Here, the term DSC Operation is used to define a single unique DSC execution from its start to its end. For example, Test-DscConfiguration would be a separate DSC Operation. Similarly, every other cmdlet in DSC (such as Get-DscConfiguration, Start-DscConfiguration, etc.) could each be identified as separate DSC operations.The two cmdlets are explained in xDscDiagnostics PowerShell Module (DSC Resource Kit) and in more detail below. Help is available by running get-help <cmdlet name>.

Get-xDscOperation

This cmdlet lets you find the results of the DSC operations that run on one or multiple computers, and returns an object that contains the collection of events produced by each DSC operation.For example, in the following output, three commands were run. The first one passed, and the other two failed. These results are summarized in the output of Get-xDscOperation.

Get-xDscOperation that shows a simple output

Parameters

  • Newest – Accepts an integer value to indicate the number of operations to be displayed. By default, it returns 10 newest operations. For instance,

    Get-xDscOperation can display the last 5 operation
  • ComputerName – Parameter that accepts an array of strings, each containing the name of a computer from where you’d like to collect DSC event log data. By default, it collects data from the host machine. To enable this feature, you must run the following command in the remote machines, in elevated mode so that the will allow collection of events

    New-NetFirewallRule -Name "Service RemoteAdmin" -Action Allow    
    
  • Credential – Parameter that is of type PSCredential, which can help access to the computers specified in the ComputerName parameter.

Returned object

The cmdlet returns an array of objects each of type Microsoft.PowerShell.xDscDiagnostics.GroupedEvents. Each object in this array pertains to a different DSC operation. The default display for this object has the following properties

  • SequenceID: Specifies the incremental number assigned to the DSC operation based on time. For example, the last executed operation would have SequenceID as 1, the second to last DSC operation would have SequenceID of 2, and so on. This number is another identifier for each object in the returned array.

  • TimeCreated: A DateTime value that indicates when the DSC operation began.

  • ComputerName: The computer name from where the results are aggregated.

  • Result: A string with value Failure or Success that indicates if that DSC operation had an error or not, respectively.

  • AllEvents: An object that represents a collection of events produced by the DSC operation.

For example, the following output shows results of the last operation from multiple computers:

Get-xDscOperation can display remote computer logs

Trace-xDscOperation

This cmdlet returns an object containing a collection of events, their event types, and the message output generated from a particular DSC operation. Typically, when you find a failure in any of the operations using Get-xDscOperation, you would trace that operation to find out which of the events caused a failure.

Parameters

  • SequenceID: This is the integer value assigned to any operation, pertaining to a specific computer. By specifying a sequence ID of say, 4, the trace for the DSC operation that was 4th from the last will be output

    Trace-xDscOperation with sequence ID specified
  • JobID: This is the GUID value assigned by LCM xDscOperation to uniquely identify an operation. when a JobID is specified, the trace of the corresponding DSC operation is output.

    Trace-xDscOperation taking JobID as a parameter
  • Computer Name and Credential: These parameters allow the trace to be collected from remote computers:

    New-NetFirewallRule -Name "Service RemoteAdmin" -Action Allow
    
    Trace-xDscOperation run on a different compute

Note that, since Trace-xDscOperation aggregates events from the Analytic, Debug, and operational logs, it will prompt you to enable these logs as described above.

Returned object

The cmdlet returns an array of objects, each of type Microsoft.PowerShell.xDscDiagnostics.TraceOutput. Each object in this array contains the following fields:

  • ComputerName: The name of the computer from where the logs are being collected.

  • EventType: This is an enumerator type field that contains information on the type of event. It could be any of the following:

    • Operational: The event is from the operational log.

    • Analytic : The event is from the analytic log.

    • Debug : The event is from the debug log.

    • Verbose: Events output as verbose messages during execution. The verbose messages make it easy to identify the sequence of events that are published.

    • Error: Error events. By looking for the error events, you can usually quickly find the reason for the failure.

  • TimeCreated : A DateTime value indicating when the event was logged by DSC.

  • Message: The message that was logged by DSC into the event logs.

Following are fields in this object that can be used for more information about the event, but are not displayed by default:

  • JobID : The job ID (GUID format) specific to that DSC operation.

  • SequenceID: The SequenceID unique to that DSC operation in that computer.

  • Event: This is the actual event logged by DSC, of type System.Diagnostics.Eventing.Reader.EventLogRecord. This can also the obtained by running the cmdlet Get-Winevent. It contains more information, such as the task, eventID, and level of the event.

Alternately, you can gather information on the events by saving the output of Trace-xDscOperation into a variable. You can use the following command to display all the events for a particular DSC operation:

(Trace-xDscOperation-EquenceID3).Event

This will display the same results as the Get-Winevent cmdlet, such as in the output below:

Output that is identical to a get-winevent output

Ideally, you would first use Get-xDscOperations to list out the last few DSC configuration runs on your machines. Following this, you can examine any single operation (using its sequenceID or JobID) with Trace-xDscOperation to discover what it did behind the scenes.

My resources won’t update: How to reset the cache

The DSC engine caches resources implemented as a PowerShell module for efficiency purposes. However, this can cause problems when you are authoring a resource and testing it simultaneously because DSC will load the cached version until the process is restarted. The only way to make DSC load the newer version is to explicitly kill the process hosting the DSC engine.

Similarly, when you run Start-DSCConfiguration, after adding and modifying a custom resource, the modification may not execute unless, or until, the computer is rebooted. This is because DSC runs in the WMI Provider Host Process (WmiPrvSE), and usually, there are many instances of WmiPrvSE running at once. When you reboot, the host process is restarted and the cache is cleared.

To successfully recycle the configuration and clear the cache without rebooting, you must stop and then restart the host process. This can be done on a per instance basis, whereby you identify the process, stop it, and restart it. Or, you can use DebugMode, as demonstrated below, to reload the PowerShell DSC resource.

To identify which process is hosting the DSC engine and stop it on a per instance basis, you can list the process ID of the WmiPrvSE which is hosting the DSC engine. Then, to update the provider, stop the WmiPrvSE process using the commands below, and then run Start-DscConfiguration again.

###
### find the process that is hosting the DSC engine
###
$dscProcessID = Get-WmiObject msft_providers | 
Where-Object {$_.provider -like 'dsccore'} | 
Select-Object -ExpandProperty HostProcessIdentifier 

###
### Stop the process
###
Get-Process -Id $dscProcessID | Stop-Process

Using DebugMode

You can configure the DSC Local Configuration Manager (LCM) to use DebugMode to always clear the cache when the host process is restarted. When set to TRUE, it causes the engine to always reload the PowerShell DSC resource. Once you are done writing your resource, you can set it back to FALSE and the engine will revert to its behavior of caching the modules.

Following is a demonstration to show how DebugMode can automatically refresh the cache. First, let’s look at the default configuration:

PS C:\Users\WinVMAdmin\Desktop> Get-DscLocalConfigurationManager
 
 
AllowModuleOverwrite           : False
CertificateID                  : 
ConfigurationID                : 
ConfigurationMode              : ApplyAndMonitor
ConfigurationModeFrequencyMins : 30
Credential                     : 
DebugMode                      : False
DownloadManagerCustomData      : 
DownloadManagerName            : 
LocalConfigurationManagerState : Ready
RebootNodeIfNeeded             : False
RefreshFrequencyMins           : 15
RefreshMode                    : PUSH
PSComputerName                 :  

You can see that DebugMode is set to FALSE.

To set up the DebugMode demonstration, use the following PowerShell resource:

function Get-TargetResource
{
    param
    (
        [Parameter(Mandatory)]
        $onlyProperty
    )
    return @{onlyProperty = Get-Content -path "$env:SystemDrive\OutputFromTestProviderDebugMode.txt"}
}
function Set-TargetResource
{
    param
    (
        [Parameter(Mandatory)]
        $onlyProperty
    )
    "1"|Out-File -PSPath "$env:SystemDrive\OutputFromTestProviderDebugMode.txt"
}
function Test-TargetResource
{
    param
    (
        [Parameter(Mandatory)]
        $onlyProperty
    )
    return $false
} 

Now, author a configuration using the above resource called TestProviderDebugMode:

Configuration ConfigTestDebugMode
{
    Import-DscResource -Name TestProviderDebugMode
    Node localhost
    {
        TestProviderDebugMode test
        {
            onlyProperty = "blah"
        }
    }
}
ConfigTestDebugMode

You will see that the contents of file: “$env:SystemDrive\OutputFromTestProviderDebugMode.txt” is 1.

Now, update the provider code using the following script:

$newResourceOutput = Get-Random -Minimum 5 -Maximum 30
$content = @"
function Get-TargetResource
{
    param
    (
        [Parameter(Mandatory)]
        `$onlyProperty
    )
    return @{onlyProperty = Get-Content -path "$env:SystemDrive\OutputFromTestProviderDebugMode.txt"}
}
function Set-TargetResource
{
    param
    (
        [Parameter(Mandatory)]
        `$onlyProperty
    )
    "$newResourceOutput"|Out-File -PSPath C:\OutputFromTestProviderDebugMode.txt
}
function Test-TargetResource
{
    param
    (
        [Parameter(Mandatory)]
        `$onlyProperty
    )
    return `$false
}
"@ | Out-File -FilePath "C:\Program Files\WindowsPowerShell\Modules\MyPowerShellModules\DSCResources\TestProviderDebugMode\TestProviderDebugMode.psm1

This script generates a random number and updates the provider cade accordingly. With DebugMode set to false, the contents of the file “$env:SystemDrive\OutputFromTestProviderDebugMode.txt” are never changed.

Now, set DebugMode to TRUE in your configuration script:

LocalConfigurationManager
{
    DebugMode = $true
} 

When you run the above script again, you will see that the content of the file is different every time. (You can run Get-DscConfiguration to check it). Below is the result of two additional runs (your results may be different when you run the script):

PS C:\Users\WinVMAdmin\Desktop> Get-DscConfiguration -CimSession (New-CimSession localhost)
 
onlyProperty                            PSComputerName                         
------------                            --------------                         
20                                      localhost                              
 
PS C:\Users\WinVMAdmin\Desktop> Get-DscConfiguration -CimSession (New-CimSession localhost)
 
onlyProperty                            PSComputerName                         
------------                            --------------                         
14 

See Also



Was this page helpful?
(1500 characters remaining)
Thank you for your feedback

Community Additions

ADD
Show:
© 2014 Microsoft