Problem with Private Relay Server

Thomas_1 · May 4, 2021, 2:50pm

Hi, i have a problem getting Syncthing working via a relay server. i want to only use the private relay. We have host A and Host B and a relay server in the middle.

Host A has as Listen Address:

relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= global and local discovery is off

Host B has the same configuration

I can add Host A as Remote Device on Host B on Addresses i enter the same relayserver

relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=

On Host A i accept the connection and enter the relay server also here. Booth are now connected via the gateway.

The problem is, that they are getting disconnected, connected, disconnected and so on. From the logfiles, I cannot see a reason for the disconnect. Only some EOF and timeout. It is no firewall issue. Also the connection is stable. Netstat shows still established and ping to the relay is also responding. Here the Logfiles

Host A

[T5K77] 2021/05/04 14:00:32.277987 static.go:68: INFO: Joined relay relay://IP_of_RelayServer:22067
[T5K77] 2021/05/04 14:00:32.444966 service.go:340: INFO: Established secure connection to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT at 172.16.202.50:61872-IP_of_RelayServer:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/04 14:00:32.444966 model.go:2262: INFO: Device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT client is "syncthing v1.16.0" named "s7654321wks1" at 172.16.202.50:61872-IP_of_RelayServer:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/04 14:02:32.279890 static.go:121: DEBUG: StaticClient:0xc0001ec850@relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= timed out
[T5K77] 2021/05/04 14:02:32.279890 static.go:122: INFO: Disconnected from relay relay://IP_of_RelayServer:22067
[T5K77] 2021/05/04 14:02:32.279890 static.go:183: DEBUG: StaticClient:0xc0001ec850@relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= disconnecting
[T5K77] 2021/05/04 14:02:32.279890 relay_listen.go:71: INFO: Listen (BEP/relay): timed out
[T5K77] 2021/05/04 14:02:32.279890 relay_listen.go:73: INFO: Relay listener (relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=) shutting down
[T5K77] 2021/05/04 14:02:32.279890 svcutil.go:163: INFO: c.S.listenerSupervisor: Failed service 'relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=' (1.000000 failures of 2.000000), restarting: true, error: %!s(<nil>)
[T5K77] 2021/05/04 14:02:32.279890 relay_listen.go:62: INFO: Relay listener (relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=) starting
[T5K77] 2021/05/04 14:02:32.283795 model.go:1772: INFO: Connection to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT at 172.16.202.50:61872-IP_of_RelayServer:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: reading length: EOF
[T5K77] 2021/05/04 14:02:32.355794 static.go:55: DEBUG: StaticClient:0xc000244000@relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= connected IP_of_RelayServer:22067
[T5K77] 2021/05/04 14:02:32.387798 static.go:68: INFO: Joined relay relay://IP_of_RelayServer:22067

Host B

[WGSUV] 15:00:28 INFO: Joined relay relay://IP_of_RelayServer:22067
[WGSUV] 15:00:32 INFO: Established secure connection to T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM at 172.16.202.222:59193-IP_of_RelayServer:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[WGSUV] 15:00:32 INFO: Device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM client is "syncthing v1.16.0" named "s7654321hv1" at 172.16.202.222:59193-IP_of_RelayServer:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[WGSUV] 15:02:32 INFO: Disconnected from relay relay://IP_of_RelayServer:22067
[WGSUV] 15:02:32 INFO: Listen (BEP/relay): timed out
[WGSUV] 15:02:32 INFO: Relay listener (relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=) shutting down
[WGSUV] 15:02:32 INFO: c.S.listenerSupervisor: Failed service 'relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=' (1.000000 failures of 2.000000), restarting: true, error: %!s(<nil>)
[WGSUV] 15:02:32 INFO: Relay listener (relay://IP_of_RelayServer:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=) starting
[WGSUV] 15:02:32 INFO: Connection to T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM at 172.16.202.222:59193-IP_of_RelayServer:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: reading length: EOF
[WGSUV] 15:02:32 INFO: Joined relay relay://IP_of_RelayServer:22067

Relay Server:

2021/05/04 14:00:31 listener.go:48: Listener accepted connection from 31.18.14.118:61872 tls false
2021/05/04 14:00:31 listener.go:311: 31.18.14.118:61872 session lookup <679a8/8f2f5> 679a8
2021/05/04 14:00:31 session.go:120: New connection for <679a8/8f2f5> from 31.18.14.118:61872
2021/05/04 14:00:31 listener.go:48: Listener accepted connection from 31.18.14.118:59193 tls false
2021/05/04 14:00:31 listener.go:311: 31.18.14.118:59193 session lookup <679a8/8f2f5> 8f2f5
2021/05/04 14:00:31 session.go:120: New connection for <679a8/8f2f5> from 31.18.14.118:59193
2021/05/04 14:00:31 session.go:152: Session <679a8/8f2f5> starting between 31.18.14.118:61872 and 31.18.14.118:59193
2021/05/04 14:00:31 session.go:251: Proxy 31.18.14.118:59193 -> 31.18.14.118:61872
2021/05/04 14:00:31 session.go:251: Proxy 31.18.14.118:61872 -> 31.18.14.118:59193
2021/05/04 14:00:31 session.go:268: 255 bytes from 31.18.14.118:61872 to 31.18.14.118:59193
2021/05/04 14:00:31 session.go:268: 1012 bytes from 31.18.14.118:59193 to 31.18.14.118:61872
2021/05/04 14:00:31 session.go:268: 777 bytes from 31.18.14.118:61872 to 31.18.14.118:59193
2021/05/04 14:00:31 session.go:268: 62 bytes from 31.18.14.118:59193 to 31.18.14.118:61872
2021/05/04 14:00:31 session.go:268: 61 bytes from 31.18.14.118:61872 to 31.18.14.118:59193
2021/05/04 14:00:31 session.go:268: 28 bytes from 31.18.14.118:59193 to 31.18.14.118:61872
2021/05/04 14:00:31 session.go:268: 28 bytes from 31.18.14.118:61872 to 31.18.14.118:59193
2021/05/04 14:01:16 session.go:268: 30 bytes from 31.18.14.118:61872 to 31.18.14.118:59193
2021/05/04 14:01:16 session.go:268: 30 bytes from 31.18.14.118:59193 to 31.18.14.118:61872
2021/05/04 14:02:01 session.go:268: 30 bytes from 31.18.14.118:59193 to 31.18.14.118:61872
2021/05/04 14:02:31 listener.go:223: Closing connection WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT: EOF
2021/05/04 14:02:31 session.go:82: Dropping session <679a8/8f2f5> involving WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/04 14:02:31 session.go:177: Session <679a8/8f2f5> ended, outcomes: read tcp IP_of_RelayServer:22067->31.18.14.118:61872: use of closed network connection and read tcp IP_of_RelayServer:22067->31.18.14.118:59193: use of closed network connection
2021/05/04 14:02:31 session.go:213: Session <679a8/8f2f5> stopping
2021/05/04 14:02:31 listener.go:223: Closing connection T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM: EOF

Any Idea where to look at regarding the disconnects?

AudriusButkevicius · May 4, 2021, 7:28pm

This doesn’t seem to have the full log, as I can’t see any messages about invitations etc, so this doesn’t paint the whole picture.

Suggest you try the following:

On A, set listen address to 127.0.0.1:22000
On A, set B’s address to the relay
On B, set listen address to the relay.

It’s not clear why, but it seems the relay does not send a response to the invitation request/pings. Possible it’s due to firewall I guess.

Thomas_1 · May 5, 2021, 7:49am

Hi Audrius, i have now removed the relay from the listen address on A.

Here the full logs. x.x.x.x = IP of the relay server.

Host A

[start] 2021/05/05 07:20:59.232290 main.go:571: INFO: syncthing v1.16.0 "Fermium Flea" (go1.16.3 windows-amd64) teamcity@build.syncthing.net 2021-04-26 13:38:08 UTC
[T5K77] 2021/05/05 07:20:59.490295 syncthing.go:153: INFO: My ID: T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM
[T5K77] 2021/05/05 07:21:00.392296 sha256.go:88: INFO: Single thread SHA256 performance is 446 MB/s using minio/sha256-simd (358 MB/s using crypto/sha256).
[T5K77] 2021/05/05 07:21:00.849294 syncthing.go:185: INFO: Hashing performance is 374.20 MB/s
[T5K77] 2021/05/05 07:21:00.849294 limiter.go:167: INFO: Overall send rate is unlimited, receive rate is unlimited
[T5K77] 2021/05/05 07:21:00.849294 service.go:643: DEBUG: Starting listener tcp4://:22000
[T5K77] 2021/05/05 07:21:00.850290 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:21:00.850290 service.go:364: DEBUG: Connection loop in initial rampup
[T5K77] 2021/05/05 07:21:00.850290 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:21:00.850290 structs.go:241: DEBUG: dialing WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= prio 200
[T5K77] 2021/05/05 07:21:00.853290 tcp_listen.go:70: INFO: TCP listener (0.0.0.0:22000) starting
[T5K77] 2021/05/05 07:21:00.854290 api.go:382: INFO: GUI and API listening on 127.0.0.1:8384
[T5K77] 2021/05/05 07:21:00.854290 api.go:383: INFO: Access the GUI via the following URL: http://127.0.0.1:8384/
[T5K77] 2021/05/05 07:21:00.854290 syncthing.go:307: INFO: My name is "s7654321hv1"
[T5K77] 2021/05/05 07:21:00.854290 syncthing.go:310: INFO: Device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT is "s7654321wks1" at [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:21:01.055307 methods.go:66: DEBUG: Received invitation WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT@x.x.x.x:22067 via 172.16.202.50:55304
[T5K77] 2021/05/05 07:21:01.132295 relay_dial.go:50: DEBUG: Dial (BEP/relay): setting traffic class: not implemented on windows/amd64
[T5K77] 2021/05/05 07:21:01.237728 service.go:967: DEBUG: dialing WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= success: 172.16.202.50:55305-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/05 07:21:01.237728 service.go:985: DEBUG: connected to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT 200 using 172.16.202.50:55305-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 200
[T5K77] 2021/05/05 07:21:01.237728 service.go:392: DEBUG: Next connection loop in 5s
[T5K77] 2021/05/05 07:21:01.237728 service.go:988: DEBUG: discarding 0 connections while connecting to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT 200
[T5K77] 2021/05/05 07:21:01.343762 service.go:340: INFO: Established secure connection to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT at 172.16.202.50:55305-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/05 07:21:01.343762 model.go:2262: INFO: Device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT client is "syncthing v1.16.0" named "s7654321wks1" at 172.16.202.50:55305-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/05 07:21:06.238463 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:21:06.238463 service.go:364: DEBUG: Connection loop in initial rampup
[T5K77] 2021/05/05 07:21:06.238463 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:21:06.238463 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[T5K77] 2021/05/05 07:21:06.238463 service.go:392: DEBUG: Next connection loop in 5s
[T5K77] 2021/05/05 07:21:11.238846 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:21:11.238846 service.go:364: DEBUG: Connection loop in initial rampup
[T5K77] 2021/05/05 07:21:11.238846 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:21:11.238846 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[T5K77] 2021/05/05 07:21:11.238846 service.go:392: DEBUG: Next connection loop in 5s
[T5K77] 2021/05/05 07:21:16.239515 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:21:16.239515 service.go:364: DEBUG: Connection loop in initial rampup
[T5K77] 2021/05/05 07:21:16.239515 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:21:16.239515 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[T5K77] 2021/05/05 07:21:16.239515 service.go:392: DEBUG: Next connection loop in 8s
[T5K77] 2021/05/05 07:21:24.240645 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:21:24.240645 service.go:364: DEBUG: Connection loop in initial rampup
[T5K77] 2021/05/05 07:21:24.240645 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:21:24.240645 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[T5K77] 2021/05/05 07:21:24.240645 service.go:392: DEBUG: Next connection loop in 16s
[T5K77] 2021/05/05 07:21:40.240994 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:21:40.240994 service.go:364: DEBUG: Connection loop in initial rampup
[T5K77] 2021/05/05 07:21:40.240994 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:21:40.240994 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[T5K77] 2021/05/05 07:21:40.240994 service.go:392: DEBUG: Next connection loop in 32s
[T5K77] 2021/05/05 07:22:12.241416 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:22:12.241416 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:22:12.241416 service.go:504: DEBUG: Not dialing WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT via relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= as it's not time yet
[T5K77] 2021/05/05 07:22:12.241416 service.go:392: DEBUG: Next connection loop in 27.9994413s
[T5K77] 2021/05/05 07:22:40.241437 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:22:40.241437 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:22:40.241437 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[T5K77] 2021/05/05 07:22:40.241437 service.go:392: DEBUG: Next connection loop in 1m0s
[T5K77] 2021/05/05 07:23:01.114700 model.go:1772: INFO: Connection to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT at 172.16.202.50:55305-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: reading length: EOF
[T5K77] 2021/05/05 07:23:40.242654 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:23:40.242654 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:23:40.242654 structs.go:241: DEBUG: dialing WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= prio 200
[T5K77] 2021/05/05 07:23:40.385515 methods.go:66: DEBUG: Received invitation WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT@x.x.x.x:22067 via 172.16.202.50:55322
[T5K77] 2021/05/05 07:23:40.442541 relay_dial.go:50: DEBUG: Dial (BEP/relay): setting traffic class: not implemented on windows/amd64
[T5K77] 2021/05/05 07:23:40.558504 service.go:967: DEBUG: dialing WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= success: 172.16.202.50:55323-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/05 07:23:40.558504 service.go:985: DEBUG: connected to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT 200 using 172.16.202.50:55323-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 200
[T5K77] 2021/05/05 07:23:40.558504 service.go:392: DEBUG: Next connection loop in 1m0s
[T5K77] 2021/05/05 07:23:40.559494 service.go:988: DEBUG: discarding 0 connections while connecting to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT 200
[T5K77] 2021/05/05 07:23:40.630066 service.go:340: INFO: Established secure connection to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT at 172.16.202.50:55323-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/05 07:23:40.630066 model.go:2262: INFO: Device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT client is "syncthing v1.16.0" named "s7654321wks1" at 172.16.202.50:55323-x.x.x.x:22067/relay-client/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[T5K77] 2021/05/05 07:24:40.560211 service.go:362: DEBUG: Connection loop
[T5K77] 2021/05/05 07:24:40.560211 service.go:495: DEBUG: Resolved device WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[T5K77] 2021/05/05 07:24:40.560211 service.go:504: DEBUG: Not dialing WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT via relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= as it's not time yet
[T5K77] 2021/05/05 07:24:40.560211 service.go:392: DEBUG: Next connection loop in 1m0s

Host B

[start] 2021/05/05 07:20:57.124487 main.go:571: INFO: syncthing v1.16.0 "Fermium Flea" (go1.16.3 windows-amd64) teamcity@build.syncthing.net 2021-04-26 13:38:08 UTC
[start] 2021/05/05 07:20:57.178874 upgrade_supported.go:93: INFO: Couldn't fetch release information: Get "": unsupported protocol scheme ""
[start] 2021/05/05 07:20:57.178874 main.go:641: INFO: Initial automatic upgrade: no version to select
[WGSUV] 2021/05/05 07:20:57.178874 syncthing.go:153: INFO: My ID: WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
[WGSUV] 2021/05/05 07:20:58.080862 sha256.go:88: INFO: Single thread SHA256 performance is 462 MB/s using minio/sha256-simd (411 MB/s using crypto/sha256).
[WGSUV] 2021/05/05 07:20:58.552856 syncthing.go:185: INFO: Hashing performance is 346.15 MB/s
[WGSUV] 2021/05/05 07:20:58.552856 limiter.go:167: INFO: Overall send rate is unlimited, receive rate is unlimited
[WGSUV] 2021/05/05 07:20:58.552856 service.go:643: DEBUG: Starting listener relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=
[WGSUV] 2021/05/05 07:20:58.553857 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:20:58.553857 service.go:364: DEBUG: Connection loop in initial rampup
[WGSUV] 2021/05/05 07:20:58.553857 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:20:58.553857 relay_listen.go:62: INFO: Relay listener (relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=) starting
[WGSUV] 2021/05/05 07:20:58.557857 structs.go:241: DEBUG: dialing T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= prio 200
[WGSUV] 2021/05/05 07:20:58.579289 api.go:382: INFO: GUI and API listening on [::]:8384
[WGSUV] 2021/05/05 07:20:58.579289 api.go:383: INFO: Access the GUI via the following URL: http://127.0.0.1:8384/
[WGSUV] 2021/05/05 07:20:58.579289 syncthing.go:307: INFO: My name is "s7654321wks1"
[WGSUV] 2021/05/05 07:20:58.579289 syncthing.go:310: INFO: Device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM is "DubaiHV1" at [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:20:58.856284 static.go:55: DEBUG: StaticClient:0xc0003f6850@relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy= connected x.x.x.x:22067
[WGSUV] 2021/05/05 07:20:59.310278 static.go:68: INFO: Joined relay relay://x.x.x.x:22067
[WGSUV] 2021/05/05 07:20:59.310278 service.go:965: DEBUG: dialing T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= error: incorrect response code 1: not found
[WGSUV] 2021/05/05 07:20:59.310278 service.go:996: DEBUG: failed to connect to T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM 200
[WGSUV] 2021/05/05 07:20:59.310278 service.go:392: DEBUG: Next connection loop in 5s
[WGSUV] 2021/05/05 07:20:59.457299 upgrade_supported.go:93: INFO: Couldn't fetch release information: Get "": unsupported protocol scheme ""
[WGSUV] 2021/05/05 07:21:01.047748 static.go:86: DEBUG: StaticClient:0xc0003f6850@relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy= received message protocol.SessionInvitation
[WGSUV] 2021/05/05 07:21:01.122074 relay_listen.go:91: DEBUG: Listen (BEP/relay): setting traffic class: not implemented on windows/amd64
[WGSUV] 2021/05/05 07:21:01.375463 service.go:340: INFO: Established secure connection to T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM at 172.16.202.222:63405-x.x.x.x:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[WGSUV] 2021/05/05 07:21:01.375463 model.go:2262: INFO: Device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM client is "syncthing v1.16.0" named "s7654321hv1" at 172.16.202.222:63405-x.x.x.x:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[WGSUV] 2021/05/05 07:21:04.317102 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:21:04.317102 service.go:364: DEBUG: Connection loop in initial rampup
[WGSUV] 2021/05/05 07:21:04.317102 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:21:04.317102 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[WGSUV] 2021/05/05 07:21:04.317102 service.go:392: DEBUG: Next connection loop in 5s
[WGSUV] 2021/05/05 07:21:09.324694 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:21:09.324694 service.go:364: DEBUG: Connection loop in initial rampup
[WGSUV] 2021/05/05 07:21:09.324694 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:21:09.324694 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[WGSUV] 2021/05/05 07:21:09.324694 service.go:392: DEBUG: Next connection loop in 5s
[WGSUV] 2021/05/05 07:21:14.327627 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:21:14.327627 service.go:364: DEBUG: Connection loop in initial rampup
[WGSUV] 2021/05/05 07:21:14.327627 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:21:14.327627 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[WGSUV] 2021/05/05 07:21:14.327627 service.go:392: DEBUG: Next connection loop in 8s
[WGSUV] 2021/05/05 07:21:22.342950 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:21:22.342950 service.go:364: DEBUG: Connection loop in initial rampup
[WGSUV] 2021/05/05 07:21:22.342950 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:21:22.342950 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[WGSUV] 2021/05/05 07:21:22.342950 service.go:392: DEBUG: Next connection loop in 16s
[WGSUV] 2021/05/05 07:21:38.349360 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:21:38.349360 service.go:364: DEBUG: Connection loop in initial rampup
[WGSUV] 2021/05/05 07:21:38.349360 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:21:38.349360 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[WGSUV] 2021/05/05 07:21:38.349360 service.go:392: DEBUG: Next connection loop in 32s
[WGSUV] 2021/05/05 07:22:10.352094 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:22:10.352094 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:22:10.352094 service.go:504: DEBUG: Not dialing T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM via relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= as it's not time yet
[WGSUV] 2021/05/05 07:22:10.352094 service.go:392: DEBUG: Next connection loop in 27.9975252s
[WGSUV] 2021/05/05 07:22:38.368265 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:22:38.368265 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:22:38.368265 service.go:541: DEBUG: Not dialing using Relay Dialer as priority is not better than current connection (200 >= 200)
[WGSUV] 2021/05/05 07:22:38.368265 service.go:392: DEBUG: Next connection loop in 1m0s
[WGSUV] 2021/05/05 07:23:01.062695 static.go:121: DEBUG: StaticClient:0xc0003f6850@relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy= timed out
[WGSUV] 2021/05/05 07:23:01.062695 static.go:122: INFO: Disconnected from relay relay://x.x.x.x:22067
[WGSUV] 2021/05/05 07:23:01.062695 static.go:183: DEBUG: StaticClient:0xc0003f6850@relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy= disconnecting
[WGSUV] 2021/05/05 07:23:01.062695 relay_listen.go:71: INFO: Listen (BEP/relay): timed out
[WGSUV] 2021/05/05 07:23:01.062695 relay_listen.go:73: INFO: Relay listener (relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=) shutting down
[WGSUV] 2021/05/05 07:23:01.063709 svcutil.go:163: INFO: c.S.listenerSupervisor: Failed service 'relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=' (1.000000 failures of 2.000000), restarting: true, error: %!s(<nil>)
[WGSUV] 2021/05/05 07:23:01.063709 relay_listen.go:62: INFO: Relay listener (relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy=) starting
[WGSUV] 2021/05/05 07:23:01.105747 model.go:1772: INFO: Connection to T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM at 172.16.202.222:63405-x.x.x.x:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: reading length: EOF
[WGSUV] 2021/05/05 07:23:01.217754 static.go:55: DEBUG: StaticClient:0xc0000e0000@relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy= connected x.x.x.x:22067
[WGSUV] 2021/05/05 07:23:01.268645 static.go:68: INFO: Joined relay relay://x.x.x.x:22067
[WGSUV] 2021/05/05 07:23:38.381011 service.go:362: DEBUG: Connection loop
[WGSUV] 2021/05/05 07:23:38.381011 service.go:495: DEBUG: Resolved device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM addresses: [relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=]
[WGSUV] 2021/05/05 07:23:38.381011 structs.go:241: DEBUG: dialing T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= prio 200
[WGSUV] 2021/05/05 07:23:38.536618 service.go:965: DEBUG: dialing T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy= error: incorrect response code 1: not found
[WGSUV] 2021/05/05 07:23:38.536618 service.go:996: DEBUG: failed to connect to T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM 200
[WGSUV] 2021/05/05 07:23:38.536618 service.go:392: DEBUG: Next connection loop in 1m0s
[WGSUV] 2021/05/05 07:23:40.372188 static.go:86: DEBUG: StaticClient:0xc0000e0000@relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&amp;pingInterval=1m0s&amp;networkTimeout=2m0s&amp;sessionLimitBps=0&amp;globalLimitBps=0&amp;statusAddr=&amp;providedBy= received message protocol.SessionInvitation
[WGSUV] 2021/05/05 07:23:40.427494 relay_listen.go:91: DEBUG: Listen (BEP/relay): setting traffic class: not implemented on windows/amd64
[WGSUV] 2021/05/05 07:23:40.639712 service.go:340: INFO: Established secure connection to T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM at 172.16.202.222:63431-x.x.x.x:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[WGSUV] 2021/05/05 07:23:40.639712 model.go:2262: INFO: Device T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM client is "syncthing v1.16.0" named "s7654321hv1" at 172.16.202.222:63431-x.x.x.x:22067/relay-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256

Thomas_1 · May 5, 2021, 7:49am

And the relay Log

2021/05/05 07:20:49 main.go:140: strelaysrv v1.15.0 "Fermium Flea" (go1.16.3 windows-amd64) teamcity@build.syncthing.net 2021-04-06 06:03:22 UTC
2021/05/05 07:20:50 main.go:185: ID: 7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ
2021/05/05 07:20:50 main.go:239: URI: relay://x.x.x.x:22067/?id=7FZI3TK-RQWVVNV-HM6V4VU-ZGLJPRW-S64OGII-MOMUPLA-WDR6LUP-X4ODAQZ&pingInterval=5m0s&networkTimeout=10m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=&providedBy=
2021/05/05 07:20:57 listener.go:48: Listener accepted connection from 31.18.14.118:63402 tls true
2021/05/05 07:20:57 listener.go:48: Listener accepted connection from 31.18.14.118:63401 tls true
2021/05/05 07:20:58 listener.go:117: Message protocol.JoinRelayRequest from WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:20:58 listener.go:117: Message protocol.ConnectRequest from WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:20:58 listener.go:166: WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT is looking for T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM which does not exist
2021/05/05 07:20:58 listener.go:223: Closing connection WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT: read tcp x.x.x.x:22067->31.18.14.118:63402: use of closed network connection
2021/05/05 07:21:00 listener.go:48: Listener accepted connection from 31.18.14.118:55304 tls true
2021/05/05 07:21:00 listener.go:117: Message protocol.ConnectRequest from T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM
2021/05/05 07:21:00 session.go:54: New session <48b56/17f71>
2021/05/05 07:21:00 session.go:135: Session <48b56/17f71> serving
2021/05/05 07:21:00 listener.go:191: Sent invitation from T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:21:00 listener.go:281: Sending message protocol.SessionInvitation to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:21:00 listener.go:223: Closing connection T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM: read tcp x.x.x.x:22067->31.18.14.118:55304: use of closed network connection
2021/05/05 07:21:00 listener.go:48: Listener accepted connection from 31.18.14.118:63405 tls false
2021/05/05 07:21:00 listener.go:311: 31.18.14.118:63405 session lookup <48b56/17f71> 17f71
2021/05/05 07:21:00 session.go:120: New connection for <48b56/17f71> from 31.18.14.118:63405
2021/05/05 07:21:00 listener.go:48: Listener accepted connection from 31.18.14.118:55305 tls false
2021/05/05 07:21:00 listener.go:311: 31.18.14.118:55305 session lookup <48b56/17f71> 48b56
2021/05/05 07:21:00 session.go:120: New connection for <48b56/17f71> from 31.18.14.118:55305
2021/05/05 07:21:00 session.go:152: Session <48b56/17f71> starting between 31.18.14.118:63405 and 31.18.14.118:55305
2021/05/05 07:21:00 session.go:251: Proxy 31.18.14.118:55305 -> 31.18.14.118:63405
2021/05/05 07:21:00 session.go:251: Proxy 31.18.14.118:63405 -> 31.18.14.118:55305
2021/05/05 07:21:00 session.go:268: 255 bytes from 31.18.14.118:55305 to 31.18.14.118:63405
2021/05/05 07:21:00 session.go:268: 1013 bytes from 31.18.14.118:63405 to 31.18.14.118:55305
2021/05/05 07:21:00 session.go:268: 777 bytes from 31.18.14.118:55305 to 31.18.14.118:63405
2021/05/05 07:21:00 session.go:268: 62 bytes from 31.18.14.118:63405 to 31.18.14.118:55305
2021/05/05 07:21:00 session.go:268: 61 bytes from 31.18.14.118:55305 to 31.18.14.118:63405
2021/05/05 07:21:00 session.go:268: 28 bytes from 31.18.14.118:63405 to 31.18.14.118:55305
2021/05/05 07:21:00 session.go:268: 28 bytes from 31.18.14.118:55305 to 31.18.14.118:63405
2021/05/05 07:21:45 session.go:268: 30 bytes from 31.18.14.118:55305 to 31.18.14.118:63405
2021/05/05 07:21:45 session.go:268: 30 bytes from 31.18.14.118:63405 to 31.18.14.118:55305
2021/05/05 07:22:30 session.go:268: 30 bytes from 31.18.14.118:55305 to 31.18.14.118:63405
2021/05/05 07:23:00 listener.go:223: Closing connection WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT: EOF
2021/05/05 07:23:00 session.go:82: Dropping session <48b56/17f71> involving WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:23:00 session.go:177: Session <48b56/17f71> ended, outcomes: read tcp x.x.x.x:22067->31.18.14.118:63405: use of closed network connection and read tcp x.x.x.x:22067->31.18.14.118:55305: use of closed network connection
2021/05/05 07:23:00 session.go:213: Session <48b56/17f71> stopping
2021/05/05 07:23:00 listener.go:48: Listener accepted connection from 31.18.14.118:63425 tls true
2021/05/05 07:23:00 listener.go:117: Message protocol.JoinRelayRequest from WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:23:37 listener.go:48: Listener accepted connection from 31.18.14.118:63430 tls true
2021/05/05 07:23:37 listener.go:117: Message protocol.ConnectRequest from WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:23:37 listener.go:166: WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT is looking for T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM which does not exist
2021/05/05 07:23:37 listener.go:223: Closing connection WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT: read tcp x.x.x.x:22067->31.18.14.118:63430: use of closed network connection
2021/05/05 07:23:39 listener.go:48: Listener accepted connection from 31.18.14.118:55322 tls true
2021/05/05 07:23:39 listener.go:117: Message protocol.ConnectRequest from T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM
2021/05/05 07:23:39 session.go:54: New session <d47e7/9eddc>
2021/05/05 07:23:39 session.go:135: Session <d47e7/9eddc> serving
2021/05/05 07:23:39 listener.go:191: Sent invitation from T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:23:39 listener.go:281: Sending message protocol.SessionInvitation to WGSUVDA-LJRTJ7C-LCO2XDN-TR6RYJE-AXA4AS7-7L6YHED-RUQZ42P-V7BPSQT
2021/05/05 07:23:39 listener.go:223: Closing connection T5K77EF-PNYQQR7-GTHOV7K-FMN36KA-X73L5JH-HIA5HMW-PKAXI55-JRJLJQM: read tcp x.x.x.x:22067->31.18.14.118:55322: use of closed network connection
2021/05/05 07:23:39 listener.go:48: Listener accepted connection from 31.18.14.118:55323 tls false
2021/05/05 07:23:39 listener.go:311: 31.18.14.118:55323 session lookup <d47e7/9eddc> d47e7
2021/05/05 07:23:39 session.go:120: New connection for <d47e7/9eddc> from 31.18.14.118:55323
2021/05/05 07:23:39 listener.go:48: Listener accepted connection from 31.18.14.118:63431 tls false
2021/05/05 07:23:39 listener.go:311: 31.18.14.118:63431 session lookup <d47e7/9eddc> 9eddc
2021/05/05 07:23:39 session.go:120: New connection for <d47e7/9eddc> from 31.18.14.118:63431
2021/05/05 07:23:39 session.go:152: Session <d47e7/9eddc> starting between 31.18.14.118:55323 and 31.18.14.118:63431
2021/05/05 07:23:39 session.go:251: Proxy 31.18.14.118:63431 -> 31.18.14.118:55323
2021/05/05 07:23:39 session.go:251: Proxy 31.18.14.118:55323 -> 31.18.14.118:63431
2021/05/05 07:23:39 session.go:268: 255 bytes from 31.18.14.118:55323 to 31.18.14.118:63431
2021/05/05 07:23:39 session.go:268: 1011 bytes from 31.18.14.118:63431 to 31.18.14.118:55323
2021/05/05 07:23:39 session.go:268: 776 bytes from 31.18.14.118:55323 to 31.18.14.118:63431
2021/05/05 07:23:39 session.go:268: 62 bytes from 31.18.14.118:63431 to 31.18.14.118:55323
2021/05/05 07:23:39 session.go:268: 61 bytes from 31.18.14.118:55323 to 31.18.14.118:63431
2021/05/05 07:23:39 session.go:268: 28 bytes from 31.18.14.118:63431 to 31.18.14.118:55323
2021/05/05 07:23:39 session.go:268: 28 bytes from 31.18.14.118:55323 to 31.18.14.118:63431

What I see is that A saw EOF and Host B saw a timeout.

AudriusButkevicius · May 5, 2021, 7:20pm

So no smoking gun.

Seems like the connection between relay and B just dies.

Maybe your tcp stack has very short keep alives/statefull firewall with a short timeout?

I guess you could set -ping-interval=10s on the relay and see if that helps, this will make sure there are some messages exchanged between the two every 10 seconds.

It’s a bit sad that a connection to the relay for the purposes of accepting new connections breaking, breaks existing connections, but I guess that’s just how the current architecture works, and it would be non-trivial to do something else.

Also, I guess it sort of makes sense, as it helps recover from cases where the relay genuinely disappeared, allowing quicker detection of dead connections.

Thomas_1 · May 6, 2021, 7:29am

Looks like it is working now. I start with 10s and now at 1m connection is still stable.

Many thanks !

system · June 5, 2021, 7:29am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.