In Quebec : MID Server upgrade stops if PowerShell tests in Pre-upgrade check failed, PowerConsole remains busy, and closing the PowerShell session fails - Known Error

Description

If PowerShell console is very slow on the MID Server host machine, and any of the pre-uprgade powershell tests fail because of timeout, MID Server upgrade would stop with some errors like below:

03/19/21 11:01:28 (310) AutoUpgrade.3600 WARNING *** WARNING *** PowerConsole unable to close : Command [exit] timed out after PT2M
03/19/21 11:01:31 (301) AutoUpgrade.3600 SEVERE *** ERROR *** PowerConsole is in the busy state and cannot run any commands
java.lang.IllegalStateException: PowerConsole is in the busy state and cannot run any commands
at com.service_now.mid.win.powershell.api.PowerConsole.execute(PowerConsole.java:169)
at com.service_now.mid.win.powershell.api.APowershellSession.executeWithoutResultExtraction(APowershellSession.java:366)
at com.service_now.mid.win.powershell.api.APowershellSession.execute(APowershellSession.java:346)
at com.service_now.mid.win.powershell.api.APowershellSession.execute(APowershellSession.java:334)
at com.service_now.mid.win.powershell.api.LocalPowerShellSession.close(LocalPowerShellSession.java:48)
at com.service_now.mid.dist.upgrade.MIDUpgrader.runPowerShellTests(MIDUpgrader.java:691)
at com.service_now.mid.dist.upgrade.MIDUpgrader.runPreUpgradeCheck(MIDUpgrader.java:416)
at com.service_now.monitor.AutoUpgrade.attemptUpgrade(AutoUpgrade.java:165)
at com.service_now.monitor.AutoUpgrade.run(AutoUpgrade.java:111)
at com.service_now.monitor.AMonitor.runit(AMonitor.java:155)
at com.service_now.monitor.AMonitor.access$200(AMonitor.java:44)
at com.service_now.monitor.AMonitor$MonitorTask.execute(AMonitor.java:148)
at com.service_now.monitor.base.AMonitorTask.run(AMonitorTask.java:29)
at java.base/java.util.TimerThread.mainLoop(Timer.java:556)
at java.base/java.util.TimerThread.run(Timer.java:506)

04/12/21 11:13:46 (848) AutoUpgrade.3600 Setting mid status to Upgrading
04/12/21 11:13:46 (848) AutoUpgrade.3600 Instance.updateAgentRecordState(), OperationalState=UPGRADING
04/12/21 11:13:46 (911) AutoUpgrade.3600 Pausing monitor: StatusMonitor
04/12/21 11:13:46 (927) AutoUpgrade.3600 Getting instance ACLs for table: ecc_agent_log
04/12/21 11:13:47 (065) AutoUpgrade.3600 Getting instance ACLs for table: ecc_agent_upgrade_history
04/12/21 11:13:47 (205) AutoUpgrade.3600 Getting instance ACLs for table: ecc_agent_upgrade_history_stage
04/12/21 11:13:47 (408) AutoUpgrade.3600 Performing pre-upgrade validation tests.
04/12/21 11:13:47 (408) AutoUpgrade.3600 Downloading from https://install.service-now.com/glide/distribution/builds/package/app-signed/mid-upgrade/2021/03/14/mid-upgrade.quebec-12-09-2020__patch1-hotfix1-03-12-2021_03-14-2021_1717.preUpgradeCheck.zip
04/12/21 11:13:47 (408) AutoUpgrade.3600 For MID server auto upgrade, using proxy host=xxxx.com, port=8080, user=null
04/12/21 11:13:48 (518) AutoUpgrade.3600 Downloading C:\ServiceNow\TEST\ServiceNow MID Server NOW-MID-TEST-1\agent\package\incoming\preUpgradeCheck.zip, 1193 bytes
...
04/12/21 11:13:48 (533) AutoUpgrade.3600 Package was successfully downloaded from https://install.service-now.com/glide/distribution/builds/package/app-signed/mid-upgrade/2021/03/14/mid-upgrade.quebec-12-09-2020__patch1-hotfix1-03-12-2021_03-14-2021_1717.preUpgradeCheck.zip
04/12/21 11:13:48 (705) AutoUpgrade.3600 Verifying digital signature of C:\ServiceNow\TEST\ServiceNow MID Server NOW-MID-TEST-1\agent\package\incoming\preUpgradeCheck.zip
04/12/21 11:13:48 (783) AutoUpgrade.3600 Extracting: C:\Users\xxxxx\AppData\Local\Temp\1618218828783-0\META-INF\MANIFEST.MF
...
04/12/21 11:13:48 (799) AutoUpgrade.3600 Upgrade check files extracted to C:\Users\xxxxx\AppData\Local\Temp\1618218828783-0
04/12/21 11:13:48 (799) AutoUpgrade.3600 Upgrade check file contents validated
04/12/21 11:13:48 (799) AutoUpgrade.3600 Moving upgrade check file to C:\ServiceNow\TEST\ServiceNow MID Server NOW-MID-TEST-1\agent\package\upgradeCheck
04/12/21 11:13:48 (799) AutoUpgrade.3600 Upgrade check file contents validated
04/12/21 11:13:48 (799) AutoUpgrade.3600 The service name is detected as snc_mid_NOW-MID-TEST-1
04/12/21 11:13:48 (846) AutoUpgrade.3600 WARNING *** WARNING *** no context : null
...
04/12/21 11:18:50 (078) AutoUpgrade.3600 SEVERE *** ERROR *** Exception during executeCommand, keeping PowerConsole in busy state
com.snc.automation_common.integration.exceptions.CommandTimeoutException: Command [snc-decode-command cnVuVXBncmFkZUNoZWNrICJzbmNfbWlkX05PVy1NSUQtVEVTVC0xIg== | invoke-expression] timed out after PT5M
 at com.service_now.mid.win.powershell.api.PowerConsole.executeCurrentCommand(PowerConsole.java:258)
 at com.service_now.mid.win.powershell.api.PowerConsole.executeCommand(PowerConsole.java:201)
 at com.service_now.mid.win.powershell.api.PowerConsole.execute(PowerConsole.java:173)
 at com.service_now.mid.win.powershell.api.APowershellSession.executeWithoutResultExtraction(APowershellSession.java:366)
 at com.service_now.mid.win.powershell.api.APowershellSession.execute(APowershellSession.java:346)
 at com.service_now.mid.win.powershell.api.APowershellSession.execute(APowershellSession.java:334)
 at com.service_now.mid.dist.upgrade.MIDUpgrader.runPowerShellTests(MIDUpgrader.java:677)
 at com.service_now.mid.dist.upgrade.MIDUpgrader.runPreUpgradeCheck(MIDUpgrader.java:416)
 at com.service_now.monitor.AutoUpgrade.attemptUpgrade(AutoUpgrade.java:165)
 at com.service_now.monitor.AutoUpgrade.run(AutoUpgrade.java:111)
 at com.service_now.monitor.AMonitor.runit(AMonitor.java:155)
 at com.service_now.monitor.AMonitor.access$200(AMonitor.java:44)
 at com.service_now.monitor.AMonitor$MonitorTask.execute(AMonitor.java:148)
 at com.service_now.monitor.base.AMonitorTask.run(AMonitorTask.java:29)
 at java.base/java.util.TimerThread.mainLoop(Timer.java:556)
 at java.base/java.util.TimerThread.run(Timer.java:506)

04/12/21 11:18:50 (078) AutoUpgrade.3600 WARNING *** WARNING *** Command [snc-decode-command cnVuVXBncmFkZUNoZWNrICJzbmNfbWlkX05PVy1NSUQtVEVTVC0xIg== | invoke-expression] timed out after PT5M:, command: runUpgradeCheck "snc_mid_NOW-MID-TEST-1", stdout: [], stderr[] : Command [snc-decode-command cnVuVXBncmFkZUNoZWNrICJzbmNfbWlkX05PVy1NSUQtVEVTVC0xIg== | invoke-expression] timed out after PT5M
04/12/21 11:18:50 (078) AutoUpgrade.3600 WARNING *** WARNING *** Continuing with upgrade, but the following issue was encountered during upgradeCheck: Command [snc-decode-command cnVuVXBncmFkZUNoZWNrICJzbmNfbWlkX05PVy1NSUQtVEVTVC0xIg== | invoke-expression] timed out after PT5M
...
04/12/21 11:19:20 (698) AutoUpgrade.3600 SEVERE *** ERROR *** PowerConsole is in the busy state and cannot run any commands
java.lang.IllegalStateException: PowerConsole is in the busy state and cannot run any commands
 at com.service_now.mid.win.powershell.api.PowerConsole.execute(PowerConsole.java:169)
 at com.service_now.mid.win.powershell.api.APowershellSession.executeWithoutResultExtraction(APowershellSession.java:366)
 at com.service_now.mid.win.powershell.api.APowershellSession.execute(APowershellSession.java:346)
 at com.service_now.mid.win.powershell.api.APowershellSession.execute(APowershellSession.java:334)
 at com.service_now.mid.win.powershell.api.LocalPowerShellSession.close(LocalPowerShellSession.java:48)
 at com.service_now.mid.dist.upgrade.MIDUpgrader.runPowerShellTests(MIDUpgrader.java:691)
 at com.service_now.mid.dist.upgrade.MIDUpgrader.runPreUpgradeCheck(MIDUpgrader.java:416)
 at com.service_now.monitor.AutoUpgrade.attemptUpgrade(AutoUpgrade.java:165)
 at com.service_now.monitor.AutoUpgrade.run(AutoUpgrade.java:111)
 at com.service_now.monitor.AMonitor.runit(AMonitor.java:155)
 at com.service_now.monitor.AMonitor.access$200(AMonitor.java:44)
 at com.service_now.monitor.AMonitor$MonitorTask.execute(AMonitor.java:148)
 at com.service_now.monitor.base.AMonitorTask.run(AMonitorTask.java:29)
 at java.base/java.util.TimerThread.mainLoop(Timer.java:556)
 at java.base/java.util.TimerThread.run(Timer.java:506)

Steps to Reproduce

It is hard to re-produce the issue. You have to create a scenario which Application Experience test failed with PowerConsoleTerminatedException or CommandTimeoutException. In this case the pre-upgrade will be stop.

Workaround

This problem has been fixed. If you are able to upgrade, review the Fixed In or Intended Fix Version fields to determine whether any versions have a planned or permanent fix.

Workarounds:

The best work-around is to verify why PowerShell is slow on the MID Server host machine. You can verify if there are many open idle session running on the machine.
OR
You can temporary skip the pre-upgrade check by adding "mid.upgrade.run_precheck=false" to a MID Server's configuration parameters.
NOTE: This should be deleted again as soon as you have upgraded to a fixed version, as these pre-checks are very important for avoiding other upgrade issues that may leave a mid server down.

Related Problem: PRB1489024