MID Server down after attempted upgrade, due to file locks caused by Dell SecureWorks Red Cloak anti-virus (mid.bat, java.exe, wrapper-windows-x86-64.exe)


Description

MID Server down after attempted upgrade, due to file locks caused by Dell SecureWorks Red Cloak anti-virus. The upgrade service can fail to delete the following files, causing the upgrade service to stop, leaving the MID Server down, with a corrupt installation with missing files.

The following processes:

Can lock the following files:

Notes for confirming this PRB:

Example logs:

A New York example, although this has also been seen with upgrades to Madrid and Orlando at the time of writing:

Agent log:

04/05/20 02:52:33 (492) AutoUpgrade.3600   Installed: [mid-core.newyork-06-26-2019__patch4-hotfix4-01-14-2020_01-28-2020_1641.universal.universal.zip, mid-jre.newyork-06-26-2019__patch4-hotfix4-01-14-2020_01-28-2020_1641.windows.x86-64.zip]
04/05/20 02:52:33 (492) AutoUpgrade.3600   Assigned: [mid-core.newyork-06-26-2019__patch7-02-25-2020_03-02-2020_2243.universal.universal.zip, mid-upgrade.newyork-06-26-2019__patch7-02-25-2020_03-02-2020_2243.universal.universal.zip]
...
04/05/20 02:53:19 (813) AutoUpgrade.3600 Stopping MID server. Bootstrapping upgrade.
04/05/20 02:53:19 (813) AutoUpgrade.3600 MIDUpgrader.startUpgradeRunner(), OperationalState=UPGRADING
04/05/20 02:53:29 (839) Gobbling stdout: cmd.exe /C bin\glide-dist-upgrade.bat start Gobbled: STATUS | wrapperm | 2020/04/05 02:53:26 | Starting the ServiceNow Platform Distribution Upgrade (prod-disco-mid) service...
04/05/20 02:53:29 (842) Gobbling stdout: cmd.exe /C bin\glide-dist-upgrade.bat start Gobbled: STATUS | wrapperm | 2020/04/05 02:53:29 | ServiceNow Platform Distribution Upgrade (prod-disco-mid) service started.
04/05/20 02:53:31 (907) AutoUpgrade.3600 Added marker `C:\windows\TEMP\1586069554859-0` to upgrade marker file.
...
04/05/20 02:53:35 (738) Wrapper-Stopper Main.handleStop() after shutdown, OperationalState=UPGRADING
04/05/20 02:53:35 (762) MIDServer MID Server stopping
04/05/20 02:53:36 (029) MIDServer Stoping LDAP Listener for: cd.chdcorp.com
04/05/20 02:53:36 (305) MIDServer MID Server stopped
04/05/20 02:53:37 (514) Thread-1 Shutdown hook entered
04/05/20 02:53:37 (514) Thread-1 Stopping MID server

Wrapper log:

Confirms MID Server shut down:

2020/04/05 02:53:29 | Logger for 'glide' already configured by container. Only formatters will be adjusted:
2020/04/05 02:53:29 | Overriding formatter to: shade.distupgrade.com.glide.util.DefaultLogFormatter (for handler: java.util.logging.FileHandler)
2020/04/05 02:53:38 | <-- Wrapper Stopped

This is from the service asking the wrapper if the MID Server was shut down, which is the last log from the wrapper service, and it will have shut down the process shortly afterwards:

2020/04/05 02:53:43 | The ServiceNow MID Server_PROD_DISCO_MID Service is installed.
2020/04/05 02:53:43 |   Start Type: Automatic
2020/04/05 02:53:43 |   Interactive: No
2020/04/05 02:53:43 |   Running: No

The glide-dist-upgrade.log the upgrade service copied into the wrapper log:

In this example, the sigar-amd64-winnt.dll errors will probably be unrelated, and from the wrapper process not quite being shut down fully yet. See:
PRB1419577 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

<< UPGRADE LOG BEGIN >>
ERROR  | wrapperm | 2020/04/05 02:53:21.624 | The ServiceNow Platform Distribution Upgrade (prod-disco-mid) service is not installed - The specified service does not exist as an installed service. (0x424)
STATUS | wrapperm | 2020/04/05 02:53:24.240 | ServiceNow Platform Distribution Upgrade (prod-disco-mid) service installed.
STATUS | wrapperm | 2020/04/05 02:53:26.748 | Starting the ServiceNow Platform Distribution Upgrade (prod-disco-mid) service...
STATUS | wrapper  | 2020/04/05 02:53:26.819 | --> Wrapper Started as Service
STATUS | wrapper  | 2020/04/05 02:53:26.847 | Java Service Wrapper Standard Edition 64-bit 3.5.36
STATUS | wrapper  | 2020/04/05 02:53:26.847 |   Copyright (C) 1999-2018 Tanuki Software, Ltd. All Rights Reserved.
STATUS | wrapper  | 2020/04/05 02:53:26.847 |     http://wrapper.tanukisoftware.com
STATUS | wrapper  | 2020/04/05 02:53:26.847 |   Licensed to ServiceNow, Inc. for MID Upgrade
STATUS | wrapper  | 2020/04/05 02:53:26.847 | 
ERROR  | wrapper  | 2020/04/05 02:53:27.268 | Failed to parse the version of Java. Resolving to the lowest supported version (1.4).
STATUS | wrapper  | 2020/04/05 02:53:27.373 | Launching a JVM...
INFO   | jvm 1    | 2020/04/05 02:53:27.685 | WrapperManager: Initializing...
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | Apr 05, 2020 2:53:27 AM com.snc.dist.mid_upgrade.UpgradeMain$1 start
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | INFO: WrapperListener.start()
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | Apr 05, 2020 2:53:27 AM com.snc.dist.mid_upgrade.UpgradeMain logArguments
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | INFO: Command-line arguments: --dist-file=C:\Windows\Temp\1586069554859-0\mid-upgrade.newyork-06-26-2019__patch7-02-25-2020_03-02-2020_2243.universal.universal.zip --mode=dist-upgrade --current-dir=C:\MIDServer\agent
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | Apr 05, 2020 2:53:27 AM com.snc.dist.mid_upgrade.UpgradeMain run
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | INFO: MID Server upgrade v2.0 starting...
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | Apr 05, 2020 2:53:27 AM com.snc.dist.mid_upgrade.UpgradeMain run
INFO   | jvm 1    | 2020/04/05 02:53:27.892 | INFO: Upgrading MID `C:\MIDServer\agent` with contents from `C:\Windows\Temp\1586069554859-0\agent`.
STATUS | wrapperm | 2020/04/05 02:53:29.822 | ServiceNow Platform Distribution Upgrade (prod-disco-mid) service started.
INFO   | jvm 1    | 2020/04/05 02:53:30.922 | Apr 05, 2020 2:53:30 AM com.snc.dist.mid_upgrade.UpgradeMain missingOrCanDelete
INFO   | jvm 1    | 2020/04/05 02:53:30.922 | INFO: C:\MIDServer\agent\lib\sigar-amd64-winnt.dll cannot be deleted: C:\MIDServer\agent\lib\sigar-amd64-winnt.dll (The process cannot access the file because it is being used by another process)
INFO   | jvm 1    | 2020/04/05 02:53:30.922 | Retrying in 1000ms...
...
INFO   | jvm 1    | 2020/04/05 02:53:37.941 | Apr 05, 2020 2:53:37 AM com.snc.dist.mid_upgrade.UpgradeMain missingOrCanDelete
INFO   | jvm 1    | 2020/04/05 02:53:37.941 | INFO: C:\MIDServer\agent\lib\sigar-amd64-winnt.dll is no longer locked after 7 checks.
INFO   | jvm 1    | 2020/04/05 02:53:43.106 | Apr 05, 2020 2:53:43 AM com.snc.dist.mid_upgrade.UpgradeMarker markService
INFO   | jvm 1    | 2020/04/05 02:53:43.106 | INFO: Added service `snc-platform-dist-upgrade-prod-disco-mid` to upgrade marker file.
INFO   | jvm 1    | 2020/04/05 02:53:46.641 | Apr 05, 2020 2:53:46 AM com.snc.dist.mid_upgrade.UpgradeMain wipeDirs
INFO   | jvm 1    | 2020/04/05 02:53:46.641 | INFO: ** Debug Stale files ** TargetDirectory Path = C:\MIDServer\agent
INFO   | jvm 1    | 2020/04/05 02:53:46.641 | Apr 05, 2020 2:53:46 AM com.snc.dist.mid_upgrade.UpgradeMain wipeDirs
INFO   | jvm 1    | 2020/04/05 02:53:46.642 | INFO: ** Debug Stale files ** Files in TargetDirectory = bin conf config.xml etc EULA.pdf extlib installer.bat installer.sh jre keystore lib logs midinstaller package properties README.doc scripts ServiceNow Open Source Disclosure 062419NMS0.pdf start.bat start.sh stop.bat stop.sh work wrapper-development-license-1.3.txt wrapper-tsims-addendum-1.3.txt 
INFO   | jvm 1    | 2020/04/05 02:53:46.749 | Apr 05, 2020 2:53:46 AM com.snc.dist.mid_upgrade.UpgradeMain wipeDirs
INFO   | jvm 1    | 2020/04/05 02:53:46.749 | INFO: ** Debug Stale files ** Files from Matching pattern = EULA.pdf README.doc ServiceNow Open Source Disclosure 062419NMS0.pdf 
INFO   | jvm 1    | 2020/04/05 02:53:46.749 | Apr 05, 2020 2:53:46 AM com.snc.dist.mid_upgrade.UpgradeMain migrateToTarget
INFO   | jvm 1    | 2020/04/05 02:53:46.749 | INFO: Copying files to MID server installation path.
INFO   | jvm 1    | 2020/04/05 02:53:47.153 | Apr 05, 2020 2:53:47 AM com.snc.dist.mid_upgrade.UpgradeMain run
INFO   | jvm 1    | 2020/04/05 02:53:47.153 | SEVERE: com.snc.dist.mid_upgrade.UpgradeException: java.io.FileNotFoundException: C:\MIDServer\agent\bin\wrapper-windows-x86-64.exe (Access is denied)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 | com.snc.dist.mid_upgrade.UpgradeException: java.io.FileNotFoundException: C:\MIDServer\agent\bin\wrapper-windows-x86-64.exe (Access is denied)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at com.snc.dist.mid_upgrade.UpgradeMain.migrateToTarget(UpgradeMain.java:840)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at com.snc.dist.mid_upgrade.UpgradeMain.run(UpgradeMain.java:313)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at java.lang.Thread.run(Thread.java:748)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 | Caused by: java.io.FileNotFoundException: C:\MIDServer\agent\bin\wrapper-windows-x86-64.exe (Access is denied)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at java.io.FileOutputStream.open0(Native Method)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at java.io.FileOutputStream.open(FileOutputStream.java:270)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at java.io.FileOutputStream.<init>(FileOutputStream.java:213)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at java.io.FileOutputStream.<init>(FileOutputStream.java:162)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at org.apache.commons.io.FileUtils.doCopyFile(FileUtils.java:1142)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at org.apache.commons.io.FileUtils.doCopyDirectory(FileUtils.java:1446)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at org.apache.commons.io.FileUtils.doCopyDirectory(FileUtils.java:1444)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at org.apache.commons.io.FileUtils.copyDirectory(FileUtils.java:1388)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at org.apache.commons.io.FileUtils.copyDirectory(FileUtils.java:1317)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  at com.snc.dist.mid_upgrade.UpgradeMain.migrateToTarget(UpgradeMain.java:837)
INFO   | jvm 1    | 2020/04/05 02:53:47.153 |  ... 2 more
INFO   | jvm 1    | 2020/04/05 02:53:47.153 | 
INFO   | jvm 1    | 2020/04/05 02:53:47.153 | Apr 05, 2020 2:53:47 AM com.snc.dist.mid_upgrade.UpgradeMain appendMidLogs
INFO   | jvm 1    | 2020/04/05 02:53:47.153 | INFO: Flushing logs
<< UPGRADE LOG END >>

Steps to Reproduce

Reproduction on demand in a lab environment hasn't been possible so far, but we have seen file handles within the agent folder of customers installations during upgrades.

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.


Related Problem: PRB1429834