Auto-update failure -> syncthing binary gone

[scienmind]

Following up a brief discussion over IRC:
Few days ago one of my ST nodes suddenly reverted to v0.13 from v0.14.3.

According to the logs, during the auto-update procedure, syncthing binary (syncthing.exe) disappeared from this world, and then upon restart of the OS was reverted to the 0.13 binary shipped with the wrapper (SyncTrayzor):

 ...
 [IDIDID] 19:33:39 INFO: Device IDIDIDID-01 folder "FOLDER-26" has a new index ID (0xCA2C14FFB8F66F0A)
 [IDIDID] 19:33:39 INFO: Device IDIDIDID-01 folder "FOLDER-12" has a new index ID (0x8EA614B817094139)
 [IDIDID] 19:33:39 INFO: Automatic upgrade (current "v0.14.3" < latest "v0.14.4")
 [IDIDID] 19:33:54 WARNING: Automatic upgrade: rename C:\Users\USER-01\AppData\Roaming\SyncTrayzor\syncthing844288339 C:\Users\USER-01\AppData\Roaming\SyncTrayzor\syncthing.exe: The process cannot access the file because it is being used by another process.
 [IDIDID] 19:33:59 INFO: Established secure connection to IDIDIDID-05 at LOCAL-IPv4-01.13:54604-91.121.160.153:22067 (Relay (Client))
 [IDIDID] 19:33:59 INFO: Device IDIDIDID-05 client is "syncthing v0.14.4" named "DEVICE-05"
 [IDIDID] 19:33:59 INFO: Connected to device IDIDIDID-05 with a newer version (current "v0.14.3" < remote "v0.14.4"). Checking for upgrades.
 [IDIDID] 19:34:00 INFO: Device IDIDIDID-05 folder "FOLDER-17" has a new index ID (0xF578543A56D85C50)
 [IDIDID] 19:34:00 INFO: Device IDIDIDID-05 folder "FOLDER-28" has a new index ID (0x853993BEA1E882B9)
 [IDIDID] 19:34:01 INFO: Automatic upgrade (current "v0.14.3" < latest "v0.14.4")
 [IDIDID] 19:34:06 INFO: Established secure connection to IDIDIDID-08 at LOCAL-IPv4-01.13:54619-78.46.45.123:22067 (Relay (Client))
 [IDIDID] 19:34:06 INFO: Device IDIDIDID-08 client is "syncthing v0.14.4" named "DEVICE-08"
 [IDIDID] 19:34:07 INFO: Device IDIDIDID-08 folder "FOLDER-12" has a new index ID (0x7DD4C1C6E2890737)
 ...
 [IDIDID] 19:34:25 INFO: Device IDIDIDID-08 folder "FOLDER-32" has a new index ID (0xCEBB3A9C0672FBBD)
 [IDIDID] 19:34:26 WARNING: Automatic upgrade: rename C:\Users\USER-01\AppData\Roaming\SyncTrayzor\syncthing.exe C:\Users\USER-01\AppData\Roaming\SyncTrayzor\syncthing.exe.old: The system cannot find the file specified.
 [IDIDID] 19:34:26 INFO: Connected to device IDIDIDID-08 with a newer version (current "v0.14.3" < remote "v0.14.4"). Checking for upgrades.
 [IDIDID] 19:34:27 INFO: Automatic upgrade (current "v0.14.3" < latest "v0.14.4")
 [IDIDID] 19:34:27 INFO: Device IDIDIDID-08 folder "FOLDER-27" has a new index ID (0x21478973CE9A9B35)
 ...
 [IDIDID] 19:34:37 INFO: Device IDIDIDID-08 folder "FOLDER-14" has a new index ID (0x5C81B96863E500DF)
 [IDIDID] 19:34:40 WARNING: Automatic upgrade: rename C:\Users\USER-01\AppData\Roaming\SyncTrayzor\syncthing.exe C:\Users\USER-01\AppData\Roaming\SyncTrayzor\syncthing.exe.old: The system cannot find the file specified.
 [IDIDID] 19:34:51 INFO: Device IDIDIDID-08 folder "FOLDER-09" has a new index ID (0xE4C0F8E536E7C3D1)
 [IDIDID] 19:36:02 INFO: Shutting down
 [IDIDID] 19:36:02 INFO: Exiting
 [IDIDID] 23:00:16 INFO: syncthing v0.13.10 "Copper Cockroach" (go1.6.2 windows-amd64) WIN-P6RP886TVDJ\Administrator@WIN-P6RP886TVDJ 2016-07-03 11:29:32 UTC
 [IDIDID] 23:00:16 INFO: My ID: IDIDIDID-12
 [IDIDID] 23:00:17 INFO: Single thread hash performance is ~39 MB/s
 [IDIDID] 23:00:31 INFO: Ready to synchronize FOLDER-01 (readwrite)
 [IDIDID] 23:00:32 INFO: Ready to synchronize FOLDER-13 (readwrite)
 [IDIDID] 23:00:36 INFO: Ready to synchronize FOLDER-19 (readwrite)
 ...

Moreover, turns out its not "one time thing" (!). I noticed that another node on the cluster was stuck on v0.14.3 about a day after every other node was auto-upgraded to v0.14.4
I suspected that the same might have happened there. And surely that was the case. This node was running standalone syncthing instance governed by NSSM, no wrapper. And once the PC was restarted, syncthing was dead there for good. No binary. No wrapper to resurrect it.

Inspecting ST's folder on that machine revealed a fat list of temporary binaries (all are bit-wise copies of 0.14.4):

Logs are similar to the first machine:

 ...
 [IDIDID] 19:10:36 INFO: Device IDIDIDID-08 folder "FOLDER-48" has a new index ID (0xF09B1B83A25B09E5)
 [IDIDID] 19:10:47 WARNING: Automatic upgrade: rename C:\Program Files\Syncthing-Service\Service\syncthing767851213 C:\Program Files\Syncthing-Service\Service\syncthing.exe: The process cannot access the file because it is being used by another process.
 [IDIDID] 19:11:28 INFO: Connection to IDIDIDID-08 closed: switching connections
 [IDIDID] 19:11:28 INFO: Established secure connection to IDIDIDID-08 at LOCAL-IPv4-01.3:22000-LOCAL-IPv4-01.2:58038 (TCP (Server))
 [IDIDID] 19:11:28 INFO: Device IDIDIDID-08 client is "syncthing v0.14.4" named "DEVICE-08"
 [IDIDID] 19:11:28 INFO: Connected to device IDIDIDID-08 with a newer version (current "v0.14.3" < remote "v0.14.4"). Checking for upgrades.
 [IDIDID] 19:11:28 INFO: Connection to IDIDIDID-08 closed: writing message: write tcp LOCAL-IPv4-01.3:63354->93.180.156.234:22067: use of closed network connection
 [IDIDID] 19:11:28 INFO: Connection to IDIDIDID-08 closed: reading length: read tcp LOCAL-IPv4-01.3:22000->LOCAL-IPv4-01.2:58038: use of closed network connection
 [IDIDID] 19:11:29 INFO: Automatic upgrade (current "v0.14.3" < latest "v0.14.4")
 [IDIDID] 19:11:37 WARNING: Automatic upgrade: rename C:\Program Files\Syncthing-Service\Service\syncthing.exe C:\Program Files\Syncthing-Service\Service\syncthing.exe.old: The system cannot find the file specified.
 [IDIDID] 19:11:56 INFO: Established secure connection to IDIDIDID-08 at LOCAL-IPv4-01.3:22000-LOCAL-IPv4-01.2:58101 (TCP (Server))
 [IDIDID] 19:11:56 INFO: Device IDIDIDID-08 client is "syncthing v0.14.4" named "DEVICE-08"
 [IDIDID] 19:11:56 INFO: Connected to device IDIDIDID-08 with a newer version (current "v0.14.3" < remote "v0.14.4"). Checking for upgrades.
 [IDIDID] 19:11:56 INFO: Device IDIDIDID-08 folder "FOLDER-36" is delta index compatible (mlv=32259)
 ...
 [IDIDID] 12:03:27 INFO: Device IDIDIDID-07 folder "FOLDER-23" is delta index compatible (mlv=1595)
 [IDIDID] 12:09:09 INFO: Established secure connection to IDIDIDID-12 at LOCAL-IPv4-01.3:61254-93.180.156.234:22067 (Relay (Server))
 [IDIDID] 12:09:09 INFO: Device IDIDIDID-12 client is "syncthing v0.14.4" named "DEVICE-12"
 [IDIDID] 12:09:09 INFO: Connected to device IDIDIDID-12 with a newer version (current "v0.14.3" < remote "v0.14.4"). Checking for upgrades.
 [IDIDID] 12:09:09 INFO: Device IDIDIDID-12 folder "FOLDER-29" is delta index compatible (mlv=32263)
 [IDIDID] 12:09:09 INFO: Device IDIDIDID-12 folder "FOLDER-18" is delta index compatible (mlv=35)
 [IDIDID] 12:09:09 INFO: Device IDIDIDID-12 folder "FOLDER-25" is delta index compatible (mlv=35518)
 [IDIDID] 12:09:10 INFO: Automatic upgrade (current "v0.14.3" < latest "v0.14.4")
 [IDIDID] 12:09:17 WARNING: Automatic upgrade: rename C:\Program Files\Syncthing-Service\Service\syncthing.exe C:\Program Files\Syncthing-Service\Service\syncthing.exe.old: The system cannot find the file specified.
 [IDIDID] 12:10:57 INFO: Connection to IDIDIDID-07 closed: read timeout
 [IDIDID] 12:11:33 INFO: Established secure connection to IDIDIDID-07 at [IPv6-05%Ethernet]:61304-[IPv6-09%Ethernet]:22000 (TCP (Client))
 [IDIDID] 12:11:33 INFO: Device IDIDIDID-07 client is "syncthing v0.14.3" named "DEVICE-07"
 [IDIDID] 12:11:33 INFO: Device IDIDIDID-07 folder "FOLDER-39" is delta index compatible (mlv=29)
 ...

TL;DR: Seems like for some reason renaming of the updated binary from temp to .exe failed (maybe due to security software scan, or whatever...), but the original ST binary was already wiped (or renamed to .old. And thus node is effectively dead on next boot.

Syncthing should handle binary switching more fail-safe: verify valid access to the new binary before removing the old one, and/or revert back to old one if the new one can't be used.
Either way, avoid "floating on the air (RAM)" as much as possible.

Version Information

Syncthing Version: v0.14.3
OS Version: Windows 10