Relay listener does not restart sometimes #8749
Description
Does your log mention database corruption?
No
Include required information
- Syncthing v1.23.0, Linux (64-bit Intel/AMD)
- Browser N/A
Steps to reproduce:
- Manually configure a relay server in "Sync protocol listen addresses"
- Let the connection to the relay server drop periodically (due to inadvertent network issues)
- Watch how the relay listener usually restarts after a while, trying to reconnect
- At some point, the relay listener stops restarting altogether
This didn't happen in older versions of syncthing, though I cannot exactly say which ones. In those versions, the relay listener would always restart after some period, if the relay failed. This seems to no longer be the case. Below is a sanitized log of one of my syncthing instances, recorded over the last 10 days:
Jan 04 06:02:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) starting
Jan 04 06:02:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Joined relay relay://my.own.relay:22067
Jan 04 06:02:32 Odroid-H2 syncthing[458004]: [<Self>] INFO: Established secure connection to <some-device> at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256
Jan 04 06:02:32 Odroid-H2 syncthing[458004]: [<Self>] INFO: Replacing old connection <IPs>:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 with <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 for <device>
Jan 04 06:02:32 Odroid-H2 syncthing[458004]: [<Self>] INFO: Device <some-device> client is "syncthing v1.22.2" named "my.device" at [2003:f1:1f07:a400:fd4d:a411:d86a:4122]:45450-[2a01:4f8:151:506c::2]:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256
Jan 04 06:02:32 Odroid-H2 syncthing[458004]: [<Self>] INFO: Replacing old connection <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 with <IPs>:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 for <some-device>
Jan 04 06:02:32 Odroid-H2 syncthing[458004]: [<Self>] INFO: Connection to <some-device> at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 closed: replacing connection
Jan 05 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) shutting down
Jan 05 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: listenerSupervisor@relay://my.own.relay:22067/?id=<ID>: service relay://my.own.relay:22067/?id=<ID> failed: timed out
Jan 05 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) starting
Jan 05 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Joined relay relay://my.own.relay:22067
Jan 06 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) shutting down
Jan 06 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: listenerSupervisor@relay://my.own.relay:22067/?id=<ID>: service relay://my.own.relay:22067/?id=<ID> failed: timed out
Jan 06 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) starting
Jan 06 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Joined relay relay://my.own.relay:22067
Jan 06 06:00:58 Odroid-H2 syncthing[458004]: [<Self>] INFO: Established secure connection to <some-device> at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256
Jan 06 06:00:58 Odroid-H2 syncthing[458004]: [<Self>] INFO: Replacing old connection <IPs>:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 with <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 for <some-device>
Jan 06 06:00:58 Odroid-H2 syncthing[458004]: [<Self>] INFO: Device <some-device> client is "syncthing v1.23.0" named "my.device" at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256
Jan 06 06:01:38 Odroid-H2 syncthing[458004]: [<Self>] INFO: Replacing old connection <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 with <IPs>:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 for <some-device>
Jan 06 06:01:38 Odroid-H2 syncthing[458004]: [<Self>] INFO: Connection to <some-device> at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 closed: replacing connection
Jan 07 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) shutting down
Jan 07 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: listenerSupervisor@relay://my.own.relay:22067/?id=<ID>: service relay://my.own.relay:22067/?id=<ID> failed: timed out
Jan 07 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) starting
Jan 07 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Joined relay relay://my.own.relay:22067
Jan 08 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) shutting down
Jan 08 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: listenerSupervisor@relay://my.own.relay:22067/?id=<ID>: service relay://my.own.relay:22067/?id=<ID> failed: timed out
Jan 08 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) starting
Jan 08 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Joined relay relay://my.own.relay:22067
Jan 09 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) shutting down
Jan 09 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: listenerSupervisor@relay://my.own.relay:22067/?id=<ID>: service relay://my.own.relay:22067/?id=<ID> failed: timed out
Jan 09 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) starting
Jan 09 05:57:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Joined relay relay://my.own.relay:22067
Jan 09 06:01:24 Odroid-H2 syncthing[458004]: [<Self>] INFO: Established secure connection to <some-device> at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256
Jan 09 06:01:24 Odroid-H2 syncthing[458004]: [<Self>] INFO: Replacing old connection <IPs>:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 with <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 for <some-device>
Jan 09 06:01:24 Odroid-H2 syncthing[458004]: [<Self>] INFO: Device <some-device> client is "syncthing v1.23.0" named "my.device" at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256
Jan 09 06:02:05 Odroid-H2 syncthing[458004]: [<Self>] INFO: Replacing old connection <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 with <IPs>:22000/tcp-client/TLS1.3-TLS_AES_128_GCM_SHA256 for <some-device>
Jan 09 06:02:05 Odroid-H2 syncthing[458004]: [<Self>] INFO: Connection to <some-device> at <IPs>:22067/relay-server/TLS1.3-TLS_AES_128_GCM_SHA256 closed: replacing connection
Jan 09 20:18:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) shutting down
Jan 09 20:18:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: listenerSupervisor@relay://my.own.relay:22067/?id=<ID>: service relay://my.own.relay:22067/?id=<ID> failed: timed out
Jan 09 20:18:15 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) starting
Jan 09 20:18:25 Odroid-H2 syncthing[458004]: [<Self>] INFO: Relay listener (relay://my.own.relay:22067/?id=<ID>) shutting down
Pay special attention to the dates: The relay listener last failed on Jan 9th, tried to restart - which apparently failed - and then never restarted. It's been over 5 days now, and the relay listener hasn't yet attempted at a restart (at least no log line mentioning the word "relay" has been printed at all).
As you can see from the logs, the relay does fail from time to time - this is (probably) due to a slightly unreliable network connection, nothing I can do about that. I understand if there's an exponential backoff implemented somewhere, but 5+ days without a reconnection attempt is a bit excessive I think.
In the advanced configuration, my
Relay Reconnect Interval (minutes) / relayReconnectIntervalM is set to 10. I do not recall changing this, but I don't know what the default value is.
(Of course, restarting syncthing fixes this issue immediatly, but it's not ideal)