Repository: syncthing/syncthing (language: go)

Issue:
Relay listener does not restart sometimes
### 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:
1. Manually configure a relay server in "Sync protocol listen addresses"
2. Let the connection to the relay server drop periodically (due to inadvertent network issues)
3. Watch how the relay listener _usually_ restarts after a while, trying to reconnect
4. 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)


Discussion / hints:
Can we have a non sanitized log? At least for an hour around the last event. 
I have send the full log privately. I don't think it contains useful data though. If you can give me some pointers about which debugging facilities to enable, I could try to reproduce with more logging enabled.
Well, the `relay` one to begin with. The relay listener not restarting should be due to its context being cancelled, that is, because of a config change or because Syncthing itself is shutting down. Without any context in the logs I have no idea what's going on.

Fix patch:
diff --git a/lib/svcutil/svcutil.go b/lib/svcutil/svcutil.go
index 41dd970a103..f9d5684b009 100644
--- a/lib/svcutil/svcutil.go
+++ b/lib/svcutil/svcutil.go
@@ -122,7 +122,12 @@ func (s *service) Serve(ctx context.Context) error {
 	s.err = nil
 	s.mut.Unlock()
 
-	err := s.serve(ctx)
+	// The error returned by serve() may well be a network timeout, which as
+	// of Go 1.19 is a context.DeadlineExceeded, which Suture interprets as
+	// a signal to stop the service instead of restarting it. This typically
+	// isn't what we want, so we make sure to remove the context specific
+	// error types unless *our* context is actually cancelled.
+	err := asNonContextError(ctx, s.serve(ctx))
 
 	s.mut.Lock()
 	s.err = err
@@ -139,7 +144,6 @@ func (s *service) Error() error {
 
 func (s *service) String() string {
 	return fmt.Sprintf("Service@%p created by %v", s, s.creator)
-
 }
 
 type doneService func()
@@ -203,3 +207,19 @@ func infoEventHook(l logger.Logger) suture.EventHook {
 		}
 	}
 }
+
+// asNonContextError returns err, except if it is context.Canceled or
+// context.DeadlineExceeded in which case the error will be a simple string
+// representation instead. The given context is checked for cancellation,
+// and if it is cancelled then that error is returned instead of err.
+func asNonContextError(ctx context.Context, err error) error {
+	select {
+	case <-ctx.Done():
+		return ctx.Err()
+	default:
+	}
+	if errors.Is(err, context.Canceled) || errors.Is(err, context.DeadlineExceeded) {
+		return fmt.Errorf("%s (non-context)", err.Error())
+	}
+	return err
+}


Test patch: