Exit after update

Support
1

Hello,

Today Syncthing was not running on my servers, found this in logs

2017/02/07 11:39:30 INFO: Automatic upgrade (current "v0.14.21" < latest "v0.14.22")
2017/02/07 11:39:34 WARNING: Automatically upgraded to version "v0.14.22". Restarting in 1 minute.
2017/02/07 11:40:34 INFO: Exiting

Manual start was necessary. No errors found, all seems to work as usual, no prior changes in config/network/user permissions, etc. Happened on multiple computers (one of them with manual update) Only similarity that all of them are linux.

2

How is it started/run?

3

just simple nice -n 19 ionice -c3 ./syncthing -logflags=3 inside a separate screen. I’m also not seeing a friend online who has a NAS so I will ask if it also happened there.

4

Have you set STNORESTART?

5

We’ve had the same issue, several of our PCs have fallen about 5 hours behind.

Some of them have restarted themselves without issue, some not. All running on Windows, either XP or 7, failed and successful updates seen on both.

6

Same here. Syncthing was manually started in an Screen Session.

[JCFBB] 11:09:46 INFO: Automatic upgrade (current “v0.14.21” < latest “v0.14.22”) [JCFBB] 11:09:49 WARNING: Automatically upgraded to version “v0.14.22”. Restarting in 1 minute. [JCFBB] 11:10:49 INFO: Exiting …

7

Anyone of you have the full log since it was started manually?

8

Since manual restart (broke “https” with a space so I can post it without forum telling me off for too many links):

[3OIEV] 06:13:24 INFO: syncthing v0.14.22 “Dysprosium Dragonfly” (go1.7.4 windows-386) jenkins@build.syncthing.net 2017-02-07 07:57:39 UTC [3OIEV] 06:13:24 INFO: My ID: CENSORED [3OIEV] 06:13:25 INFO: Single thread SHA256 performance is 34 MB/s using crypto/sha256 (11 MB/s using minio/sha256-simd). [3OIEV] 06:13:26 INFO: Hashing performance with weak hash is 25.47 MB/s [3OIEV] 06:13:26 INFO: Hashing performance without weak hash is 32.60 MB/s [3OIEV] 06:13:26 INFO: Archiving a copy of old config file format at: C:\Users\Administrator\AppData\Local\Syncthing\config.xml.v17 [3OIEV] 06:13:26 INFO: Weak hash disabled, as it has an unacceptable performance impact. [3OIEV] 06:14:01 INFO: Ready to synchronize “Bellingham1_Sync” (o3guy-9boly) (readwrite) [3OIEV] 06:14:04 INFO: Ready to synchronize “ArchiveFolder-1357” (vzcm2-3zo5e) (readwrite) [3OIEV] 06:14:04 INFO: Send rate is unlimited, receive rate is unlimited [3OIEV] 06:14:04 INFO: Rate limits do not apply to LAN connections [3OIEV] 06:14:04 INFO: Using discovery server ht tps://discovery-v4-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC [3OIEV] 06:14:04 INFO: Using discovery server ht tps://discovery-v4-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ [3OIEV] 06:14:04 INFO: Using discovery server ht tps://discovery-v4-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW [3OIEV] 06:14:04 INFO: Using discovery server ht tps://discovery-v6-2.syncthing.net/v2/?id=DVU36WY-H3LVZHW-E6LLFRE-YAFN5EL-HILWRYP-OC2M47J-Z4PE62Y-ADIBDQC [3OIEV] 06:14:04 INFO: Using discovery server ht tps://discovery-v6-3.syncthing.net/v2/?id=VK6HNJ3-VVMM66S-HRVWSCR-IXEHL2H-U4AQ4MW-UCPQBWX-J2L2UBK-NVZRDQZ [3OIEV] 06:14:04 INFO: Using discovery server ht tps://discovery-v6-4.syncthing.net/v2/?id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW [3OIEV] 06:14:04 INFO: TCP listener ([::]:22000) starting [3OIEV] 06:14:11 INFO: Completed initial scan (rw) of “ArchiveFolder-1357” (vzcm2-3zo5e) [3OIEV] 06:14:11 INFO: GUI and API listening on 127.0.0.1:8384 [3OIEV] 06:14:11 INFO: Access the GUI via the following URL: http://127.0.0.1:8384/ [3OIEV] 06:14:11 INFO: Device CENSORED is “PIG-PC” at [dynamic] [3OIEV] 06:14:11 INFO: Device CENSORED is “ARK055” at [dynamic] [3OIEV] 06:14:11 INFO: Cleaned away old file config.xml.v15 [3OIEV] 06:14:14 INFO: Established secure connection to CENSORED at 192.168.2.101:59924-163.172.132.71:22067 (relay-client) (TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384) [3OIEV] 06:14:14 INFO: Device CENSORED client is “syncthing v0.14.22” named “PIG-PC” [3OIEV] 06:14:16 INFO: Detected 0 NAT devices [3OIEV] 06:14:18 INFO: Connection to CENSORED closed: writing message: write tcp 192.168.2.101:59924->163.172.132.71:22067: wsasend: An existing connection was forcibly closed by the remote host. [3OIEV] 06:14:18 INFO: Established secure connection to CENSORED at 192.168.2.101:59943-217.236.109.25:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384) [3OIEV] 06:14:18 INFO: Device CENSORED client is “syncthing v0.14.22” named “PIG-PC” [3OIEV] 06:14:22 INFO: Joined relay relay://172.82.187.139:22067 [3OIEV] 06:14:25 INFO: Connected to already connected device (CENSORED) [3OIEV] 06:16:00 INFO: Completed initial scan (rw) of “Bellingham1_Sync” (o3guy-9boly)

9

no - and my log looks just like the one from @MKtimelapse, no errors

Only diff I found in config.xml are

<upgradeToPreReleases>false</upgradeToPreReleases>
<weakHashSelectionMethod>auto</weakHashSelectionMethod>

but that was expected

10

Neither of you have the first line indicating the startup of the monitor process:

jb@unu:~/s/g/s/s/test $ syncthing -home h1
[monitor] 16:56:29 INFO: Starting syncthing  <--- this one
[I6KAH] 16:56:29 INFO: syncthing v0.14.22 "Dysprosium Dragonfly" (go1.8rc3 darwin-amd64) jenkins@build.syncthing.net 2017-02-07 07:57:39 UTC
[I6KAH] 16:56:29 INFO: My ID: I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU
[I6KAH] 16:56:30 INFO: Single thread SHA256 performance is 360 MB/s using minio/sha256-simd (358 MB/s using crypto/sha256).

What does export report?

11

Should the monitor appear also when starting Syncthing manually?

12

Yes. It is the one that does the actual restart. It not running is the reason it doesn’t restart after upgrade. Question is, why is it not. Possible causes include STNORESTART being set in the environment.

13

Happy to find out, though I’m green to this software and not sure where to find export and STNORESTERT?

14

In Windows, run SET on the command line, before starting Syncthing. Are you really running Syncthing manually like this in Windows though? Not using Synctrayzor or so?

15

Currently yes. I’m following this up for our Principal Engineer at the moment, may have to ask for more detail tomorrow, in case I’m missing something.

16

I found this in my log. Seems the update to 0.14.21 broke it.

[L6TPD] 2017/01/24 10:33:56.940684 WARNING: Automatically upgraded to version "v0.14.20". Restarting in 1 minute.
[L6TPD] 2017/01/24 10:34:56.941496 INFO: Exiting
[monitor] 2017/01/24 10:34:56.949187 INFO: Restarting monitor...
[monitor] 2017/01/24 10:34:56.953673 INFO: Starting syncthing
[L6TPD] 2017/01/24 10:34:56.958835 INFO: syncthing v0.14.20 "Dysprosium Dragonfly" (go1.8rc2 linux-amd64) jenkins@build.syncthing.net 2017-01-24 08:26:45 UTC
....
[L6TPD] 2017/01/25 09:39:28.877830 INFO: Automatic upgrade (current "v0.14.20" < latest "v0.14.21")
[L6TPD] 2017/01/25 09:39:32.501977 WARNING: Automatically upgraded to version "v0.14.21". Restarting in 1 minute.
[L6TPD] 2017/01/25 09:39:57.837266 INFO: TLS handshake (BEP/tcp): EOF
[L6TPD] 2017/01/25 09:40:32.502228 INFO: Exiting
[monitor] 2017/01/25 09:40:32.515101 INFO: Restarting monitor...
[L6TPD] 2017/01/25 09:40:32.522008 INFO: syncthing v0.14.21 "Dysprosium Dragonfly" (go1.8rc2 linux-amd64) jenkins@build.syncthing.net 2017-01-25 07:33:35 UTC

I start syncthing like this in my crontab, no ST env vars set:

@reboot /path/to/syncthing -logflags=7 2>&1 >> /path/to/logfile.log

OT: For some reason, I have a massiv amount of TLS handshake (BEP/tcp): EOF in my log :frowning:

17

[monitor] INFO: Starting syncthing

I tested and I have this line. Also I have been running Syncthing like this for a long time without any problems (e.g. automatic restart on manual update click). Export does not show STNORESTART or anything Syncthing related.

18

Yep, I see the bug now. Thanks all. No more debugging needed.

2 Likes
19

I released a v0.14.23 which 1) doesn’t have this problem, 2) detects the situation so that it works when upgraded to from v0.14.21-22.

2 Likes
20

My two local devices (both on macOS 10.12) auto-updated to 0.14.22 and 0.14.23 without any issues, but my third and off-site device (on Windows 7) sadly have been offline the last 10 hours. Clearly faulty update.
Really bad timing, just when Syncthing were splitting into “Stable Releases” and “Release Candidates”… Better luck next time. :slight_smile: