Thursday, March 20, 2014

Adventures in DSC

I'm experimenting with creating a deployment package with Desired State Configuration.  Huge thanks to Jacob Benson for his wonderful DSC journal, which has helped me enormously to work through problems caused by Microsoft's sparse DSC documentation.  I read the Day 11 post and was able to then proceed as described below to attempt to use a script to install a few utilities.

I have a configuration script that, first, recursively copies a File (directory type) Resource to a folder.  The script follows:

#Requires -version 4.0

Configuration NG_BackendDSC
{
param (
[String[]]$ComputerName = $env:COMPUTERNAME
,
$ReleaseSourcepath = "d:\download\ng"
,
$NGTargetPath = 'd:\ng_backend'

)

Node $ComputerName
{
File BackendInstallationFiles
{
Ensure = "Present"

SourcePath = (Join-Path $ReleaseSourcepath '7.0\ng_backend')

DestinationPath = $NGTargetPath

Type = "Directory"

Recurse = $true

}

Log AfterDirectoryCopy
        {
            # The message below gets written to the Microsoft-Windows-Desired State Configuration/Analytic log
            Message = "Finished running the file resource with ID BackendInstallationFiles"
            DependsOn = "[File]BackendInstallationFiles" # This means run "BackendInstallationFiles" first.
        }
# ... [package resources follow here as described below]
} # End configuration block

The Configuration script then continues with a Package Resource to install 7Zip and another for Winmerge:

Package 7Zip
{
DependsOn = '[File]BackendInstallationFiles'

Ensure = "Present"

Path = (Join-Path $ReleaseSourcepath 'Utilities\7z457-x64.msi')

Name = '7-Zip'

ProductID = '23170F69-40C1-2702-0457-000001000000'

LogPath = (Join-Path $ReleaseSourcepath '7zip_dsc.log')
}

Package WinMerge
{
DependsOn = '[File]BackendInstallationFiles'

Ensure = 'Present'

Path =  (Join-Path $ReleaseSourcepath 'Utilities\WinMerge-2.14.0-Setup.exe')

Name = 'WinMerge'

ProductID = ''

LogPath = (Join-Path $ReleaseSourcepath 'winmerge_dsc.log')
}

There are three more packages:

Package NotePadPlus
{
DependsOn = '[File]BackendInstallationFiles'

Ensure = 'Present'

Path =  (Join-Path $ReleaseSourcepath 'Utilities\npp.6.5.5.Installer.exe')

Name = 'Notepad++'

ProductID = ''

LogPath = (Join-Path $ReleaseSourcepath 'notepadplus_dsc.log')
}

Package FileZilla
{
DependsOn = '[File]BackendInstallationFiles'

Ensure = 'Present'

Path =  (Join-Path $ReleaseSourcepath 'Utilities\FileZilla_3.7.4.1_win32-setup.exe')

Name = 'FileZilla FTP Client'

ProductID = ''

LogPath = (Join-Path $ReleaseSourcepath 'FileZilla_dsc.log')
}

Package AgentRansack
{
DependsOn = '[File]BackendInstallationFiles'

Ensure = 'Present'

Path =  (Join-Path $ReleaseSourcepath 'Utilities\AgentRansack_820.exe')

Name = 'Agent Ransack'

ProductID = ''

LogPath = (Join-Path $ReleaseSourcepath 'Agent_Ransack_dsc.log')
}

At the end of the script, after the closing Configuration bracket, I create the MOF files and start off the implementation of the configuration:

    ng_backendDSC -OutputPath d:\dsc\MOF
    Start-DscConfiguration -Wait -Path d:\dsc\MOF -Verbose

I executed the script within the ISE.

The directory copy happened fine.  7zip was already installed, so DSC noticed this and skipped it.

Winmerge then began to install.  I waited a half-hour, but the script did not finish.  In fact Winmerge did install, which I could see from the Start Menu, but the log file 'winmerge_dsc.log' was only just created and has zero bytes.

Here's all I got from the verbose comments:
VERBOSE:  [[Package]WinMerge] The package WinMerge is not installed
VERBOSE: [[Package]WinMerge] Package configuration starting

I clicked the Stop button in the ISE.  The status bar says "Stopping" but not "Stopped."
I closed the ISE and checked the Event log (Diagnostics/Applications and Services Logs/Microsoft/Windows/Desired State Configuration.  There's an entry for the starting of the script and one for the ending of the script.  Both logs have the same message:
Job {66685F9E-D242-4A6C-9CA5-DD47AED6B62B} : 
Configuration is sent from computer NULL by user sid S-1-5-21-2621261384-2063666624-962377667-1000.

Great.  Nothing helpful there.  There was no debug log even though analytic and debug logging are enabled as described here.

I've seen scripts hang the ISE before, so I tried running the script from the PowerShell console.  As I had dreaded, I saw this output:

VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' =
SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' =
root/Microsoft/Windows/DesiredStateConfiguration'.
Cannot invoke the SendConfigurationApply method. The SendConfigurationApply method is in progress and must return before SendConfigurationApply can be invoked.
    + CategoryInfo          : NotSpecified: (root/Microsoft/...gurationManager:String) [], CimException
    + FullyQualifiedErrorId : MI RESULT 1
    + PSComputerName        : QAIDD7

VERBOSE: Operation 'Invoke CimMethod' complete.
VERBOSE: Time taken for configuration job to complete is 0.557 seconds

I had dreaded this because I have seen this before.  Jason's blog is so far the sole page on the Internet that I have found that even mentions this error.  When he saw it, it went away by itself.  When I saw it, I waited several days and rebooted the server and still see the message, preventing me from doing any other DSC script runs.

Before running this script, I had created a snapshot of the virtual machine, so I can recover, but I tried rebooting the server.  It's a Windows 2008 R2 machine by the way, with PowerShell 4.0 installed, which is the minimum version that supports DSC.  I understand that DSC is not PowerShell.  That only makes it more difficult to figure out ways to troubleshoot the underlying technology, when there is no helpful output into logs.

After the reboot, the "SendConfigurationApply method is in progress and must return before SendConfigurationApply can be invoked" error still came up, strangely.  The output recommends using -Force in this case, so I changed the command to delete the -Wait and add -Force:

Start-DscConfiguration -Wait -Path d:\dsc\MOF -Verbose

Cool.  The script seems to run this time:
HasMoreData     : True
StatusMessage   : Running
Location        :  Server1
StartParameters : {}
Command         : Start-DscConfiguration -Force -Path d:\dsc\MOF -Verbose
JobStateInfo    : Running
Finished        : System.Threading.ManualResetEvent
InstanceId      : 9282f535-6026-49eb-932b-c4cd58e3f815
Id              : 4
Name            : Job4
ChildJobs       : {Job5}
PSBeginTime     : 3/20/2014 2:33:16 PM
PSEndTime       :
PSJobTypeName   : ConfigurationJob
Output          : {}
Error           : {}
Progress        : {}
Verbose         : {}
Debug           : {}
Warning         : {}
State           : Running

VERBOSE: Time taken for configuration job to complete is 0.077 seconds

So what's a scripter to do?  Microsoft recommends using the -Wait, but the script won't run unless I use -Force instead.

I am still not seeing anything in the winmerge log file.  I ran a Get-Job | FormatList and see the job is still in the Running state:

HasMoreData     : True
StatusMessage   : Running
Location        : Server1
StartParameters : {}
Command         : Start-DscConfiguration -Force -Path d:\dsc\MOF -Verbose
JobStateInfo    : Running
Finished        : System.Threading.ManualResetEvent
InstanceId      : 9282f535-6026-49eb-932b-c4cd58e3f815
Id              : 4
Name            : Job4
ChildJobs       : {Job5}
PSBeginTime     : 3/20/2014 2:33:16 PM
PSEndTime       :
PSJobTypeName   : ConfigurationJob
Output          : {}
Error           : {}
Progress        : {}
Verbose         : {}
Debug           : {}
Warning         : {}
State           : Running

I then ran receive-job -id 4 -Keep.  No output at all.

Get-Job did show a ChildJobs property, so I tried Get-Member on it but didn't receive anything I can use.

PS D:\> get-job | select childjobs | gm

   TypeName: Selected.System.Management.Automation.ContainerParentJob

Name        MemberType   Definition
----        ----------   ----------
Equals      Method       bool Equals(System.Object obj)
GetHashCode Method       int GetHashCode()
GetType     Method       type GetType()
ToString    Method       string ToString()
ChildJobs   NoteProperty System.Collections.Generic.List`1[[System.Management.Automation.Job, System.Management.Auto...

get-command *config* turned up a Get-DSCConfiguration cmdlet.  Sounds promising.  I was stopped by the same error as before:

get-dscconfiguration : Cannot invoke the GetConfiguration method. The SendConfigurationApply method is in progress and must return before GetConfiguration can be invoked.
At line:1 char:1
+ get-dscconfiguration
+ ~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (MSFT_DSCLocalConfigurationManager:root/Microsoft/...gurationManager) [Get
   -DscConfiguration], CimException
    + FullyQualifiedErrorId : MI RESULT 1,Get-DscConfiguration

I will revert the VM, but I don't know how to proceed from here.  Is Winmerge not compatible with DSC?  How can I get more information?

1 comment:

jv said...

I would start by saying that you should never let a guitarist near a computer but, since you are a classical guitarist. I will make an exception.

Start by isolation the code that causes the first error and try to run it outside of a DSC script. Look closely at the requirements. Check all system logs and install logs. YOU will have to figure this out without much outside help. it is a detective story.

I know - classical guitarists are not good detectives - my buddy complains like that all the time. A 'G'and his(its) guitar.

Seriously...start with the first issue and ignore everything else.