MSFT_Archive: Failed to execute Set-TargetResource

[ChrisFg]

An azure arm vm is being provisioned, which failed, using a dsc resource, Unzip-coronaBenchmarkDsc.ps1.zip, located on an azure storage account. The vm dsc extension config is initiated from a powershell runbook. To reproduce the issue the specific runbook code was isolated and invoked from an automation engineer’s workstation via the ISE and azure sdk. The zip extract did succeed, but the portal, and powershell on the workstation, reported an error.

Azure portal > Virtual Machine > Extensions > Microsoft.Poweshell.DSC
Status Provisioning failed.
Portal error message extract
…
[2017-08-28 06:23:46Z] [VERBOSE] [cjfle1vm]: LCM: [ End Set ] [[Archive]CoronBenchmarkUnzip] in 12.8170 seconds.\r\n[2017-08-28 06:23:46Z] [ERROR] PowerShell DSC resource MSFT_Archive failed to execute Set-TargetResource functionality with error message: Exception setting "LastWriteTime": "The process cannot access the file 'C:\Temp\Corona1.3.Benchmark.exe' because it is being used by another process." \r\n[2017-08-28 06:23:46Z] [VERBOSE] [cjfle1vm]: LCM: [ End Set ]\r\n[2017-08-28 06:23:47Z] [ERROR] The SendConfigurationApply function did not succeed.\r\n[2017-08-28 06:23:47Z] [VERBOSE] Operation 'Invoke CimMethod' complete.\r\n[2017-08-28 06:23:47Z] [VERBOSE] Time taken for configuration job to complete is 19.166 seconds"

DSC resource: Unzip-coronaBenchmarkDsc.ps1.zip
Runs on arm vm: cjfle1vm
ARM AzureRM modules version: either 3.3.1 or 4.3.1.

DSC resource filename: Unzip-coronaBenchmarkDsc.ps1.zip
DSC resource content:
Configuration Unzip-coronaBenchmarkDsc {
Import-DscResource -ModuleName 'PSDscResources'
Node localhost {
Archive CoronBenchmarkUnzip {
Ensure = "Present"
Path = "C:\Temp\Corona1.3.Benchmark.zip"
Destination = "C:\Temp"
Force = $true
}
}
}
Located at: https://xxx.blob.core.windows.net/yyy/Unzip-coronaBenchmarkDsc.ps1.zip

Published from workstation to azure storage account by:
Publish-AzureRmVMDscConfiguration -ConfigurationPath '.\StorageBackendVmExtentsions\Unzip-coronaBenchmarkDsc.ps1'
-ResourceGroupName $resourcegroupName -StorageAccountName $storageAccountName `
-ContainerName $blobContainerName –Force

Published from:
Automation engineer’s workstation
Workstation ISE v5.1.15063.502
AzureRM 4.3.1
PSDscResources Manifest 2.8.0.0

Install of DSC vm extension is invoked from automation engineer’s workstation by:
Set-AzureRmVMDscExtension -ResourceGroupName 'zzz' -VMName 'cjfle1vm' -Name 'Unzip-coronaBenchmarkDsc'
-ArchiveResourceGroupName 'TRigsSa' -ArchiveStorageAccountName 'xxx'
-ArchiveContainerName 'yyy' -ArchiveBlobName 'Unzip-coronaBenchmarkDsc.ps1.zip'
-ConfigurationName 'Unzip-coronaBenchmarkDsc' -Version "2.26"
-WmfVersion 5.1

Let me know if you need more or different.

[PlagueHO]

Hi @ChrisFg - Does the file C:\Temp\Corona1.3.Benchmark.exe get started after it is extracted?

I'm wondering if the DSC Config is being applied twice (which is usually quite acceptable). The first time the file C:\Temp\Corona1.3.Benchmark.exe is extracted correctly. The second time the DSC is applied the file C:\Temp\Corona1.3.Benchmark.exe is executing so can't be overwritten.

A way to resolve this might be to set the -Validate parameter to $True and -Force to $False. This will prevent the Archive resource from trying to overwrite the C:\Temp\Corona1.3.Benchmark.exe file if it already exists and the modify date/time matches.

E.g.

Configuration Unzip-coronaBenchmarkDsc {
Import-DscResource -ModuleName 'PSDscResources'
Node localhost {
Archive CoronBenchmarkUnzip {
Ensure = "Present"
Path = "C:\Temp\Corona1.3.Benchmark.zip"
Destination = "C:\Temp"
Validate = $true
Force = $false
}
}
}

Hope this helps!

[ChrisFg]

Hi @PlagueHO -- Thanks for your suggestion. No, the C:\Temp\Corona1.3.Benchmark.exe is not started after it is extracted. The Set-AzureRmVMDscExtension cmdlet is the last in the run book. I tried the configuration arguments you suggested: the extract occurs, as it did previously, but dsc extension still fails. The portal shows the same error: [ERROR] PowerShell DSC resource MSFT_Archive failed to execute Set-TargetResource functionality with error message: Exception setting "LastWriteTime": "The process cannot access the file 'C:\Temp\Corona1.3.Benchmark.exe' because it is being used by another process
Regards, C.

[PlagueHO]

Hi @ChrisFg - It definitely looks like something is going on here. I did some digging into the code and it looks like the problem could be occurring when the LastWriteTime property of the file is being set. Specifically this line here:
https://github.com/PowerShell/PSDscResources/blob/dev/DscResources/MSFT_Archive/MSFT_Archive.psm1#L1323

I'm not sure what might be preventing this. I did a few tests on some local VMs here and I could successfully set the LastWriteTime of a file using the same process the Archive resource uses. But I can't see why it would report that the file is being used by another process.

[ChrisFg]

Hi @PlagueHO, thanks for the attention. My test uses an azure arm vm; the Set-AzureRmVMDscExtension cmdlet is run from the ISE on my local workstation via SDK (login-azurerm) to my azure arm subscription. The 'Unzip-coronaBenchmarkDsc.ps1.zip' argument for the cmdlet's ArchiveBlobName parameter is pulled onto the vm being configured, from my storage account. And presumably arm issues an 'invoke-cimMethod' call to cjfle1vm vm to invoke 'Unzip-coronaBenchmarkDsc.ps1 which includes the unzip.

When running Set-AzureRmVMDscExtension cmdlet twice in sequence the first instance usually (I comment below) fails with:
"[2017-08-28 03:05:32Z] [VERBOSE] Perform operation 'Invoke CimMethod' with following parameters, ''methodName' = SendConfigurationApply,'className' = MSFT_DSCLocalConfigurationManager,'namespaceName' = root/Microsoft/Windows/DesiredStateConfiguration'.\r\n[2017-08-28 03:05:33Z] [VERBOSE] An LCM method call arrived from computer cjfle1vm with user sid S-1-5-18.\r\n[2017-08-28 03:05:33Z] [VERBOSE] [cjfle1vm]: LCM: [ Start Set ]\r\n[2017-08-28 03:05:36Z] [VERBOSE] [cjfle1vm]: LCM: [ Start Resource ] [[Archive]CoronBenchmarkUnzip]\r\n[2017-08-28 03:05:37Z] [VERBOSE] [cjfle1vm]: LCM: [ Start Test ] [[Archive]CoronBenchmarkUnzip]\r\n[2017-08-28 03:05:37Z] [VERBOSE] [cjfle1vm]: [[Archive]CoronBenchmarkUnzip] The destination file C:\Temp\Corona1.3.Benchmark.exe was missing or was not a file\r\n[2017-08-28 03:05:37Z] [VERBOSE] [cjfle1vm]: LCM: [ End Test ] [[Archive]CoronBenchmarkUnzip] in 0.5780 seconds.\r\n[2017-08-28 03:05:37Z] [VERBOSE] [cjfle1vm]: LCM: [ Start Set ] [[Archive]CoronBenchmarkUnzip]\r\n[2017-08-28 03:05:37Z] [VERBOSE] [cjfle1vm]: [[Archive]CoronBenchmarkUnzip] The configuration of MSFT_ArchiveResource is starting\r\n[2017-08-28 03:05:37Z] [VERBOSE] [cjfle1vm]: [[Archive]CoronBenchmarkUnzip] Unzip archived file to C:\Temp\Corona1.3.Benchmark.exe\r\n[2017-08-28 03:05:39Z] [VERBOSE] [cjfle1vm]: LCM: [ End Set ] [[Archive]CoronBenchmarkUnzip] in 4.5790 seconds.\r\n[2017-08-28 03:05:39Z] [ERROR] PowerShell DSC resource MSFT_ArchiveResource failed to execute Set-TargetResource functionality with error message: Exception setting "CreationTime": "The process cannot access the file 'C:\Temp\Corona1.3.Benchmark.exe' because it is being used by another process." \r\n[2017-08-28 03:05:39Z] [VERBOSE] [cjfle1vm]: LCM: [ End Set ]\r\n[2017-08-28 03:05:39Z] [ERROR] The SendConfigurationApply function did not succeed.\r\n[2017-08-28 03:05:39Z] [VERBOSE] Operation 'Invoke CimMethod' complete.\r\n[2017-08-28 03:05:39Z] [VERBOSE] Time taken for configuration job to complete is 6.617 seconds"

The second instance, invoked immediately, succeeds, because of the 'skip set' test:
"[2017-08-27 13:01:24Z] [VERBOSE] Perform operation \u0027Invoke CimMethod\u0027 with following parameters, \u0027\u0027methodName\u0027 = SendConfigurationApply,\u0027className\u0027 = MSFT_DSCLocalConfigurationManager,\u0027namespaceName\u0027 = root/Microsoft/Windows/DesiredStateConfiguration\u0027.\r\n[2017-08-27 13:01:24Z] [VERBOSE] An LCM method call arrived from computer cjfle1vm with user sid S-1-5-18.\r\n[2017-08-27 13:01:24Z] [VERBOSE] [cjfle1vm]: LCM: [ Start Set ]\r\n[2017-08-27 13:01:26Z] [VERBOSE] [cjfle1vm]: LCM: [ Start Resource ] [[Archive]CoronBenchmarkUnzip]\r\n[2017-08-27 13:01:26Z] [VERBOSE] [cjfle1vm]: LCM: [ Start Test ] [[Archive]CoronBenchmarkUnzip]\r\n[2017-08-27 13:01:26Z] [VERBOSE] [cjfle1vm]: LCM: [ End Test ] [[Archive]CoronBenchmarkUnzip] in 0.5780 seconds.\r\n[2017-08-27 13:01:27Z] [VERBOSE] [cjfle1vm]: LCM: [ Skip Set ] [[Archive]CoronBenchmarkUnzip]\r\n[2017-08-27 13:01:27Z] [VERBOSE] [cjfle1vm]: LCM: [ End Resource ] [[Archive]CoronBenchmarkUnzip]\r\n[2017-08-27 13:01:27Z] [VERBOSE] [cjfle1vm]: LCM: [ End Set ]\r\n[2017-08-27 13:01:27Z] [VERBOSE] [cjfle1vm]: LCM: [ End Set ] in 2.3780 seconds.\r\n[2017-08-27 13:01:27Z] [VERBOSE] Operation \u0027Invoke CimMethod\u0027 complete.\r\n[2017-08-27 13:01:27Z] [VERBOSE] Time taken for configuration job to complete is 2.95 seconds",
"lang": "en-US"
}
The above, a sequence of two calls,, is my work around, which results in a 'provisioning succeeded' message in the portal and in my workstation ISE.

Now, talking about more than I know: the error feels like a timing (thread/async?) issue. With my test setup I can reliably reproduce the failure and the workaround. However I have had one case, out of hours :-( when the first instance succeeded. So It feels like timing within the invoke-cimMethod to cjfle1vm vm and the unzip activity on cjfle1vm. vm.
But I have no idea what goes on in invoke-cimMethod. I stopped my rabbit hole dive at Set-AzureRmVMDscExtension, Archive.
Regards, Chris

[PlagueHO]

@kwirkykat or anyone else, do you have any ideas on what might be going on here? It definitely feels like a timing issue that is preventing the setting of the "LastWriteTime" because the file has clearly been extracted correctly.

@ChrisFg - do you know if there is a virus scanner or something like that running on this machine? It is not impossible that something like that is momentarily locking the file while it is scanned. Or I wonder if because this file is being downloaded from a "public" network it is being marked as "blocked" and needs to be unblocked. But I'm really grasping at straws there.

[kwirkykat]

I tried out running the Archive resource on a folder including a .exe with the Force parameter set to true multiple times in a row on my test machine, and that worked without any errors.

This specific error comes up if anything else on the machine has an open write handle to the file. The most likely culprits are usually Windows Defender/other antimalware or Windows Explorer (if you have a GUI open on the machine which I doubt). Invoke-CimMethod is called inside the DSC engine to invoke the configuration, so that isn't causing a timing problem.

I don't think there's anything I can do from the resource or DSC side to help you out. Sorry 😕

[ChrisFg]

@PlagueHO thanks for the straws, more floated past u than me, and @kwirkykat for the confirmation of no timing problem. The antimalware straw looks promising.

This phase of the automation script installs, in sequence:

1. BGInfo vm extension;
2. Antimalware extension, using Set-AzureRmVMExtension -settings ;
3. Update W2012R2 to wmf 5.1, using dsc extension with xHotFix;
4. Download benchmark .zip, approx. 200MB, using custom script vm extension with Invoke-webRequest;
5. Unzip benchmark .zip, using dsc extension with Archive;
6. Invoke benchmark .exe, using custom script vm extension, after removal of prior, with start-process;

I'll reconfigure the automation to remove antimalware and update the result here for completeness.
Thanks to both of u for ur time and thoughts.
Regards, Chris

[PlagueHO]

Thanks for the update @ChrisFg - hopefully it is a timing issue with the Antimalware extension that can be easily resolved... or at least worked around. Keen to know your findings on this one.

[ChrisFg]

Hi @PlagueHO , @kwirkykat, The cause of the ‘Archive’ dsc vm extension provision failure and the corresponding message -- "The process cannot access the file 'C:\Temp\Corona1.3.Benchmark.exe' because it is being used by another process." -- is the presence of the antimalware software, installed prior to the ‘Archive’ dsc vm extension.

Removing the antimalware extension and then invoking the archive dsc vm extension enables the archive dsc extension provision to succeed. My vm configuration sequence now installs the antimalware dsc vm extension after the unzip.

Interestingly; I also ran a custom script vm extension that uses the wmf5.1 Expand-Archive cmdlet to perform the unzip activity. When antimalware is installed and then the custom script vm extension is invoked the extension provision succeeds but portal ‘detailed status shows:
[
{
"code": "ComponentStatus/StdOut/succeeded",
"level": "Info",
"displayStatus": "Provisioning succeeded",
"message": "True\ntpt-install-CoronaBenchMark: Corona benchmark downloaded, .zip exists."
},
{
"code": "ComponentStatus/StdErr/succeeded",
"level": "Info",
"displayStatus": "Provisioning succeeded",
"message": "Exception calling "ExtractToFile" with "3" argument(s): **"The process cannot \naccess the file 'C:\Temp\Corona1.3.Benchmark.exe' because it is being used by \nanother process.**"\nAt C:\Windows\system32\WindowsPowerShell\v1.0\Modules\Microsoft.PowerShell.Arch\nive\Microsoft.PowerShell.Archive.psm1:1033 char:25\n+ ... [System.IO.Compression.ZipFileExtensions]::ExtractToFile( ...\n+ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n + CategoryInfo : NotSpecified: (:) [], MethodInvocationException\n + FullyQualifiedErrorId : IOException\n "
}
]

Without antimalware installed the custom script vm extension detailed message shows:
[
{
"code": "ComponentStatus/StdOut/succeeded",
"level": "Info",
"displayStatus": "Provisioning succeeded",
"message": "True\ntpt-install-CoronaBenchMark: Corona benchmark downloaded, .zip exists."
},
{
"code": "ComponentStatus/StdErr/succeeded",
"level": "Info",
"displayStatus": "Provisioning succeeded",
"message": ""
}
]

Thanks for your above assistance, appreciated.
Regards, Chris

[johlju]

A solution seem to have been found on this issue, so I suggest we close this issue.

[johlju]

Closing this as solved as per previous comments. Please reopen or comment if this was closed in error.