bugzapper

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.

8 responses to Debugging Desired State Configuration (DSC) on #Azure VMs

  1. 
    Hélder Pinto June 9, 2015 at 7:39 AM

    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?

    Like

  2. 

    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!

    Like

  3. 

    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?

    Like

Trackbacks and Pingbacks:

  1. Build it, Use it, Destroy it! « Alexandre Brisebois ☁ - October 17, 2015

    […] Resource Manager to provision a new Windows Virtual Machine and use Desired State Configuration (DSC) for the final […]

    Like

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s