“If this step is executed X times” not unique to step

[mkreitzer]

In the queue I’m currently working on I use this statement in two places. The issue I’m encountering is that the counter doesn’t appear unique to the step. See for example:

08/24 20:43:05> Job Queue: Execution jumping to Label:Remanage. This step has been executed: 3 times.
08/24 20:43:05> Job Queue: Initiating ‘If this step is executed 3 times, goto label:Remanage’ – This is step 35
08/24 20:43:05> Job Queue: Execution continuing. Previous ‘Check for available updates’ found 1 update(s)
08/24 20:43:05> Job Queue: Initiating ‘If most recent ‘Check for available updates’ found 0 updates, goto label:AllUpdatesComplete’
08/24 20:43:04> Windows Update: 1 update(s) found
08/24 20:42:59> Windows Update: Executing BatchPatchRemoteAgent.exe…
08/24 20:42:58> Windows Update: Attempting to initiate Windows Update (Action: Search for updates: ‘ImportantAndRecommended’ | Server selection: Default / Managed) …
08/24 20:42:58> Windows Update: Establishing connection…
08/24 20:42:57> Windows Update: Initializing…
08/24 20:42:57> Job Queue: Initiating ‘Check for available updates’
08/24 20:41:57> Waiting 1 minute…
08/24 20:41:57> Job Queue: Initiating ‘Wait 1 minute’
08/24 20:41:56> Remote Command: Exit Code: 0 (SUCCESS)
08/24 20:41:43> Remote Command: Executing …
08/24 20:41:42> Remote Command: Establishing connection…
08/24 20:41:42> Job Queue: Initiating ‘Remote command …’
08/24 20:40:42> Waiting 1 minute…
08/24 20:40:42> Job Queue: Initiating ‘Wait 1 minute’
08/24 20:40:41> Job Queue: Label:CBSComplete
08/24 20:40:41> Job Queue: Execution jumping to Label:CBSComplete. Previous action exit code: 0
08/24 20:40:41> Job Queue: Initiating ‘If previous action was successful (returned 0), goto label:CBSComplete’
08/24 20:40:40> Remote Command: Exit Code: 0 (SUCCESS)
08/24 20:40:23> Remote Command: Executing …
08/24 20:40:22> Remote Command: Establishing connection…
08/24 20:40:22> Job Queue: Initiating ‘Remote command …’
08/24 20:40:22> Job Queue: Label:CBSCheck
08/24 20:40:22> Job Queue: Execution jumping to Label:CBSCheck
08/24 20:40:22> Job Queue: Initiating ‘Goto label:CBSCheck’
08/24 20:40:22> Job Queue: Execution continuing. This step has been executed 2 times.
08/24 20:40:22> Job Queue: Initiating ‘If this step is executed 30 times, goto label:Remanage’ – This is step 27
08/24 20:39:21> Waiting 1 minute…
08/24 20:39:21> Job Queue: Initiating ‘Wait 1 minute’
08/24 20:39:21> Job Queue: Execution continuing. Previous action exit code: 1
08/24 20:39:21> Job Queue: Initiating ‘If previous action was successful (returned 0), goto label:CBSComplete’
08/24 20:39:20> Remote Command: Exit Code: 1
08/24 20:39:17> Remote Command: Executing …
08/24 20:39:16> Remote Command: Establishing connection…
08/24 20:39:16> Job Queue: Initiating ‘Remote command …’
08/24 20:39:16> Job Queue: Label:CBSCheck
08/24 20:39:16> Job Queue: Execution jumping to Label:CBSCheck
08/24 20:39:16> Job Queue: Initiating ‘Goto label:CBSCheck’
08/24 20:39:16> Job Queue: Execution continuing. This step has been executed 1 time.
08/24 20:39:16> Job Queue: Initiating ‘If this step is executed 30 times, goto label:Remanage’ – This is step 27
08/24 20:38:16> Waiting 1 minute…
08/24 20:38:16> Job Queue: Initiating ‘Wait 1 minute’
08/24 20:38:16> Job Queue: Execution continuing. Previous action exit code: 1
08/24 20:38:16> Job Queue: Initiating ‘If previous action was successful (returned 0), goto label:CBSComplete’
08/24 20:38:15> Remote Command: Exit Code: 1
08/24 20:38:10> Remote Command: Executing …
08/24 20:38:09> Remote Command: Establishing connection…
08/24 20:38:09> Job Queue: Initiating ‘Remote command …’
08/24 20:38:09> Job Queue: Label:CBSCheck

Step 35 seems to have inherited the counter from step 27.

[doug]

Thanks for highlighting this. I understand what you’re describing. Would it be possible for you to share the actual job queue steps? Feel free to redact any elements as needed. To share it you can open the Job Queue window and load the queue, then press middle-click/scroll-wheel-click directly on top of the queue contents window. Doing that will show you the entire queue in a text window that you can copy from and then paste into your response here. This will help us ensure that we properly address this apparent bug.

[mkreitzer]

Sure. There’s nothing to redact, I just edited the previous for brevity/clarity. The complete job queue is below:

Job Queue
* Generic Update *
. . . . . . . . . .
Clear columns (Pre Update Clear):: Ping Reply%**%Reboot Messages%**%Windows Update Messages%**%Progress%**%Local Agent Log%**%Remote Agent Log%**%Last Boot Time%**%Total Uptime%**%Job Queue Activity%**%Deployment Output Log%**%Pending Reboot%**%All Messages
Set row color:-19276
Start pinging
Wait 1 minute
If host is offline, goto label:SendEmailReport
Deployment (Check Disk Space):: FileToDeploy:: C:\BatchPatch\Scripts\DiskCheck.vbs%**%CopyEntireFolder:: FALSE%**%LeaveEntireFolder:: FALSE%**%RetrieveConsoleOutput:: FALSE%**%Command:: cscript.exe “DiskCheck.vbs”%**%Parameters::
If previous action failed/errored (returned non-0), goto label:SendEmailReport
Check for available updates
If most recent ‘Check for available updates’ found 0 updates, goto label:SendEmailReport
Download available updates
Local command (Orion Unmanage):: powershell.exe -ExecutionPolicy Bypass C:\BatchPatch\Scripts\OrionUnmanage.ps1 -Action Unmanage -NodeName $host
If ‘Get pending reboot status’ returns FALSE, goto label:NoPendingReboot
Reboot (force always)
Wait for host to go offline and come back online
Wait 5 minutes
Label:NoPendingReboot
Label:InstallUpdates
Install downloaded updates
Local command (Update VMware Tools):: powershell.exe -ExecutionPolicy Bypass C:\BatchPatch\Scripts\Update-VMwareTools.ps1 -VMName $host
If ‘Get pending reboot status’ returns FALSE, goto label:CBSCheck
Reboot (force always)
Wait for host to go offline and come back online
Label:CBSCheck
Remote command (CBS ServicingInProgress Check):: powershell.exe -ExecutionPolicy Bypass -Command “$cbsBase = ‘HKLM:\SOFTWARE\Microsoft\Windows\CurrentVersion\Component Based Servicing’; $iface = Join-Path $cbsBase ‘Interface’; $ti = Join-Path $cbsBase ‘TiRunning’; try { $busy = ((Get-ItemProperty -Path $iface -ErrorAction Stop).ServicingInProgress -ne 0) } catch { $busy = $false }; exit [int]($busy -or (Test-Path $ti))”
If previous action was successful (returned 0), goto label:CBSComplete
Wait 1 minute
If this step is executed 30 times, goto label:Remanage
Goto label:CBSCheck
Label:CBSComplete
Wait 1 minute
Remote command (Force WSUS Update):: powershell.exe -ExecutionPolicy Bypass -Command “$updateSession = new-object -com ‘Microsoft.Update.Session’; $updates=$updateSession.CreateupdateSearcher().Search($criteria).Updates ; wuauclt /reportnow”
Wait 1 minute
Check for available updates
If most recent ‘Check for available updates’ found 0 updates, goto label:AllUpdatesComplete
If this step is executed 3 times, goto label:Remanage
Download available updates
Goto label:InstallUpdates
Label:AllUpdatesComplete
Set row color:-4915276
Label:Remanage
Local command (Orion Remanage):: powershell.exe -ExecutionPolicy Bypass C:\BatchPatch\Scripts\OrionUnmanage.ps1 -Action Remanage -NodeName $host
Label:SendEmailReport
Stop pinging
Get last boot time
Send email notification with default settings

[doug]

Thank you very much. This is helpful.

Btw FYI you can prob remove your CBSCheck because the ‘Get Pending Reboot Status’ already includes CBS as part of its check. It’s explained here:

https://batchpatch.com/explanation-of-get-pending-reboot-status-actions-in-batchpatch

[mkreitzer]

Thanks for the suggestion, but this is looking for something different. Specifically, if CBS is processing post install jobs. This is the “Getting Windows Ready…” part of the process. With newer windows this is made easy as it writes the “ServicingInProgress” value. If you inspect the CBS log file it will actually log when it sets it to 0 after completing all pending operations. The “TiRunning” key check is a fall back for the small number of 2012 R2 systems we have. The TiRunning key keeps a running list of pending jobs and is deleted when all have been processed.

I’ve seen this process take upwards of 15 – 20 minutes to complete. These jobs are part of advanced multi-queue groups and are designed highly defensively (as you no doubt noticed) to ensure the current group is, in fact, completely done before moving on.

And I’m not done. Among other things I’m still planning to write a script to ensure .NET native image generation post update is complete. This is often observed as a long period of 100% CPU activity after updates, and it can become a problem if 30 VM’s all start doing it at once.

[doug]

Oh interesting. Thanks for the info. That makes sense. I hadn’t scrutinized it carefully enough to realize what you were actually doing there. Very cool.

[Author]

Posts