MID Server fails to auto upgrade and to restart with agent log error "wrapper-windows-x86-64.exe cannot be deleted"


Description

MID Server failed to Auto Upgrade: Looking at the Agent log, the upgrade process seems to be successful but we can see that file: "wrapper-windows-x86-64.exe cannot be deleted" in Agent log and MID server won't restart.

Cause

Resolution

As per the Error below, MID server Auto upgrade process seems to be failing with unable to delete the file "wrapper-windows-x86-64.exe". Manually attempting to delete the file from the path shows that the file is in use by the "DHCP Client" as per the screenshot above.

It was later found that was another MID server services in the Windows Service is configured with the same path to the MID server that was attempting to Auto upgrade.

So check all the MID server services. if there is duplicate found, stop the services and attempt to try the "Auto Upgrade" process again.

Once the upgrade process is completed, remove any duplicate/old services no longer in use by using the command "sc delete <Service name>".

Please take care when using this command.

<Service Name> can be found by right-clicking on the Service Name -> then click on Properties -> Under the "General" Tab, there is "Service name".

 

Wrapper:
=========
INFO | jvm 1 | 2020/03/02 21:14:34.108 | INFO: D:\MID Servers\agent\bin\wrapper-windows-x86-64.exe cannot be deleted: D:\MID Servers\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/03/02 21:14:34.123 | Retrying in 1000ms...
INFO | jvm 1 | 2020/03/02 21:14:35.123 | Mar 02, 2020 9:14:35 PM com.snc.dist.mid_upgrade.UpgradeMain missingOrCanDelete
INFO | jvm 1 | 2020/03/02 21:14:35.123 | INFO: D:\MID Servers\agent\bin\wrapper-windows-x86-64.exe is no longer locked after 1 checks.
INFO | jvm 1 | 2020/03/02 21:14:35.139 | Mar 02, 2020 9:14:35 PM com.snc.dist.mid_upgrade.UpgradeMarker markService
INFO | jvm 1 | 2020/03/02 21:14:35.155 | INFO: Added service `snc-platform-dist-upgrade-devsccm` to upgrade marker file.
INFO | jvm 1 | 2020/03/02 21:14:35.155 | Mar 02, 2020 9:14:35 PM com.snc.dist.mid_upgrade.UpgradeMain waitForMidShutdown
INFO | jvm 1 | 2020/03/02 21:14:35.170 | INFO: Waiting for MID server to shutdown.
INFO | jvm 1 | 2020/03/02 21:24:35.742 | Mar 02, 2020 9:24:35 PM com.snc.dist.mid_upgrade.UpgradeMain run
INFO | jvm 1 | 2020/03/02 21:24:35.742 | SEVERE: com.snc.dist.mid_upgrade.UpgradeException: Timed out waiting for MID server to shutdown.
INFO | jvm 1 | 2020/03/02 21:24:35.758 | com.snc.dist.mid_upgrade.UpgradeException: Timed out waiting for MID server to shutdown.
INFO | jvm 1 | 2020/03/02 21:24:35.773 | at com.snc.dist.mid_upgrade.UpgradeMain.waitForMidShutdown(UpgradeMain.java:736)
INFO | jvm 1 | 2020/03/02 21:24:35.789 | at com.snc.dist.mid_upgrade.UpgradeMain.run(UpgradeMain.java:308)
INFO | jvm 1 | 2020/03/02 21:24:35.789 | at java.lang.Thread.run(Thread.java:748)
INFO | jvm 1 | 2020/03/02 21:24:35.805 |
INFO | jvm 1 | 2020/03/02 21:24:35.805 | Mar 02, 2020 9:24:35 PM com.snc.dist.mid_upgrade.UpgradeMain appendMidLogs
INFO | jvm 1 | 2020/03/02 21:24:35.820 | INFO: Flushing logs

Agent log:
========
03/02/20 21:14:15 (683) AutoUpgrade.3600 Extracting: C:\Users\SA-SNO~1\AppData\Local\Temp\1583212444165-0\agent\wrapper-development-license-1.3.txt
03/02/20 21:14:15 (683) AutoUpgrade.3600 Extracting: C:\Users\SA-SNO~1\AppData\Local\Temp\1583212444165-0\agent\wrapper-tsims-addendum-1.3.txt
03/02/20 21:14:15 (683) AutoUpgrade.3600 Extracting package D:\MID Servers\agent\package\incoming\mid-upgrade.madrid-12-18-2018__patch9b-01-28-2020_02-05-2020_1536.universal.universal.zip to C:\Users\SA-SNO~1\AppData\Local\Temp\1583212444165-0
03/02/20 21:14:16 (011) AutoUpgrade.3600 Stopping MID server. Bootstrapping upgrade.
03/02/20 21:14:16 (011) AutoUpgrade.3600 MIDUpgrader.startUpgradeRunner(), OperationalState=UPGRADING
03/02/20 21:14:25 (169) Gobbling stdout: cmd.exe /C bin\glide-dist-upgrade.bat start Gobbled: STATUS | wrapper | 2020/03/02 21:14:21 | Starting the ServiceNow Platform Distribution Upgrade (devsccm) service...
03/02/20 21:14:25 (169) Gobbling stdout: cmd.exe /C bin\glide-dist-upgrade.bat start Gobbled: STATUS | wrapper | 2020/03/02 21:14:25 | ServiceNow Platform Distribution Upgrade (devsccm) started.
03/02/20 21:14:27 (216) AutoUpgrade.3600 Added marker `C:\Users\SA-SNO~1\AppData\Local\Temp\1583212444165-0` to upgrade marker file.
03/02/20 21:14:28 (216) Wrapper-Stopper Running under Java version: 1.8.0_181-sncmid1, java PID: 5908, args: stop
03/02/20 21:14:28 (216) Wrapper-Stopper Stopping MID server
03/02/20 21:14:28 (216) Wrapper-Stopper Main.handleStop() before shutdown, OperationalState=UPGRADING
03/02/20 21:14:28 (544) Wrapper-Stopper Setting mid status to Down
03/02/20 21:14:28 (544) Wrapper-Stopper Instance.updateAgentRecordStopped(), OperationalState=UPGRADING
03/02/20 21:14:28 (700) Wrapper-Stopper interrupting thread IdleConnectionMonitor.5
03/02/20 21:14:28 (966) Wrapper-Stopper interrupting thread AutoUpgrade.3600
03/02/20 21:14:29 (200) Wrapper-Stopper interrupting thread RefreshMonitor.65
03/02/20 21:14:29 (435) Wrapper-Stopper interrupting thread LogStatusMonitor.60
03/02/20 21:14:29 (685) Wrapper-Stopper interrupting thread ECCQueueMonitor.40
03/02/20 21:14:29 (919) Wrapper-Stopper interrupting thread FileSyncer.1
03/02/20 21:14:30 (154) Wrapper-Stopper interrupting thread ECCSender.1
03/02/20 21:14:30 (388) Wrapper-Stopper Destroying injector...
03/02/20 21:14:30 (388) Wrapper-Stopper Closing com.service_now.mid.amb.AMBClientProvider
03/02/20 21:14:31 (341) Wrapper-Stopper Closing com.service_now.monitor.PriorityThreadPoolProvider
03/02/20 21:14:31 (341) Wrapper-Stopper Shutting down ThreadPool-Interactive
03/02/20 21:14:31 (341) Wrapper-Stopper Shutting down ThreadPool-Standard
03/02/20 21:14:31 (341) Wrapper-Stopper Shutting down ThreadPool-Expedited
03/02/20 21:14:31 (341) Wrapper-Stopper ThreadPool-Interactive terminated
03/02/20 21:14:31 (341) Wrapper-Stopper ThreadPool-Standard terminated
03/02/20 21:14:31 (341) Wrapper-Stopper ThreadPool-Expedited terminated
03/02/20 21:14:31 (341) Wrapper-Stopper Closing com.service_now.mid.extension.container.ExtensionContainer
03/02/20 21:14:31 (341) Wrapper-Stopper ExtensionContainer is shutting down...
03/02/20 21:14:31 (341) Wrapper-Stopper ...waiting a maximum shutdown time of 1000ms
03/02/20 21:14:31 (341) Wrapper-Stopper ExtensionContainer is cleanly shut down
03/02/20 21:14:31 (341) Wrapper-Stopper Closing com.service_now.mid.probe.event.SNEventBulkSender
03/02/20 21:14:31 (951) EventBulkSenderThread-1 the event sender was stopped after sending 0 events in 0 bulks.
03/02/20 21:14:31 (951) Wrapper-Stopper Closing com.service_now.mid.cluster.ignite.IgniteClusterManager
03/02/20 21:14:31 (951) Wrapper-Stopper Main.handleStop() after shutdown, OperationalState=UPGRADING
03/02/20 21:14:31 (967) MIDServer MID Server stopping
03/02/20 21:14:32 (545) MIDServer MID Server stopped
03/02/20 21:14:33 (717) Thread-1 Shutdown hook entered