The MID Server Upgrade service doesn't properly detect if the MID Server has fully shut down, and so has issues with file locks when it starts deleting, potentially leaving the MID Server down - Known Error

The MID Server Upgrade service doesn't properly detect if the MID Server has fully shut down, and so has issues with file locks when it starts deleting, potentially leaving the MID Server down Description Once the MID Server Upgrade service detects the MID Server is shut down, it starts to delete files in agent/bin and agent/lib immediately. The detection code can get this wrong and start deleting before the MID Server has shut down .

This is done by running "mid.bat status", which queries the wrapper, which reports "Running: No". The wrapper process is still running at that point in order to be able to do that , and so clearly isn't fully shut down quite yet, and deletes should not start yet until we have confirmed the processes are no longer running.

If, for whatever reason, the MID Server service has still not shut down after 10 minutes, the java and wrapper processes will still be locking the executable files and the upgrade service will fail, leaving the MID Server Down, and probably with empty bin and lib folders, and so unable to start again without a manual repair or re-install.

Notes for discounting this PRB: This PRB is not for the cause of the main MID Server shutdown to have failed. It is for the check in the upgrade service getting it wrong. Specific PRBs for stuck threads that prevent shutdown may already exist. This problem ticket is to be linked to cases when it has been confirmed that the MID Server java/wrapper processes were still running at the time, which is likely to need it also timing out at 10 minutes, and have the Paris logging. If the MID Server was shut down, and Resource Monitor shows other processes such as anti-virus were locking files/handles, then other PRBs exist. Symptoms: The MID Server agent log will show the normal shutdown logging, which may also show other extensions/collectors/listeners shutting down depending on the MID Server configuration:

08/06/20 22:26:44 (005) Wrapper-Stopper Closing com.service_now.mid.cluster.ignite.IgniteClusterManager 08/06/20 22:26:44 (005) Wrapper-Stopper Main.handleStop() after shutdown, OperationalState=UPGRADING 08/06/20 22:26:44 (114) MIDServer MID Server stopping 08/06/20 22:26:44 (458) MIDServer Stoping LDAP Listener for: xxx 08/06/20 22:26:44 (598) MIDServer Stoping LDAP Listener for: yyy 08/06/20 22:26:44 (848) MIDServer MID Server stopped 08/06/20 22:26:45 (770) Thread-1 Shutdown hook entered 08/06/20 22:26:45 (770) Thread-1 Stopping MID server 08/06/20 22:26:45 (770) Thread-1 Main.handleStop() before shutdown, OperationalState=UPGRADING 08/06/20 22:26:45 (770) Thread-1 Main.handleStop() after shutdown, OperationalState=UPGRADING But the wrapper.log does NOT show the wrapper actually stopped. You would normally expect something like this to confirm the wrapper has stopped the JRE:

2019/12/31 12:24:59 | Stopping the ServiceNow MID Server_xxx service... 2019/12/31 12:25:04 | Waiting to stop... 2019/12/31 12:25:04 | The upgrade service then checks that the MID Server service is down. This can be seen in wrapper.log or glide-dist-upgrade.log:

INFO | jvm 1 | 2020/08/07 11:44:37.359 | aug. 07, 2020 11:44:37 AM com.snc.dist.mid_upgrade. UpgradeMain waitForMidShutdown INFO | jvm 1 | 2020/08/07 11:44:37.359 | INFO: Waiting for MID server to shutdown . INFO | jvm 1 | 2020/08/07 11:44:39.437 | aug. 07, 2020 11:44:39 AM com.snc.dist.mid_upgrade.UpgradeMain executeCommand INFO | jvm 1 | 2020/08/07 11:44:39.437 | INFO: Executing command `"C:\ServiceNow\MidServerDev\agent\bin\ mid.bat" status `. Working dir: `C:\ServiceNow\MidServerDev\agent`. Current user: `SvcAcc-ServiceNowMID`. INFO | jvm 1 | 2020/08/07 11:44:39.437 | aug. 07, 2020 11:44:39 AM com.snc.dist.mid_upgrade.UpgradeMain executeCommand INFO | jvm 1 | 2020/08/07 11:44:39.437 | INFO: Execution result: ExitCode=0 INFO | jvm 1 | 2020/08/07 11:44:39.437 | Output=wrapperm | The ServiceNow MID Server_MidServerDev Service is installed. INFO | jvm 1 | 2020/08/07 11:44:39.437 | wrapperm | Start Type: Automatic INFO | jvm 1 | 2020/08/07 11:44:39.437 | wrapperm | Interactive: No INFO | jvm 1 | 2020/08/07 11:44:39.437 | wrapperm | Running: Yes INFO | jvm 1 | 2020/08/07 11:44:39.437 | INFO | jvm 1 | 2020/08/07 11:44:39.437 | ErrorMsg=null INFO | jvm 1 | 2020/08/07 11:44:41.515 | aug. 07, 2020 11:44:41 AM com.snc.dist.mid_upgrade.UpgradeMain executeCommand INFO | jvm 1 | 2020/08/07 11:44:41.515 | INFO: Executing command `"C:\ServiceNow\MidServerDev\agent\bin\ mid.bat" status `. Working dir: `C:\ServiceNow\MidServerDev\agent`. Current user: `SvcAcc-ServiceNowMID`. INFO | jvm 1 | 2020/08/07 11:44:41.515 | aug. 07, 2020 11:44:41 AM com.snc.dist.mid_upgrade.UpgradeMain executeCommand INFO | jvm 1 | 2020/08/07 11:44:41.515 | INFO: Execution result: ExitCode=0 INFO | jvm 1 | 2020/08/07 11:44:41.515 | Output=wrapperm | The ServiceNow MID Server_MidServerDev Service is installed. INFO | jvm 1 | 2020/08/07 11:44:41.515 | wrapperm | Start Type: Automatic INFO | jvm 1 | 2020/08/07 11:44:41.515 | wrapperm | Interactive: No INFO | jvm 1 | 2020/08/07 11:44:41.515 | wrapperm | Running: No INFO | jvm 1 | 2020/08/07 11:44:41.515 | INFO | jvm 1 | 2020/08/07 11:44:41.515 | ErrorMsg=null Paris adds additional debug code, so the upgrade log in the wrapper log shows the MID Server java and wrapper processes were still running at the 10 minute timeout. This host had multiple MID Servers running on it, but by running "wmic service" to match PIDs with Service names, and a process of elimination, it was confirmed the mid server was still running. That debugging would be easier on a host with fewer or 1 mid server. ServiceNow intend to improve that debug in a future version with service names and possibly even a stack trace of the MID Server (STRY51308739).

...INFO | jvm 1 | 2020/08/07 11:54:43.993 | aug. 07, 2020 11:54:43 AM com.snc.dist.mid_upgrade.UpgradeMain missingOrCanDelete INFO | jvm 1 | 2020/08/07 11:54:43.993 | INFO: C:\ServiceNow\MidServerDev\agent\bin\ wrapper-windows-x86-64.exe cannot be deleted : C:\ServiceNow\MidServerDev\agent\bin\wrapper-windows-x86-64.exe (The process cannot access the file because it is being used by another process) INFO | jvm 1 | 2020/08/07 11:54:43.993 | 554ms left to timeout for deleting files. Retrying in 1000ms... INFO | jvm 1 | 2020/08/07 11:54:44.977 | aug. 07, 2020 11:54:44 AM com.snc.dist.mid_upgrade.UpgradeMain missingOrCanDelete INFO | jvm 1 | 2020/08/07 11:54:44.977 | SEVERE: C:\ServiceNow\MidServerDev\agent\bin\ wrapper-windows-x86-64.exe is still locked after 594 retries, giving up. INFO | jvm 1 | 2020/08/07 11:54:45.196 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil checkLockUsingPowerShell INFO | jvm 1 | 2020/08/07 11:54:45.196 | INFO: Trying PowerShell commands to find the process that uses C:\ServiceNow\MidServerDev\agent\bin\wrapper-windows-x86-64.exe INFO | jvm 1 | 2020/08/07 11:54:45.743 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil checkLockUsingPowerShell INFO | jvm 1 | 2020/08/07 11:54:45.743 | INFO: The following processes are reported by powershell to use the file C:\ServiceNow\MidServerDev\agent\bin\wrapper-windows-x86-64.exe >>>> No processes reported locking the file. It is the fact it is still running that makes it locked. INFO | jvm 1 | 2020/08/07 11:54:45.743 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil checkLockUsingPowerShell INFO | jvm 1 | 2020/08/07 11:54:45.743 | INFO: No matching powershell command found INFO | jvm 1 | 2020/08/07 11:54:45.743 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil checkLockUsingTaskList INFO | jvm 1 | 2020/08/07 11:54:45.743 | INFO: Trying tasklist /m commands to find the process that uses C:\ServiceNow\MidServerDev\agent\bin\wrapper-windows-x86-64.exe INFO | jvm 1 | 2020/08/07 11:54:45.852 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil checkLockUsingTaskList INFO | jvm 1 | 2020/08/07 11:54:45.852 | INFO: The following processes are reported by tasklist /m to use the file C:\ServiceNow\MidServerDev\agent\bin\wrapper-windows-x86-64.exe INFO | jvm 1 | 2020/08/07 11:54:45.852 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil checkLockUsingTaskList INFO | jvm 1 | 2020/08/07 11:54:45.852 | INFO: INFO: No tasks are running which match the specified criteria. INFO | jvm 1 | 2020/08/07 11:54:45.852 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil logRunningProcesses INFO | jvm 1 | 2020/08/07 11:54:45.852 | INFO: Trying tasklist command to log the running processes INFO | jvm 1 | 2020/08/07 11:54:45.962 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.WindowsMIDUpgradeUtil logRunningProcesses INFO | jvm 1 | 2020/08/07 11:54:45.962 | INFO: INFO | jvm 1 | 2020/08/07 11:54:45.962 | Image Name PID Session Name Session# Mem Usage INFO | jvm 1 | 2020/08/07 11:54:45.962 | ========================= ======== ================ =========== ============ INFO | jvm 1 | 2020/08/07 11:54:45.962 | System Idle Process 0 Services 0 4 K INFO | jvm 1 | 2020/08/07 11:54:45.962 | System 4 Services 0 276 K ... INFO | jvm 1 | 2020/08/07 11:54:45.962 | wrapper-windows-x86-64.ex 1568 Services 0 8.872 K INFO | jvm 1 | 2020/08/07 11:54:45.962 | java.exe 2300 Services 0 795.652 K ... INFO | jvm 1 | 2020/08/07 11:54:45.962 | wrapper-windows-x86-64.ex 7784 Services 0 7.788 K INFO | jvm 1 | 2020/08/07 11:54:45.962 | java.exe 2460 Services 0 697.644 K ... INFO | jvm 1 | 2020/08/07 11:54:45.962 | wrapper-windows-x86-64.ex 848 Services 0 7.712 K INFO | jvm 1 | 2020/08/07 11:54:45.962 | java.exe 8708 Services 0 58.396 K ... INFO | jvm 1 | 2020/08/07 11:54:45.962 | tasklist.exe 712 Services 0 6.088 K ... INFO | jvm 1 | 2020/08/07 11:54:45.962 | INFO | jvm 1 | 2020/08/07 11:54:45.962 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.UpgradeMain run INFO | jvm 1 | 2020/08/07 11:54:45.962 | SEVERE: java.lang.Exception: Cannot complete upgrade, one or more files in the upgrade tree are locked and cannot be upgraded INFO | jvm 1 | 2020/08/07 11:54:45.962 | java.lang.Exception: Cannot complete upgrade, one or more files in the upgrade tree are locked and cannot be upgraded INFO | jvm 1 | 2020/08/07 11:54:45.962 | at com.snc.dist.mid_upgrade.UpgradeMain.run(UpgradeMain.java:365) INFO | jvm 1 | 2020/08/07 11:54:45.962 | at java.lang.Thread.run(Thread.java:748) INFO | jvm 1 | 2020/08/07 11:54:45.962 | INFO | jvm 1 | 2020/08/07 11:54:45.962 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.UpgradeMarker markService INFO | jvm 1 | 2020/08/07 11:54:45.962 | INFO: Added service `snc-platform-dist-upgrade-midserverdev` to upgrade marker file. INFO | jvm 1 | 2020/08/07 11:54:45.962 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.UpgradeMain run INFO | jvm 1 | 2020/08/07 11:54:45.962 | INFO: ***********UPGRADE MAIN LOGIN END*********** INFO | jvm 1 | 2020/08/07 11:54:45.962 | aug. 07, 2020 11:54:45 AM com.snc.dist.mid_upgrade.UpgradeMain appendMidLogs INFO | jvm 1 | 2020/08/07 11:54:45.962 | INFO: Flushing logs > Steps to Reproduce

This is hard to reproduce on demand, as it requires something to prevent the MID Server service shutting down.

Workaround This problem is currently under review. You can contact ServiceNow Technical Support or subscribe to this Known Error article by clicking the Subscribe button at the top right of this form to be notified when more information will become available.