Verbose output is longer than it should be

[briantist]

If you call Invoke-DscResource directly with -Verbose, you get output similar to what you would see if you ran the resource in the LCM:

VERBOSE: Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = ResourceTest,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/Desi
redStateConfiguration'.
VERBOSE: An LCM method call arrived from computer STANCHION with user sid S-1-5-21-90865308-1833148694-2130556682-1001.
VERBOSE: [COMP]: LCM:  [ Start  Test     ]  [[File]DirectResourceAccess]
VERBOSE: [COMP]:                            [[File]DirectResourceAccess] The destination object was found and no action is required.
VERBOSE: [COMP]: LCM:  [ End    Test     ]  [[File]DirectResourceAccess] True in 0.0120 seconds.
VERBOSE: [COMP]: LCM:  [ End    Set      ]    in  0.0260 seconds.
VERBOSE: Operation 'Invoke CimMethod' complete.

InDesiredState 
-------------- 
True           
VERBOSE: Time taken for configuration job to complete is 0.199 seconds

However, when running an Idempotion-generated function, the -Verbose output adds these additional lines at the top:

VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\PSDesiredStateConfiguration.psm1'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Get-DSCConfiguration.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Get-DSCLocalConfigurationManager.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Restore-DSCConfiguration.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Get-DscConfigurationStatus.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Stop-DscConfiguration.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Remove-DscConfigurationDocument.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Disable-DscDebug.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\Enable-DscDebug.cdxml'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\DSCClassResources\WindowsPackageCab\WindowsPackageCab.psd1'.
VERBOSE: Loading module from path 'C:\WINDOWS\system32\WindowsPowerShell\v1.0\Modules\PSDesiredStateConfiguration\DSCClassResources\WindowsPackageCab\WindowsPackageCab.psm1'.

This really makes what would otherwise be very useful output into kind of a mess, especially on an Update where both Test and Set will be run (independently), so that will end up in the output twice.

Why?

I think this is a difference between -Verbose being specified and it being inherited (via $VerbosePreference). Since I am wrapping Invoke-DscResource inside an advanced function, specifying -Verbose on the outer function sets the preference variable.

I think what happens is that code inside Invoke-DscResource reads the preference from a higher scope and displays that extra output, whereas it wouldn't do that if the preference wasn't set before setting -Verbose on the Invoke-DscResource call.

Confirmation of Above

I have confirmed that the preference inheritance is to blame here. This can be demonstrated with the following code:

$demoFile = 'C:\my\path\file.txt'

$VerbosePreference = 'SilentlyContonue'  # default

# Shorter verbose output
Invoke-DscResource -Name File -Method Test -ModuleName PSDesiredStateConfiguration -Property @{ DestinationPath = $demoFile ; Contents = "Hello" } -Verbose

$VerbosePreference = 'Continue'

# Longer verbose output
Invoke-DscResource -Name File -Method Test -ModuleName PSDesiredStateConfiguration -Property @{ DestinationPath = $demoFile ; Contents = "Hello" } -Verbose

Solution

I think I can fix this in the definitions with an ugly looking hack:

$oldVerbosePreference = $VerbosePreference
$VerbosePreference = [System.Management.Automation.ActionPreference]::SilentlyContinue

Invoke-DscResource -Name 'File' -ModuleName 'PSDesiredStateConfiguration' -Method 'Test' -Property $params -Verbose:$oldVerbosePreference

$VerbosePreference = $oldVerbosePreference

[briantist]

Fixed in #16