My previous post was about using the Azure Resource Manager to provision a Virtual Machine. It demonstrated how to use a custom PowerShell Desired State Configuration (DSC) to stripe, format and assign a drive letter to a storage space that contains thirty-two 1TB VHDs.
Debugging a custom PowerShell Desired State Configuration was a challenge, because I was completely new to PowerShell DSC and to the Azure Virtual Machine DSC Extension. This post is all about how I managed to debug, refine and test using the artifacts created by the Virtual Machine Extension.
Why is my DSC Failing?
The Azure Virtual Machine Extension for DSC gives us ways to test, debug and refine our Desired State Configurations. Finding that pesky bug can be challenging, don’t give up! Let’s take a look at what we should be looking for.
The Environment
To have something to work with, we need a Virtual Machine that uses the DSC Extension. So I used the Azure Resource Manager Template from my previous post to provision a brand-new VM.
Set-AzureSubscription -SubscriptionName (Get-AzureSubscription -Current).SubscriptionName -CurrentStorageAccountName 'briseboispackages'
$ModuleURL = "https://briseboispackages.blob.core.windows.net/windows-powershell-dsc/DiskConfiguration.ps1.zip"
$additionalParameters = New-Object -TypeName Hashtable
$additionalParameters["modulesUrl"] = $ModuleURL
Switch-AzureMode AzureResourceManager
New-AzureResourceGroup -Name "armmonstervm" `
-Location "westus" `
-TemplateFile 'WindowsVirtualMachine.json' `
-TemplateParameterFile 'WindowsVirtualMachine.param.dev.json' `
@additionalParameters `
-Force -Verbose
New-AzureResourceGroup Execution Trace
VERBOSE: 10:48:56 AM - Created resource group 'armmonstervm' in location 'westus' VERBOSE: 10:48:57 AM - Template is valid. VERBOSE: 10:48:58 AM - Create template deployment 'WindowsVirtualMachine'. VERBOSE: 10:49:06 AM - Resource Microsoft.Storage/storageAccounts 'msarmbrisebois' provisioning status is running VERBOSE: 10:49:11 AM - Resource Microsoft.Network/virtualNetworks 'msarmbriseboisvnet' provisioning status is running VERBOSE: 10:49:13 AM - Resource Microsoft.Network/publicIPAddresses 'PublicIP' provisioning status is running VERBOSE: 10:49:27 AM - Resource Microsoft.Network/publicIPAddresses 'PublicIP' provisioning status is succeeded VERBOSE: 10:49:27 AM - Resource Microsoft.Network/virtualNetworks 'msarmbriseboisvnet' provisioning status is succeeded VERBOSE: 10:49:32 AM - Resource Microsoft.Network/networkInterfaces 'VMNic' provisioning status is succeeded VERBOSE: 10:49:32 AM - Resource Microsoft.Storage/storageAccounts 'msarmbrisebois' provisioning status is succeeded VERBOSE: 10:49:40 AM - Resource Microsoft.Compute/virtualMachines 'msarmbrisebois' provisioning status is running VERBOSE: 11:08:28 AM - Resource Microsoft.Compute/virtualMachines 'msarmbrisebois' provisioning status is succeeded VERBOSE: 11:08:31 AM - Resource Microsoft.Compute/virtualMachines/extensions 'msarmbrisebois/dscExtension' provisioning status is running VERBOSE: 11:16:27 AM - Resource Microsoft.Compute/virtualMachines/extensions 'msarmbrisebois/dscExtension' provisioning status is succeeded
Now that we have a Virtual Machine to work with, it’s time to use Remote Desktop.
Switch-AzureMode AzureResourceManager
Get-AzureRemoteDesktopFile -ResourceGroupName 'armmonstervm' `
-Name 'msarmbrisebois' `
-LocalPath 'C:\Users\brisebois'
Location of The DSC VM Extension Artifacts
When the DSC Virtual Machine Extension executes, it installs DSC in C:\Packages\Plugins\Microsoft.Powershell.DSC\1.7.0.0. It will also download and extract our DSC Module to C:\Program Files\WindowsPowerShell\Modules.
Location: C:\Packages\Plugins\Microsoft.Powershell.DSC\1.7.0.0
This folder contains 3 important sub-folders that help us understand what is push to the Virtual Machine from the Azure Resource Manager and the status of the DSC execution.
RuntimeSettings
This folder contains the Extension Settings that allow us to validate that we have the correct settings in our Azure Resource Manager Template.
{
"runtimeSettings": [{
"handlerSettings": {
"publicSettings": {
"ModulesUrl": "https://briseboispackages.blob.core.windows.net/windows-powershell-dsc/DiskConfiguration.ps1.zip",
"SasToken": "",
"ConfigurationFunction": "DiskConfiguration.ps1\\DiskConfiguration",
"Properties": {
"StoragePoolFriendlyName": "storagespace0",
"VirtualDiskFriendlyName": "datadisk",
"DriveSize": 35184372088832,
"NumberOfColumns": 32
}
}
}
}]
}
DSCWork
This folder contains the configuration and the localhost.mof file. Use these assets to replay the DSC as if it were executed by the Extension.
Start-DscConfiguration -Path 'C:\Packages\Plugins\Microsoft.Powershell.DSC\1.7.0.0\DSCWork\DiskConfiguration.ps1.0\DiskConfiguration' `
-ComputerName localhost `
-Force `
-wait `
-Verbose `
-Debug
This execution produces an output that surfaces issues. Use this to identify where the DSC fails and what to address.
VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = SendConfigurationApply,'className' = MSFT_DSC
LocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.
VERBOSE: An LCM method call arrived from computer MSARMBRISEBOIS with user sid S-1-5-21-3103417715-464229043-512622935-500.
VERBOSE: An LCM method call arrived from computer MSARMBRISEBOIS with user sid S-1-5-21-3103417715-464229043-512622935-500.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Set ]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[StorageSpace]CreateStorageSpace]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Test ] [[StorageSpace]CreateStorageSpace]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Test ] [[StorageSpace]CreateStorageSpace] in 1.5790 seconds.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Set ] [[StorageSpace]CreateStorageSpace]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Set ] [[StorageSpace]CreateStorageSpace] in 62.5030 seconds.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Resource ] [[StorageSpace]CreateStorageSpace]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[VirtualDisk]CreateVirtualDisk]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Test ] [[VirtualDisk]CreateVirtualDisk]
DEBUG: [MSARMBRISEBOIS]: [[VirtualDisk]CreateVirtualDisk] datadisk
DEBUG: [MSARMBRISEBOIS]: [[VirtualDisk]CreateVirtualDisk] False
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Test ] [[VirtualDisk]CreateVirtualDisk] in 0.0710 seconds.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Set ] [[VirtualDisk]CreateVirtualDisk]
DEBUG: [MSARMBRISEBOIS]: [[VirtualDisk]CreateVirtualDisk] datadisk
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Set ] [[VirtualDisk]CreateVirtualDisk] in 2.4500 seconds.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Resource ] [[VirtualDisk]CreateVirtualDisk]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[Disk]InitializeDisk]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Test ] [[Disk]InitializeDisk]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Test ] [[Disk]InitializeDisk] in 0.2260 seconds.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Set ] [[Disk]InitializeDisk]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Set ] [[Disk]InitializeDisk] in 0.3820 seconds.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Resource ] [[Disk]InitializeDisk]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[DiskPartition]CreateDiskPartition]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Test ] [[DiskPartition]CreateDiskPartition]
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Test ] [[DiskPartition]CreateDiskPartition] in 0.1530 seconds.
VERBOSE: [MSARMBRISEBOIS]: LCM: [ Start Set ] [[DiskPartition]CreateDiskPartition]
Invalid Parameter
+ CategoryInfo : InvalidArgument: (:) [], CimException
+ FullyQualifiedErrorId : StorageWMI 5,New-Partition
+ PSComputerName : localhost
VERBOSE: [MSARMBRISEBOIS]: LCM: [ End Set ] [[DiskPartition]CreateDiskPartition] in 0.5880 seconds.
The PowerShell DSC resource cCreateDiskPartition threw one or more non-terminating errors while running the Set-TargetResource
functionality. These errors are logged to the ETW channel called Microsoft-Windows-DSC/Operational. Refer to this channel for more
details.
+ CategoryInfo : InvalidOperation: (:) [], CimException
+ FullyQualifiedErrorId : NonTerminatingErrorFromProvider
+ PSComputerName : localhost
The SendConfigurationApply function did not succeed.
+ CategoryInfo : NotSpecified: (root/Microsoft/...gurationManager:String) [], CimException
+ FullyQualifiedErrorId : MI RESULT 1
+ PSComputerName : localhost
VERBOSE: Operation 'Invoke CimMethod' complete.
VERBOSE: Time taken for configuration job to complete is 68.836 seconds
The error above is generated because of this following PowerShell.
Get-VirtualDisk -FriendlyName $VirtualDiskFriendlyName `
| Get-Disk `
| New-Partition -UseMaximumSize `
-AssignDriveLetter `
-DriveLetter Y `
| Format-Volume
It failed because I used both the AssignDriveLetter and the DriveLetter parameters. Removing the DriveLetter parameter allowed the script to auto assign the next available drive letter.
Status
This folder contains the DSC Status files. Are a great way to get insight into what happened when the VM Extension ran.
[{
"status": {
"substatus": [{
"status": "success",
"code": 1,
"name": "DscConfigurationLog",
"formattedMessage": {
"message": "Perform operation \u0027Invoke CimMethod\u0027 with following parameters, \u0027\u0027methodName\u0027 = SendConfigurationApply,\u0027className\u0027 = MSFT_DSCLocalConfigurationManager,\u0027namespaceName\u0027 = root/Microsoft/Windows/DesiredStateConfiguration\u0027.\r\nAn LCM method call arrived from computer MSARMBRISEBOIS with user sid S-1-5-18.\r\nAn LCM method call arrived from computer MSARMBRISEBOIS with user sid S-1-5-18.\r\n[MSARMBRISEBOIS]: LCM: [ Start Set ]\r\n[MSARMBRISEBOIS]: LCM: [ Start Resource ] [[StorageSpace]CreateStorageSpace]\r\n[MSARMBRISEBOIS]: LCM: [ Start Test ] [[StorageSpace]CreateStorageSpace]\r\n[MSARMBRISEBOIS]: LCM: [ End Test ] [[StorageSpace]CreateStorageSpace] in 1.5470 seconds.\r\n[MSARMBRISEBOIS]: LCM: [ Skip Set ] [[StorageSpace]CreateStorageSpace]\r\n[MSARMBRISEBOIS]: LCM: [ End Resource ] [[StorageSpace]CreateStorageSpace]\r\n[MSARMBRISEBOIS]: LCM: [ Start Resource ] [[VirtualDisk]CreateVirtualDisk]\r\n[MSARMBRISEBOIS]: LCM: [ Start Test ] [[VirtualDisk]CreateVirtualDisk]\r\n[MSARMBRISEBOIS]: LCM: [ End Test ] [[VirtualDisk]CreateVirtualDisk] in 0.0780 seconds.\r\n[MSARMBRISEBOIS]: LCM: [ Skip Set ] [[VirtualDisk]CreateVirtualDisk]\r\n[MSARMBRISEBOIS]: LCM: [ End Resource ] [[VirtualDisk]CreateVirtualDisk]\r\n[MSARMBRISEBOIS]: LCM: [ Start Resource ] [[Disk]InitializeDisk]\r\n[MSARMBRISEBOIS]: LCM: [ Start Test ] [[Disk]InitializeDisk]\r\n[MSARMBRISEBOIS]: LCM: [ End Test ] [[Disk]InitializeDisk] in 0.1450 seconds.\r\n[MSARMBRISEBOIS]: LCM: [ Skip Set ] [[Disk]InitializeDisk]\r\n[MSARMBRISEBOIS]: LCM: [ End Resource ] [[Disk]InitializeDisk]\r\n[MSARMBRISEBOIS]: LCM: [ Start Resource ] [[DiskPartition]CreateDiskPartition]\r\n[MSARMBRISEBOIS]: LCM: [ Start Test ] [[DiskPartition]CreateDiskPartition]\r\n[MSARMBRISEBOIS]: LCM: [ End Test ] [[DiskPartition]CreateDiskPartition] in 0.1440 seconds.\r\n[MSARMBRISEBOIS]: LCM: [ Skip Set ] [[DiskPartition]CreateDiskPartition]\r\n[MSARMBRISEBOIS]: LCM: [ End Resource ] [[DiskPartition]CreateDiskPartition]\r\n[MSARMBRISEBOIS]: LCM: [ End Set ] in 2.4610 seconds.\r\nOperation \u0027Invoke CimMethod\u0027 complete.\r\nTime taken for configuration job to complete is 18.63 seconds",
"lang": "en-US"
}
}],
"status": "success",
"code": 1,
"formattedMessage": {
"message": "DSC configuration was applied successfully.",
"lang": "en-US"
}
},
"timestampUTC": "2015-05-20 17:27:50Z",
"version": "1.0"
}]
The substatus contains a capture of the log. This will contain details about the exceptions that occurred which DSC tried to apply the configuration.
Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'. An LCM method call arrived from computer MSARMBRISEBOIS with user sid S-1-5-18. An LCM method call arrived from computer MSARMBRISEBOIS with user sid S-1-5-18. [MSARMBRISEBOIS]: LCM: [ Start Set ] [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[StorageSpace]CreateStorageSpace] [MSARMBRISEBOIS]: LCM: [ Start Test ] [[StorageSpace]CreateStorageSpace] [MSARMBRISEBOIS]: LCM: [ End Test ] [[StorageSpace]CreateStorageSpace] in 1.5470 seconds. [MSARMBRISEBOIS]: LCM: [ Skip Set ] [[StorageSpace]CreateStorageSpace] [MSARMBRISEBOIS]: LCM: [ End Resource ] [[StorageSpace]CreateStorageSpace] [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[VirtualDisk]CreateVirtualDisk] [MSARMBRISEBOIS]: LCM: [ Start Test ] [[VirtualDisk]CreateVirtualDisk] [MSARMBRISEBOIS]: LCM: [ End Test ] [[VirtualDisk]CreateVirtualDisk] in 0.0780 seconds. [MSARMBRISEBOIS]: LCM: [ Skip Set ] [[VirtualDisk]CreateVirtualDisk] [MSARMBRISEBOIS]: LCM: [ End Resource ] [[VirtualDisk]CreateVirtualDisk] [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[Disk]InitializeDisk] [MSARMBRISEBOIS]: LCM: [ Start Test ] [[Disk]InitializeDisk] [MSARMBRISEBOIS]: LCM: [ End Test ] [[Disk]InitializeDisk] in 0.1450 seconds. [MSARMBRISEBOIS]: LCM: [ Skip Set ] [[Disk]InitializeDisk] [MSARMBRISEBOIS]: LCM: [ End Resource ] [[Disk]InitializeDisk] [MSARMBRISEBOIS]: LCM: [ Start Resource ] [[DiskPartition]CreateDiskPartition] [MSARMBRISEBOIS]: LCM: [ Start Test ] [[DiskPartition]CreateDiskPartition] [MSARMBRISEBOIS]: LCM: [ End Test ] [[DiskPartition]CreateDiskPartition] in 0.1440 seconds. [MSARMBRISEBOIS]: LCM: [ Skip Set ] [[DiskPartition]CreateDiskPartition] [MSARMBRISEBOIS]: LCM: [ End Resource ] [[DiskPartition]CreateDiskPartition] [MSARMBRISEBOIS]: LCM: [ End Set ] in 2.4610 seconds. Operation 'Invoke CimMethod' complete. Time taken for configuration job to complete is 18.63 seconds
Location: C:\Program Files\WindowsPowerShell\Modules
This folder contains the uncompressed DSC configuration and Modules that were packaged and uploaded to Azure Storage or any other accessible location.
Debugging, Testing and Refining
Now that we understand the environment that we have to work with, it’s time to dive in.
To start our debug session, we have to look at the status that was generated by DSC. This will give us something to work with. Then based on what we find, we can look at the configuration that was used to execute the DSC. Next based on our findings we can look at the DSC configuration and modules installed on the Virtual Machine.
Once we find out what has gone terribly wrong. We can fix the module in the target Virtual Machine and trigger the Start-DscConfiguration cmdlet. Using the produced output, we can iterate through dev & test cycles until we reach our goal.
When we have something that works, we copy the DSC configuration and module out of the vm. Then we insert it into our Azure Resource Manager Template Solution. From this point on, it’s business as usual. We package the DSC configuration and modules. And finally, we test the entire pipeline by deploying the template to a new Azure Resource Group.
Alexandre Brisebois ☁ 
Very good and helpful post! Thank you.
Today I came across a new problem. After changing having changed DNS settings for the VNet and rebooting the VMs, these are not running DSC consistency checks anymore. Worse: I just updated the DSC configuration and the VM extension is not reacting to the update. Nothing happens… Have you ever seen this? Any idea?
LikeLike
Hi, when This happened to me, I completely removed the dsc, state and packages from the virtual machine. I also reinstalled the extension and it started working on the next try.
LikeLike
Thank you for your reply! Yes, only after reinstalling the extension I solved the problem. Unfortunately, I could not understand why DNS/DC changes had impact on DSC.
LikeLike
FYI, two days ago I was happy thinking I solved the problem after reinstalling DSC… Unfortunately, it didn’t last long. After a reboot, same problem. I reported a bug to the Powershell team here: https://connect.microsoft.com/PowerShell/feedbackdetail/view/1420510/dsc-extension-for-azure-iaas-vm-v-1-10-1-0-stops-executing-consistency-checks-after-a-reboot
LikeLike
Hi – I am testing applying DSC to a VM with a template and New-AzureResourceGroup. If I make a mistake or DSC errors and I try to run a second time it fails with the last status. Do you know is there a way to clean up the last status and run a second time after fixing your DSC ps1? I have also had to delete the dswork directory to get a new same file to run. DSC extension in IaaS v2 is a real bear if it does not run well the first time!
LikeLike
Hi, I’ve had to go through similar steps to get my DSC working. I don’t have anything else to provide in terms of guidance at this time.
LikeLike
@John, to clear an ARM DSC Extension config that is in an error state, use:
Remove-AzureRmVMExtension -ResourceGroupName “rg name” -VMName “vm name” -Name “extension name”
“Extension name” is the name you used in your ARM template.
It took me days of frustration to figure this out – was fortunately able to get help from someone else.
Also, be sure to update forceUpdateTag in the DSC extension properties of your .json ARM template every time you make a change to the DSC config .ps1.
“forceUpdateTag”: “1.00”,
Note also that:
“typeHandlerVersion”: “2.23” is more recent than “typeHandlerVersion”: “2.9” and that properties are now specified differently than in some of the older quickstart templates.
“properties”: {
“publisher”: “Microsoft.Powershell”,
“type”: “DSC”,
“typeHandlerVersion”: “2.23”,
“autoUpgradeMinorVersion”: true,
“forceUpdateTag”: “1.02”,
“settings”: {
“modulesUrl”: “[concat(parameters(‘_artifactsLocation’), ‘/’, variables(‘VMConfigArchiveFolder’), ‘/’, variables(‘VMConfigArchiveFileName’))]”,
“configurationFunction”: “VMConfig.ps1\Main”,
“properties”: [
{
“Name”: “nodeName”,
“Value”: “[variables(‘namingInfix’)]”,
“TypeName”: “System.String”
}
You can also try setting DebugMode, though this didn’t seem to help.
Configuration Main
{
Param ( [string] $nodeName, $webDeployPackagePath )
See the following location on the target VM for the latest install error logs:
C:\WindowsAzure\Logs\Plugins\Microsoft.Powershell.DSC\2.23.0.0
I probably need to start my own blog to compile all of the other dead ends and side streets encountered on the learning curve. I’m still hopeful that DSC will be worth the initial pain. Good luck!
LikeLiked by 1 person
Good guide, Alexandre!
I am trying to Start-DscConfiguration on the VM, but always get the error
“The computer-specific MOF file for computer localhost does not exist in the current directory”
I made sure the localhost.schema.mof is present in the directory specified in -Path.
What could be the reason?
LikeLike