Performance issues with Set-AzVmRunCommand

Question

Hello, I have an Azure Function where I am using AzVmRunCommand to call a .bat file in this way:

Set-AzVMRunCommand -ResourceGroupName $vmRessourseGroup -VMName $vmName -RunCommandName $jobId -Location westeurope -AsJob -NoWait -SourceScript "C:\Test\Test.bat Param1 $($jobId).xml $($requestedLanguage)"

It is working perfect with one of our VMs. But on the other VM it take too long times. On Vm1 it take about 20 seconds until the .bat file is called, which is totally fine. On VM2 it take about between 6 minutes and 30 minutes, sometimes one hour and sometimes it is not working at all. Of course I compared the two VMs, why it is working at one VM but not at the other. The only difference I found was that on the VM1 the extension VMAccessAgent was installed but on the VM2 it was missing. Not sure if this could be the problem? My research did not lead me to this conclution. But what else could be the problem? I hope anyone has ideas. Best regards, Benjamin

Answer 1

Hello, I was running into this problem as well and I think I may have partially solved it by doing additional queries and "cleaning" out the "stuck" commands. Now, I run this "cleaning" cycle before I run new commands. ;-) It worked for me, so I thought I would post it here. Also, please note my question at the bottom.

First, see which VMs are currently in an "Updating" Provisioning state by running Get-AzVM. An Updating state indicates that the VM is still running (or stuck running) one or more commands which is what the problem was for me.

Get-AzVM -ResourceGroupName 'ResourceGroup' -Status | Where-Object { $_.PowerState -eq "VM Running" }

Next, optionally run Get-AzVMRunCommand against the target VM(s) that are in an Updating Provisioning state to see which commands are running/stuck:

Get-AzVMRunCommand -ResourceGroupName 'SampleResourceGroup' -VMName 'SampleVM'

Next, remove/clean all of the running/stuck commands by running Remove-AzVMRunCommand - optionally use nowait and then use Get-AzVM to see if/when the Provisioning status updates to Succeeded. This can take several minutes to run, so I recommend using the nowait parameter.

Get-AzVMRunCommand -ResourceGroupName 'SampleResourceGroup' -VMName 'SampleVM' 
| ForEach-Object {Remove-AzVMRunCommand -VMName 'SampleVM' -ResourceGroupName 'SampleResourceGroup' -RunCommandName $_.Name -nowait}

Once Get-AzVM shows the VMs in a Succeeded Provisioning state, the VMs are now open for new commands. Now/Finally, try running/re-running your Get-AzVMRunCommand against the VM(s) and this time, it "should" work consistently. It certainly made my commands work more reliably.

Question: After I know that my script has completed successfully (my script provides me updates on its progress) it still takes several minutes for the Provisioning state to go from Updating (it thinks it is still running the command) to Succeeded, therefore I'm looking for advice that might help make it faster. Any help is appreciated. Thank you!

Answer 2

@Benjamin Apologies for the delayed response. Sorry to hear you are facing issues using Run Command through Azure Functions on one of your VMs. It sounds like you have already done some comparison and analysis.

I don't think VMAccess extension would be the issue here. However, it is something that you can easily install and check to see if any changes occur. You can deploy VMAccess Extension by running:

Set-AzureVMExtension -ExtensionName $ExtensionName -VM $vm `
  -Publisher $Publisher -Version $Version `
  -PrivateConfiguration $PrivateConf -PublicConfiguration $PublicConf |
  Update-AzureVM

If installing the VMAccess extension doesn't work you can check the logs on the VM2 to see if there are any errors or warnings related to the AzVmRunCommand or the bat file. The handler log file is typically located in the following directory:

You can also try running the .bat file manually on VM2 to see if it executes without any issues. This can help you determine if the issue is with the .bat file or with the AzVmRunCommand.

Hope this helps. Let me know if you still have issues and we will be happy to help you.

---

Please don’t forget to "Accept the answer" and “up-vote” wherever the information provided helps you, this can be beneficial to other community members.

Answer 3

Hello, thank you for your response. I also assume the VM Extension does not have any impact on this issue. I tried to find anything suspicious in the logs, but cannot find some suspicous. I suppose, on my Windows VM the logs are in "C:\WindowsAzure\Logs\Plugins\Microsoft.CPlat.Core.RunCommandHandlerWindows\2.05" and in"C:\WindowsAzure\Logs\Plugins\Microsoft.CPlat.Core.RunCommandWindows\1.1.11". In both directorys I found some log files for the specific jobs and summary log files. But I did not find any error in this logs. But one thing I found was in RunCommandHandler.log, there are WARN logs, please see following snippet (line 4):

[68108+00000001] [04/11/2023 08:48:49.56] [INFO] Using environment variable [ConfigExtensionName]=xxx [68108+00000001] [04/11/2023 08:48:49.56] [INFO] Using environment variable [ConfigSequenceNumber]=0 [68108+00000001] [04/11/2023 08:48:49.56] [INFO] Process handler command: enable [68108+00000001] [04/11/2023 08:48:49.56] [WARN] Current sequence number, 0, is not greater than the sequence number of the most recently executed configuration. Exiting... [79168+00000001] [04/11/2023 08:49:08.54] [INFO] Temporary directory for event files was successfully created: C:\WindowsAzure\Logs\Plugins\Microsoft.CPlat.Core.RunCommandHandlerWindows\Events\Temp [79168+00000001] [04/11/2023 08:49:08.55] [INFO] Space available in event directory: 39981250B [79168+00000001] [04/11/2023 08:49:08.55] [INFO] Setting event reporting interval to 10000ms [79168+00000001] [04/11/2023 08:49:08.55] [INFO] Event polling is starting... [79168+00000001] [04/11/2023 08:49:08.56] [INFO] An ExtensionEventLogger was created [79168+00000001] [04/11/2023 08:49:08.56] [INFO] Starting RunCommand Extension version 1 [79168+00000001] [04/11/2023 08:49:08.56] [INFO] HandlerEnvironment = Version: 1, HandlerEnvironment: [LogFolder: "C:\WindowsAzure\Logs\Plugins\Microsoft.CPlat.Core.RunCommandHandlerWindows\2.0.5", ConfigFolder: "C:\Packages\Plugins\Microsoft.CPlat.Core.RunCommandHandlerWindows\2.0.5\RuntimeSettings", StatusFolder: "C:\Packages\Plugins\Microsoft.CPlat.Core.RunCommandHandlerWindows\2.0.5\Status", EventsFolder: "C:\WindowsAzure\Logs\Plugins\Microsoft.CPlat.Core.RunCommandHandlerWindows\Events", HeartbeatFile: "C:\Packages\Plugins\Microsoft.CPlat.Core.RunCommandHandlerWindows\2.0.5\Status\HeartBeat.Json"] [79168+00000001] [04/11/2023 08:49:08.56] [INFO] Using environment variable [ConfigExtensionName]=yyy

Perhaps it could has to do with this warning messages? Best regards Benjamin

Answer 4

I am facing similar issue. I am running Poweshell scripts on Azure VM to do SFTP and actually I can see the SFTP scripts running and doing their task on VM but the issue is the Set-AzVmRunCommand does not return anything and also the Get-AzVMRunCommand -ResourceGroupName SFTP -VMName CMSAZSFTP01 -RunCommandName says the command is in pending state. this behaviour is happening recently . I was able to execute run commands smothly previously. I have tried to reboot the VM but that has not helped.

Answer 5

Question: What is the purpose of the Target URL returned from Set-AzVMRunCommand? When I browse to the URL, it always returns, "Authentication failed. The 'Authorization' header is missing." Is this supposed to be a way to view the status of the command or is the URL missing some kind of authentication before I can get the status?