"the remote device speaks an unknown (newer?) version of the protocol" when connecting between v1.20.0 and v1.19.2

I’ve just seen this “notice” on one of the Windows devices after upgrading to v1.20.0. The remote device runs the official Android app v1.19.2 (which is still the newest release on F-Droid at the moment).

Below is a filtered log from the Windows device with all lines where the remote device “GCXVKIG” is being mentioned.

[QJFP3] 2022/05/03 19:11:05 INFO: Device GCXVKIG is "GCXVKIG" at [dynamic]
[QJFP3] 2022/05/03 19:11:06 INFO: Established secure connection to GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[QJFP3] 2022/05/03 19:11:14 INFO: Device GCXVKIG client is "syncthing v1.19.2" named "GCXVKIG" at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[QJFP3] 2022/05/03 19:11:14 VERBOSE: Connected to device GCXVKIG at 10.0.0.57:22000 (type quic-server)
[QJFP3] 2022/05/03 19:11:33 VERBOSE: Completion for folder "fx37a-wmmxy" on device GCXVKIG is 0% (state: unknown)
[QJFP3] 2022/05/03 19:11:33 VERBOSE: Completion for folder "5eief-x9lna" on device GCXVKIG is 0% (state: unknown)
[QJFP3] 2022/05/03 19:14:06 VERBOSE: Received ClusterConfig from device GCXVKIG
[QJFP3] 2022/05/03 19:14:06 INFO: Connection to GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: writing message: Application error 0x0: closing
[QJFP3] 2022/05/03 19:14:06 VERBOSE: Disconnected from device GCXVKIG
[QJFP3] 2022/05/03 19:14:07 VERBOSE: Completion for folder "mgieg-z3mzc" on device GCXVKIG is 0% (state: unknown)
[QJFP3] 2022/05/03 19:14:07 INFO: Established secure connection to GCXVKIG at 10.0.0.55:49767-161.97.133.225:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:14:07 INFO: Device GCXVKIG client is "syncthing v1.19.2" named "GCXVKIG" at 10.0.0.55:49767-161.97.133.225:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:14:07 VERBOSE: Connected to device GCXVKIG at 161.97.133.225:22067 (type relay-client)
[QJFP3] 2022/05/03 19:14:07 VERBOSE: Received ClusterConfig from device GCXVKIG
[QJFP3] 2022/05/03 19:14:07 INFO: Failed to exchange Hello messages with GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: Application error 0x0: closing
[QJFP3] 2022/05/03 19:14:07 INFO: Failed to exchange Hello messages with GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256: Application error 0x0: closing
[QJFP3] 2022/05/03 19:14:08 WARNING: Connecting to GCXVKIG (10.0.0.56:22000): the remote device speaks an unknown (newer?) version of the protocol
[QJFP3] 2022/05/03 19:14:11 INFO: Connection to GCXVKIG at 10.0.0.55:49767-161.97.133.225:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: writing message: write tcp 10.0.0.55:49767->161.97.133.225:22067: wsasend: An existing connection was forcibly closed by the remote host.
[QJFP3] 2022/05/03 19:14:11 VERBOSE: Disconnected from device GCXVKIG
[QJFP3] 2022/05/03 19:14:12 INFO: Established secure connection to GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[QJFP3] 2022/05/03 19:14:12 INFO: Device GCXVKIG client is "syncthing v1.19.2" named "GCXVKIG" at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[QJFP3] 2022/05/03 19:14:12 VERBOSE: Connected to device GCXVKIG at 10.0.0.57:22000 (type quic-server)
[QJFP3] 2022/05/03 19:14:12 INFO: Connection to GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: reading length: Application error 0x0: closing
[QJFP3] 2022/05/03 19:14:12 VERBOSE: Disconnected from device GCXVKIG
[QJFP3] 2022/05/03 19:14:15 INFO: Established secure connection to GCXVKIG at 10.0.0.55:22000-10.0.0.57:22000/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:14:15 INFO: Device GCXVKIG client is "syncthing v1.19.2" named "GCXVKIG" at 10.0.0.55:22000-10.0.0.57:22000/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:14:15 VERBOSE: Connected to device GCXVKIG at 10.0.0.57:22000 (type tcp-server)
[QJFP3] 2022/05/03 19:14:15 VERBOSE: Received ClusterConfig from device GCXVKIG
[QJFP3] 2022/05/03 19:14:15 INFO: Connection to GCXVKIG at 10.0.0.55:22000-10.0.0.57:22000/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256 closed: writing message: use of closed network connection
[QJFP3] 2022/05/03 19:14:15 VERBOSE: Disconnected from device GCXVKIG
[QJFP3] 2022/05/03 19:14:23 INFO: Established secure connection to GCXVKIG at 10.0.0.55:50143-161.97.133.225:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:14:23 INFO: Device GCXVKIG client is "syncthing v1.19.2" named "GCXVKIG" at 10.0.0.55:50143-161.97.133.225:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:14:23 VERBOSE: Connected to device GCXVKIG at 161.97.133.225:22067 (type relay-client)
[QJFP3] 2022/05/03 19:14:23 VERBOSE: Received ClusterConfig from device GCXVKIG
[QJFP3] 2022/05/03 19:14:24 VERBOSE: Device GCXVKIG sent an index update for "5eief-x9lna" with 25 items
[QJFP3] 2022/05/03 19:14:24 VERBOSE: Device GCXVKIG sent an index update for "w9h6p-vpccd" with 7 items
[QJFP3] 2022/05/03 19:14:28 VERBOSE: Device GCXVKIG sent an index update for "mgieg-z3mzc" with 25 items
[QJFP3] 2022/05/03 19:14:30 INFO: Established secure connection to GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[QJFP3] 2022/05/03 19:14:30 INFO: Replacing old connection 10.0.0.55:50143-161.97.133.225:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256 with [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 for GCXVKIG
[QJFP3] 2022/05/03 19:14:32 INFO: Connection to GCXVKIG at 10.0.0.55:50143-161.97.133.225:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: replacing connection
[QJFP3] 2022/05/03 19:14:32 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 1000 items
[QJFP3] 2022/05/03 19:14:32 INFO: Device GCXVKIG client is "syncthing v1.19.2" named "GCXVKIG" at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256
[QJFP3] 2022/05/03 19:14:32 VERBOSE: Disconnected from device GCXVKIG
[QJFP3] 2022/05/03 19:14:32 VERBOSE: Connected to device GCXVKIG at 10.0.0.57:22000 (type quic-server)
[QJFP3] 2022/05/03 19:14:33 VERBOSE: Received ClusterConfig from device GCXVKIG
[QJFP3] 2022/05/03 19:14:35 INFO: Connection from GCXVKIG at 161.97.133.225:22067 (relay-client) rejected: already connected to this device
[QJFP3] 2022/05/03 19:14:38 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 1000 items
[QJFP3] 2022/05/03 19:15:13 INFO: Established secure connection to GCXVKIG at 10.0.0.55:22000-10.0.0.57:22000/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:15:13 INFO: Replacing old connection [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 with 10.0.0.55:22000-10.0.0.57:22000/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256 for GCXVKIG
[QJFP3] 2022/05/03 19:15:14 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:15:14 INFO: Connection to GCXVKIG at [::]:22000-10.0.0.57:22000/quic-server/TLS1.3-TLS_CHACHA20_POLY1305_SHA256 closed: replacing connection
[QJFP3] 2022/05/03 19:15:14 INFO: Device GCXVKIG client is "syncthing v1.19.2" named "GCXVKIG" at 10.0.0.55:22000-10.0.0.57:22000/tcp-server/TLS1.3-TLS_AES_128_GCM_SHA256
[QJFP3] 2022/05/03 19:15:14 VERBOSE: Disconnected from device GCXVKIG
[QJFP3] 2022/05/03 19:15:14 VERBOSE: Connected to device GCXVKIG at 10.0.0.57:22000 (type tcp-server)
[QJFP3] 2022/05/03 19:15:14 VERBOSE: Received ClusterConfig from device GCXVKIG
[QJFP3] 2022/05/03 19:15:16 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:15:50 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 1000 items
[QJFP3] 2022/05/03 19:15:51 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:15:52 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:15:53 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 1000 items
[QJFP3] 2022/05/03 19:15:55 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:15:56 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 1000 items
[QJFP3] 2022/05/03 19:15:57 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:15:58 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 627 items
[QJFP3] 2022/05/03 19:15:59 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:16:00 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:16:01 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:16:02 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 860 items
[QJFP3] 2022/05/03 19:16:03 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:16:04 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 1000 items
[QJFP3] 2022/05/03 19:16:04 VERBOSE: Device GCXVKIG sent an index update for "fx37a-wmmxy" with 12 items
[QJFP3] 2022/05/03 19:16:04 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 31 items
[QJFP3] 2022/05/03 19:16:04 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 44 items
[QJFP3] 2022/05/03 19:16:13 VERBOSE: Completion for folder "j2kgm-h9kws" on device GCXVKIG is 100% (state: valid)
[QJFP3] 2022/05/03 19:16:25 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 18 items
[QJFP3] 2022/05/03 19:16:26 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 3 items
[QJFP3] 2022/05/03 19:16:28 VERBOSE: Completion for folder "j2kgm-h9kws" on device GCXVKIG is 100% (state: valid)
[QJFP3] 2022/05/03 19:16:35 VERBOSE: Device GCXVKIG sent an index update for "j2kgm-h9kws" with 59 items
[QJFP3] 2022/05/03 19:16:37 VERBOSE: Completion for folder "j2kgm-h9kws" on device GCXVKIG is 100% (state: valid)
[QJFP3] 2022/05/03 19:19:53 VERBOSE: Completion for folder "mgieg-z3mzc" on device GCXVKIG is 100% (state: valid)
[QJFP3] 2022/05/03 19:19:53 VERBOSE: Completion for folder "w9h6p-vpccd" on device GCXVKIG is 100% (state: valid)
[QJFP3] 2022/05/03 19:19:53 VERBOSE: Completion for folder "5eief-x9lna" on device GCXVKIG is 100% (state: valid)
[QJFP3] 2022/05/03 19:19:53 VERBOSE: Completion for folder "fx37a-wmmxy" on device GCXVKIG is 100% (state: valid)

Have you got any idea what the problem may be about here? I can provide full verbose and audit (but not debug, unfortunately) logs from the Windows side and the basic log from the Android side if necessary.

Edit I’ve just noticed something weird here. The notice mentions “GCXVKIG (10.0.0.56:22000)”, but the actual address of GCXVKIG is “10.0.0.57”, while “10.0.0.56” belongs to a different Windows device. All remote devices have their addresses set to dynamic.

I have no idea but my guess is that an unknown version of the protocol means “not actually Syncthing” on the other side.

@tomasz86 what happens if you hardcode both sides to use quic?

I have the same problem, but both sides are on 1.20.0. It started after the upgrade to 1.20.0.

Looking at the log above, there’s a connection established via relay, and then a direct connection, and the direct connection dies with the protocol error. There were some changes to the connection registry in 1.20.0. I wonder if there’s some mixup or leakage between connections there somehow.

Try disabling relays?

I upgraded all devices to 1.20.0, and started receiving this message: “the remote device speaks an unknown (newer?) version of the protocol” on the introducer. Nothing was modified on the configuration on any device before or after the update. Some devices sync and some don’t. I’m using the default synching config on all devices, with only one introducer. I checked and all devices are on 1.20.0, I didn’t have this problem before upgrade. Can you help me?

Do the times with connections attempt on the other device lines up? Whats the error there?

Usually this error means that something else than syncthing is trying to connect to it.

This is what looks wrong on the logs:

2022-05-04 17:13:35 Device XXXXXXXXXXXXXXXXXX-TNDZMQB client is “syncthing v1.20.0” named “DEVICE4” at 10.152.152.11:54742-45.116.189.26:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256

2022-05-04 17:13:36 Connection to XXXXXXXXXXXXXXXXXX-TNDZMQB at 10.152.152.11:54742-45.116.189.26:22067/relay-client/TLS1.3-TLS_AES_128_GCM_SHA256 closed: unmarshalling header: proto: Header: illegal tag 0 (wire type 0)

Ah, I think I see the problem.

2 Likes

A new 1.20.1 release is coming to address this.

4 Likes

Thank you very much for a very quick fix :relieved:.

3 Likes

Thank YOU for the very quick issue reporting! A shame we didn’t catch this in the RC. Though I must admit for always-running devices I stick to stable as well, using the main branch code only during development tests :frowning:

1 Like

Yeah, it could probably be worth it to consider to have at least one, perhaps less important device running on the RC channel. I do use multiple local instances always compiled from the current main for testing, but I didn’t experience this specific error there.

1 Like

I do run RCs on “stable” machines and nightlies on my dev machine, but I also missed it. I need to add some log parsing with alerts to make it more useful.

1 Like