Cannot get QUIC working at all

Support
1

one linux node runs discovery, relay, eturnal turn/stun server and a client; another linux node runs a client. using binaries from github releases.

tcp and relay works fine. netcat over udp between nodes work fine.

there is direct ip connectivity between nodes (not on same lan, but routed. no nat no port mapping no upnp involved. no firewall is blocking ports, inspecting session, security etc)

however I cannot get devices to talk to each other using QUIC. There is talk at udp network level between the devices, but they seem to not finalize with a successful session. the certs and keys were autogenerated by syncthing on first launch.

rsync and rsync-stage hostnames in logs = same machine with all services 10.y.y.y

xml modifications: on node with all services:

$ diff --suppress-common-lines -y .local/state/syncthing/config.xml /var/tmp/config.xml |grep -E -v 'user|password|apikey'
    <folder id="default" label="Default Folder" path="/srv/da |     <folder id="default" label="Default Folder" path="/opt/et
        <device id="N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-Z |         <device id="RQIHUID-TW7ZMI4-U2AJ4QN-YXGVLA4-OIVVYQL-H
            <encryptionPassword></encryptionPassword>         <
        </device>                                             <
        <device id="ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-H <
        <maxConflicts>0</maxConflicts>                        |         <maxConflicts>10</maxConflicts>
        <blockPullOrder>random</blockPullOrder>               |         <blockPullOrder>standard</blockPullOrder>
    <device id="N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZ |     <device id="RQIHUID-TW7ZMI4-U2AJ4QN-YXGVLA4-OIVVYQL-HBWJU
        <address>dynamic</address>                            <
        <paused>false</paused>                                <
        <autoAcceptFolders>false</autoAcceptFolders>          <
        <maxSendKbps>0</maxSendKbps>                          <
        <maxRecvKbps>0</maxRecvKbps>                          <
        <maxRequestKiB>0</maxRequestKiB>                      <
        <untrusted>false</untrusted>                          <
        <remoteGUIPort>0</remoteGUIPort>                      <
        <numConnections>4</numConnections>                    <
    </device>                                                 <
    <device id="ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKY <
        <numConnections>4</numConnections>                    |         <numConnections>0</numConnections>
        <address>rsync:8384</address>                         |         <address>127.0.0.1:8384</address>
        <listenAddress>quic4://rsync:22000</listenAddress>    |         <listenAddress>default</listenAddress>
        <listenAddress1>tcp4://rsync:22000</listenAddress1>   |         <globalAnnounceServer>default</globalAnnounceServer>
        <listenAddress1>relay://rsync:22067/?id=QKNYIZC-RIY7H <
        <globalAnnounceServer>https://rsync:8443/v2/?id=QKNYI <
        <localAnnounceEnabled>false</localAnnounceEnabled>    |         <localAnnounceEnabled>true</localAnnounceEnabled>
        <startBrowser>false</startBrowser>                    |         <startBrowser>true</startBrowser>
        <natEnabled>false</natEnabled>                        |         <natEnabled>true</natEnabled>
        <urAccepted>-1</urAccepted>                           |         <urAccepted>0</urAccepted>
        <urURL>https://rsync</urURL>                          |         <urURL>https://data.syncthing.net/newdata</urURL>
        <autoUpgradeIntervalH>0</autoUpgradeIntervalH>        |         <autoUpgradeIntervalH>12</autoUpgradeIntervalH>
        <releasesURL>https://localhost</releasesURL>          |         <releasesURL>https://upgrades.syncthing.net/meta.json
                                                              >         <unackedNotificationID>authenticationUserAndPassword<
        <crashReportingURL>https://localhost</crashReportingU |         <crashReportingURL>https://crash.syncthing.net/newcra
        <crashReportingEnabled>false</crashReportingEnabled>  |         <crashReportingEnabled>true</crashReportingEnabled>
        <stunServer>rsync:3478</stunServer>                   |         <stunServer>default</stunServer>
        <announceLANAddresses>false</announceLANAddresses>    |         <announceLANAddresses>true</announceLANAddresses>
        <connectionPriorityTcpLan>20</connectionPriorityTcpLa |         <connectionPriorityTcpLan>10</connectionPriorityTcpLa
        <connectionPriorityQuicLan>10</connectionPriorityQuic |         <connectionPriorityQuicLan>20</connectionPriorityQuic
        <connectionPriorityTcpWan>40</connectionPriorityTcpWa |         <connectionPriorityTcpWan>30</connectionPriorityTcpWa
        <connectionPriorityQuicWan>30</connectionPriorityQuic |         <connectionPriorityQuicWan>40</connectionPriorityQuic
            <device id="ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAA |             <device id="RQIHUID-TW7ZMI4-U2AJ4QN-YXGVLA4-OIVVY
            <numConnections>4</numConnections>                |             <numConnections>0</numConnections>

on node with only the client:

$ diff --suppress-common-lines -y .local/state/syncthing/config.xml config.xml-default | grep -E -v 'user|password|apikey'
    <folder id="default" label="Default Folder" path="/home/s |     <folder id="default" label="Default Folder" path="/home/s
        <device id="ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-H <
            <encryptionPassword></encryptionPassword>         <
        </device>                                             <
        <maxConflicts>0</maxConflicts>                        |         <maxConflicts>10</maxConflicts>
        <blockPullOrder>random</blockPullOrder>               |         <blockPullOrder>standard</blockPullOrder>
        <autoAcceptFolders>true</autoAcceptFolders>           |         <autoAcceptFolders>false</autoAcceptFolders>
        <maxSendKbps>0</maxSendKbps>                          <
        <maxRecvKbps>3</maxRecvKbps>                          <
        <maxRequestKiB>0</maxRequestKiB>                      <
        <untrusted>false</untrusted>                          <
        <remoteGUIPort>0</remoteGUIPort>                      <
        <numConnections>4</numConnections>                    <
    </device>                                                 <
    <device id="ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKY <
        <address>dynamic</address>                            <
        <paused>false</paused>                                <
        <autoAcceptFolders>true</autoAcceptFolders>           <
        <maxRecvKbps>3</maxRecvKbps>                          |         <maxRecvKbps>0</maxRecvKbps>
        <numConnections>4</numConnections>                    |         <numConnections>0</numConnections>
        <address>0.0.0.0:8384</address>                       |         <address>127.0.0.1:8384</address>
        <listenAddress>quic://:22000</listenAddress>          |         <listenAddress>default</listenAddress>
        <listenAddress1>tcp4://:22000</listenAddress1>        |         <globalAnnounceServer>default</globalAnnounceServer>
        <listenAddress1>relay://rsync:22067/?id=QKNYIZC-RIY7H <
        <globalAnnounceServer>https://rsync:8443/v2/?id=QKNYI <
        <localAnnounceEnabled>false</localAnnounceEnabled>    |         <localAnnounceEnabled>true</localAnnounceEnabled>
        <maxRecvKbps>3</maxRecvKbps>                          |         <maxRecvKbps>0</maxRecvKbps>
        <startBrowser>false</startBrowser>                    |         <startBrowser>true</startBrowser>
        <urAccepted>-1</urAccepted>                           |         <urAccepted>0</urAccepted>
        <urURL>https://localhost</urURL>                      |         <urURL>https://data.syncthing.net/newdata</urURL>
        <autoUpgradeIntervalH>0</autoUpgradeIntervalH>        |         <autoUpgradeIntervalH>12</autoUpgradeIntervalH>
        <keepTemporariesH>48</keepTemporariesH>               |         <keepTemporariesH>24</keepTemporariesH>
        <releasesURL>https://localhost</releasesURL>          |         <releasesURL>https://upgrades.syncthing.net/meta.json
                                                              >         <unackedNotificationID>authenticationUserAndPassword<
        <crashReportingURL>https://localhost</crashReportingU |         <crashReportingURL>https://crash.syncthing.net/newcra
        <crashReportingEnabled>false</crashReportingEnabled>  |         <crashReportingEnabled>true</crashReportingEnabled>
        <stunServer>rsync:3478</stunServer>                   |         <stunServer>default</stunServer>
        <announceLANAddresses>false</announceLANAddresses>    |         <announceLANAddresses>true</announceLANAddresses>
        <connectionPriorityTcpLan>20</connectionPriorityTcpLa |         <connectionPriorityTcpLan>10</connectionPriorityTcpLa
        <connectionPriorityQuicLan>10</connectionPriorityQuic |         <connectionPriorityQuicLan>20</connectionPriorityQuic
        <connectionPriorityTcpWan>40</connectionPriorityTcpWa |         <connectionPriorityTcpWan>30</connectionPriorityTcpWa
        <connectionPriorityQuicWan>30</connectionPriorityQuic |         <connectionPriorityQuicWan>40</connectionPriorityQuic
            <autoAcceptFolders>true</autoAcceptFolders>       |             <autoAcceptFolders>false</autoAcceptFolders>
            <maxRecvKbps>3</maxRecvKbps>                      |             <maxRecvKbps>0</maxRecvKbps>
            <numConnections>4</numConnections>                |             <numConnections>0</numConnections>

wireshark/tcpdump traffic between devices on next reply, as forum limits the max characters to 32000

unfortunately the STTRACE does not tell me as much as I wanted:

[y.y.y ~]$ clear
[y.y.y ~]$ export STTRACE=connections,dialer,discover,nat,upnp,protocol,net,beacon,relay
[y.y.y ~]$ syncthing-linux-amd64-v1.27.11/syncthing serve --no-upgrade 2>&1 > st.log
^C[y.y.y ~]cat st.log
2024/09/12 17:58:16.683165 control_unix.go:35: DEBUG: SO_REUSEPORT supported
2024/09/12 17:58:16.694451 control_unix.go:35: DEBUG: SO_REUSEPORT supported
[start] 2024/09/12 17:58:16.698238 main.go:535: INFO: syncthing v1.27.11 "Gold Grasshopper" (go1.22.6 linux-amd64) builder@github.syncthing.net 2024-08-28 06:32:03 UTC
[start] 2024/09/12 17:58:16.731983 main.go:761: INFO: No automatic upgrades; STNOUPGRADE environment variable defined.
[ONX5K] 2024/09/12 17:58:16.732534 syncthing.go:155: INFO: My ID: ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ
[monitor] 2024/09/12 17:58:17.184240 internal.go:44: DEBUG: Dialer logging disabled, as no proxy was detected
[ONX5K] 2024/09/12 17:58:17.193626 syncthing.go:182: INFO: Hashing performance is 276.98 MB/s
[ONX5K] 2024/09/12 17:58:17.194022 limiter.go:162: INFO: Overall send rate is unlimited, receive rate is unlimited
[ONX5K] 2024/09/12 17:58:17.194220 service.go:818: DEBUG: Starting listener quic4://rsync:22000
[ONX5K] 2024/09/12 17:58:17.194417 service.go:477: DEBUG: Connection loop
[ONX5K] 2024/09/12 17:58:17.194434 service.go:479: DEBUG: Connection loop in initial rampup
[ONX5K] 2024/09/12 17:58:17.194465 manager.go:92: INFO: Using discovery mechanism: global discovery server https://rsync:8443/v2/?id=QKNYIZC-RIY7HKO-GGL6TQA-F7IK6EO-JFRIMGU-NXW7TKS-54MUSD2-3IE43QZ
[ONX5K] 2024/09/12 17:58:17.194617 model.go:415: INFO: Ready to synchronize "Default Folder" (default) (sendonly)
[ONX5K] 2024/09/12 17:58:17.195288 internal.go:44: DEBUG: Dialer logging disabled, as no proxy was detected
[ONX5K] 2024/09/12 17:58:17.195453 quic_listen.go:126: INFO: QUIC listener (10.y.y.y:22000) starting
[ONX5K] 2024/09/12 17:58:17.195521 public.go:74: DEBUG: Dialing direct result tcp rsync:8443: &{{0xc00028c280}} <nil>
[ONX5K] 2024/09/12 17:58:17.195645 api.go:406: INFO: GUI and API listening on 10.y.y.y:8384
[ONX5K] 2024/09/12 17:58:17.195662 api.go:407: INFO: Access the GUI via the following URL: http://rsync:8384/
[ONX5K] 2024/09/12 17:58:17.195709 syncthing.go:312: INFO: My name is "rsync-stage"
[ONX5K] 2024/09/12 17:58:17.195729 syncthing.go:315: INFO: Device N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK is "T00901" at [dynamic]
[ONX5K] 2024/09/12 17:58:17.196175 folder.go:925: INFO: Completed initial scan of sendonly folder "Default Folder" (default)
[ONX5K] 2024/09/12 17:58:17.198717 global.go:186: DEBUG: globalClient.Lookup https://rsync:8443/v2/?device=N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK 404 Not Found
[ONX5K] 2024/09/12 17:58:17.198783 manager.go:164: DEBUG: lookup results for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK
[ONX5K] 2024/09/12 17:58:17.198796 manager.go:165: DEBUG:   addresses:  []
[ONX5K] 2024/09/12 17:58:17.198803 service.go:657: DEBUG: Resolved device N74QTL7 addresses: []
[ONX5K] 2024/09/12 17:58:17.198816 service.go:507: DEBUG: Next connection loop in 5s
[ONX5K] 2024/09/12 17:58:19.196943 global.go:273: DEBUG: global@https://rsync:8443/v2/ Announcement: {[quic4://rsync:22000]}
[ONX5K] 2024/09/12 17:58:19.197318 public.go:74: DEBUG: Dialing direct result tcp rsync:8443: &{{0xc00028c700}} <nil>
[ONX5K] 2024/09/12 17:58:19.202721 global.go:282: DEBUG: global@https://rsync:8443/v2/ announce POST: 204 No Content
[ONX5K] 2024/09/12 17:58:19.202789 global.go:309: DEBUG: global@https://rsync:8443/v2/ announce Reannounce-After: 3368 <nil>
[ONX5K] 2024/09/12 17:58:22.199540 service.go:477: DEBUG: Connection loop
[ONX5K] 2024/09/12 17:58:22.199574 service.go:479: DEBUG: Connection loop in initial rampup
[ONX5K] 2024/09/12 17:58:22.199691 manager.go:130: DEBUG: negative cache entry for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK at global@https://rsync:8443/v2/ valid until 2024-09-12 17:59:17.198776062 +0300 EEST m=+60.507741791 or 2024-09-12 18:00:13.198777508 +0300 EEST m=+116.507743237
[ONX5K] 2024/09/12 17:58:22.199704 manager.go:164: DEBUG: lookup results for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK
[ONX5K] 2024/09/12 17:58:22.199711 manager.go:165: DEBUG:   addresses:  []
[ONX5K] 2024/09/12 17:58:22.199718 service.go:657: DEBUG: Resolved device N74QTL7 addresses: []
[ONX5K] 2024/09/12 17:58:22.199733 service.go:507: DEBUG: Next connection loop in 5s
[ONX5K] 2024/09/12 17:58:27.200029 service.go:477: DEBUG: Connection loop
[ONX5K] 2024/09/12 17:58:27.200110 service.go:479: DEBUG: Connection loop in initial rampup
[ONX5K] 2024/09/12 17:58:27.200175 manager.go:130: DEBUG: negative cache entry for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK at global@https://rsync:8443/v2/ valid until 2024-09-12 17:59:17.198776062 +0300 EEST m=+60.507741791 or 2024-09-12 18:00:13.198777508 +0300 EEST m=+116.507743237
[ONX5K] 2024/09/12 17:58:27.200188 manager.go:164: DEBUG: lookup results for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK
[ONX5K] 2024/09/12 17:58:27.200195 manager.go:165: DEBUG:   addresses:  []
[ONX5K] 2024/09/12 17:58:27.200202 service.go:657: DEBUG: Resolved device N74QTL7 addresses: []
[ONX5K] 2024/09/12 17:58:27.200220 service.go:507: DEBUG: Next connection loop in 5s
[ONX5K] 2024/09/12 17:58:32.202376 service.go:477: DEBUG: Connection loop
[ONX5K] 2024/09/12 17:58:32.202412 service.go:479: DEBUG: Connection loop in initial rampup
[ONX5K] 2024/09/12 17:58:32.202534 manager.go:130: DEBUG: negative cache entry for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK at global@https://rsync:8443/v2/ valid until 2024-09-12 17:59:17.198776062 +0300 EEST m=+60.507741791 or 2024-09-12 18:00:13.198777508 +0300 EEST m=+116.507743237
[ONX5K] 2024/09/12 17:58:32.202549 manager.go:164: DEBUG: lookup results for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK
[ONX5K] 2024/09/12 17:58:32.202556 manager.go:165: DEBUG:   addresses:  []
[ONX5K] 2024/09/12 17:58:32.202563 service.go:657: DEBUG: Resolved device N74QTL7 addresses: []
[ONX5K] 2024/09/12 17:58:32.202577 service.go:507: DEBUG: Next connection loop in 8s
[ONX5K] 2024/09/12 17:58:40.203213 service.go:477: DEBUG: Connection loop
[ONX5K] 2024/09/12 17:58:40.203250 service.go:479: DEBUG: Connection loop in initial rampup
[ONX5K] 2024/09/12 17:58:40.203331 manager.go:130: DEBUG: negative cache entry for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK at global@https://rsync:8443/v2/ valid until 2024-09-12 17:59:17.198776062 +0300 EEST m=+60.507741791 or 2024-09-12 18:00:13.198777508 +0300 EEST m=+116.507743237
[ONX5K] 2024/09/12 17:58:40.203343 manager.go:164: DEBUG: lookup results for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK
[ONX5K] 2024/09/12 17:58:40.203350 manager.go:165: DEBUG:   addresses:  []
[ONX5K] 2024/09/12 17:58:40.203357 service.go:657: DEBUG: Resolved device N74QTL7 addresses: []
[ONX5K] 2024/09/12 17:58:40.203370 service.go:507: DEBUG: Next connection loop in 16s
[ONX5K] 2024/09/12 17:58:56.204122 service.go:477: DEBUG: Connection loop
[ONX5K] 2024/09/12 17:58:56.204157 service.go:479: DEBUG: Connection loop in initial rampup
[ONX5K] 2024/09/12 17:58:56.204227 manager.go:130: DEBUG: negative cache entry for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK at global@https://rsync:8443/v2/ valid until 2024-09-12 17:59:17.198776062 +0300 EEST m=+60.507741791 or 2024-09-12 18:00:13.198777508 +0300 EEST m=+116.507743237
[ONX5K] 2024/09/12 17:58:56.204240 manager.go:164: DEBUG: lookup results for N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK
[ONX5K] 2024/09/12 17:58:56.204247 manager.go:165: DEBUG:   addresses:  []
[ONX5K] 2024/09/12 17:58:56.204255 service.go:657: DEBUG: Resolved device N74QTL7 addresses: []
[ONX5K] 2024/09/12 17:58:56.204285 service.go:507: DEBUG: Next connection loop in 32s
[monitor] 2024/09/12 17:59:07.174251 monitor.go:161: INFO: Signal 2 received; exiting
[ONX5K] 2024/09/12 17:59:07.174507 quic_listen.go:150: INFO: QUIC listener (10.y.y.y:22000) shutting down
[ONX5K] 2024/09/12 17:59:07.275476 syncthing.go:351: INFO: Exiting

[x.x.x ~]$ export STTRACE=connections,dialer,discover,nat,upnp,protocol,net,beacon,relay
[x.x.x ~]$ syncthing serve --no-upgrade 2>&1 > st.log
^C[x.x.x ~]cat st.log
2024/09/12 17:58:22.173709 control_unix.go:35: DEBUG: SO_REUSEPORT supported
2024/09/12 17:58:22.197323 control_unix.go:35: DEBUG: SO_REUSEPORT supported
[start] 2024/09/12 17:58:22.206715 main.go:535: INFO: syncthing v1.27.11 "Gold Grasshopper" (go1.22.6 linux-amd64) builder@github.syncthing.net 2024-08-28 06:32:03 UTC
[start] 2024/09/12 17:58:22.246920 main.go:761: INFO: No automatic upgrades; STNOUPGRADE environment variable defined.
[N74QT] 2024/09/12 17:58:22.248015 syncthing.go:155: INFO: My ID: N74QTL7-GVVDDQK-OPTDSXQ-DEGHCK7-ZB7VPOS-ZIKWZJ5-5WKHG3L-2SGOVAK
[monitor] 2024/09/12 17:58:22.674660 internal.go:44: DEBUG: Dialer logging disabled, as no proxy was detected
[N74QT] 2024/09/12 17:58:22.698464 internal.go:44: DEBUG: Dialer logging disabled, as no proxy was detected
[N74QT] 2024/09/12 17:58:22.753408 syncthing.go:182: INFO: Hashing performance is 61.26 MB/s
[N74QT] 2024/09/12 17:58:22.754213 limiter.go:109: INFO: Device ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ send rate is unlimited, receive rate limit is 3 KiB/s
[N74QT] 2024/09/12 17:58:22.754287 limiter.go:162: INFO: Overall send rate is unlimited, receive rate limit is 3 KiB/s
[N74QT] 2024/09/12 17:58:22.754306 limiter.go:168: INFO: Rate limits do not apply to LAN connections
[N74QT] 2024/09/12 17:58:22.754333 service.go:52: DEBUG: Starting NAT service
[N74QT] 2024/09/12 17:58:22.754444 service.go:818: DEBUG: Starting listener quic4://:22000
[N74QT] 2024/09/12 17:58:22.755127 manager.go:92: INFO: Using discovery mechanism: global discovery server https://rsync:8443/v2/?id=QKNYIZC-RIY7HKO-GGL6TQA-F7IK6EO-JFRIMGU-NXW7TKS-54MUSD2-3IE43QZ
[N74QT] 2024/09/12 17:58:22.755399 service.go:477: DEBUG: Connection loop
[N74QT] 2024/09/12 17:58:22.755478 service.go:479: DEBUG: Connection loop in initial rampup
[N74QT] 2024/09/12 17:58:22.755725 model.go:415: INFO: Ready to synchronize "Default Folder" (default) (receiveonly)
[N74QT] 2024/09/12 17:58:22.758435 folder.go:925: INFO: Completed initial scan of receiveonly folder "Default Folder" (default)
[N74QT] 2024/09/12 17:58:22.758987 api.go:406: INFO: GUI and API listening on [::]:8384
[N74QT] 2024/09/12 17:58:22.759064 api.go:407: INFO: Access the GUI via the following URL: http://127.0.0.1:8384/
[N74QT] 2024/09/12 17:58:22.759180 syncthing.go:312: INFO: My name is "T00901"
[N74QT] 2024/09/12 17:58:22.759241 syncthing.go:315: INFO: Device ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ is "rsync-stage" at [dynamic]
[N74QT] 2024/09/12 17:58:22.779906 quic_listen.go:126: INFO: QUIC listener (0.0.0.0:22000) starting
[N74QT] 2024/09/12 17:58:22.813893 public.go:74: DEBUG: Dialing direct result tcp rsync:8443: &{{0xc0002ca480}} <nil>
[N74QT] 2024/09/12 17:58:22.963540 manager.go:139: DEBUG: lookup for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ at global@https://rsync:8443/v2/
[N74QT] 2024/09/12 17:58:22.963593 manager.go:140: DEBUG:   addresses: [quic4://rsync:22000]
[N74QT] 2024/09/12 17:58:22.963627 manager.go:164: DEBUG: lookup results for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ
[N74QT] 2024/09/12 17:58:22.963649 manager.go:165: DEBUG:   addresses:  [quic4://rsync:22000]
[N74QT] 2024/09/12 17:58:22.963678 service.go:657: DEBUG: Resolved device ONX5KQ3 addresses: [quic4://rsync:22000]
[N74QT] 2024/09/12 17:58:22.987943 structs.go:268: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 prio 30
[N74QT] 2024/09/12 17:58:24.781159 global.go:273: DEBUG: global@https://rsync:8443/v2/ Announcement: {[quic4://:22000]}
[N74QT] 2024/09/12 17:58:27.384332 public.go:74: DEBUG: Dialing direct result tcp rsync:8443: &{{0xc0001b0600}} <nil>
[N74QT] 2024/09/12 17:58:27.733483 global.go:282: DEBUG: global@https://rsync:8443/v2/ announce POST: 204 No Content
[N74QT] 2024/09/12 17:58:27.733557 global.go:309: DEBUG: global@https://rsync:8443/v2/ announce Reannounce-After: 3307 <nil>
[N74QT] 2024/09/12 17:58:32.573468 service.go:1172: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 error: dial: timeout: no recent network activity
[N74QT] 2024/09/12 17:58:32.573578 service.go:1202: DEBUG: failed to connect to ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ 30
[N74QT] 2024/09/12 17:58:32.573614 service.go:507: DEBUG: Next connection loop in 5s
[N74QT] 2024/09/12 17:58:37.575022 service.go:477: DEBUG: Connection loop
[N74QT] 2024/09/12 17:58:37.575066 service.go:479: DEBUG: Connection loop in initial rampup
[N74QT] 2024/09/12 17:58:37.575238 manager.go:120: DEBUG: cached discovery entry for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ at global@https://rsync:8443/v2/
[N74QT] 2024/09/12 17:58:37.575385 manager.go:121: DEBUG:   cache: {[quic4://rsync:22000] {13956899627676437359 773132979 0x1afc460} true {0 0 <nil>} 0}
[N74QT] 2024/09/12 17:58:37.575419 manager.go:164: DEBUG: lookup results for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ
[N74QT] 2024/09/12 17:58:37.575461 manager.go:165: DEBUG:   addresses:  [quic4://rsync:22000]
[N74QT] 2024/09/12 17:58:37.575485 service.go:657: DEBUG: Resolved device ONX5KQ3 addresses: [quic4://rsync:22000]
[N74QT] 2024/09/12 17:58:37.599662 structs.go:268: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 prio 30
[N74QT] 2024/09/12 17:58:43.647135 service.go:1172: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 error: dial: timeout: no recent network activity
[N74QT] 2024/09/12 17:58:43.647264 service.go:1202: DEBUG: failed to connect to ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ 30
[N74QT] 2024/09/12 17:58:43.647300 service.go:507: DEBUG: Next connection loop in 5s
[N74QT] 2024/09/12 17:58:48.653715 service.go:477: DEBUG: Connection loop
[N74QT] 2024/09/12 17:58:48.653762 service.go:479: DEBUG: Connection loop in initial rampup
[N74QT] 2024/09/12 17:58:48.653990 manager.go:120: DEBUG: cached discovery entry for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ at global@https://rsync:8443/v2/
[N74QT] 2024/09/12 17:58:48.654039 manager.go:121: DEBUG:   cache: {[quic4://rsync:22000] {13956899627676437359 773132979 0x1afc460} true {0 0 <nil>} 0}
[N74QT] 2024/09/12 17:58:48.654071 manager.go:164: DEBUG: lookup results for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ
[N74QT] 2024/09/12 17:58:48.654154 manager.go:165: DEBUG:   addresses:  [quic4://rsync:22000]
[N74QT] 2024/09/12 17:58:48.654240 service.go:657: DEBUG: Resolved device ONX5KQ3 addresses: [quic4://rsync:22000]
[N74QT] 2024/09/12 17:58:48.678521 structs.go:268: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 prio 30
[N74QT] 2024/09/12 17:58:58.679693 service.go:1172: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 error: dial: context deadline exceeded
[N74QT] 2024/09/12 17:58:58.679883 service.go:1202: DEBUG: failed to connect to ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ 30
[N74QT] 2024/09/12 17:58:58.679939 service.go:507: DEBUG: Next connection loop in 5s
[N74QT] 2024/09/12 17:59:03.680307 service.go:477: DEBUG: Connection loop
[N74QT] 2024/09/12 17:59:03.680375 service.go:479: DEBUG: Connection loop in initial rampup
[N74QT] 2024/09/12 17:59:03.680585 manager.go:120: DEBUG: cached discovery entry for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ at global@https://rsync:8443/v2/
[N74QT] 2024/09/12 17:59:03.680636 manager.go:121: DEBUG:   cache: {[quic4://rsync:22000] {13956899627676437359 773132979 0x1afc460} true {0 0 <nil>} 0}
[N74QT] 2024/09/12 17:59:03.680665 manager.go:164: DEBUG: lookup results for ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ
[N74QT] 2024/09/12 17:59:03.680685 manager.go:165: DEBUG:   addresses:  [quic4://rsync:22000]
[N74QT] 2024/09/12 17:59:03.680708 service.go:657: DEBUG: Resolved device ONX5KQ3 addresses: [quic4://rsync:22000]
[N74QT] 2024/09/12 17:59:03.704885 structs.go:268: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 prio 30
[monitor] 2024/09/12 17:59:04.465820 monitor.go:161: INFO: Signal 2 received; exiting
[N74QT] 2024/09/12 17:59:04.466520 service.go:1172: DEBUG: dialing ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ quic4://rsync:22000 error: dial: context canceled
[N74QT] 2024/09/12 17:59:04.466620 service.go:1202: DEBUG: failed to connect to ONX5KQ3-ST4PELN-EOLR4GG-KUDGPX3-2NCAABW-HZQKYU3-SQB75N2-YGLH7QZ 30
[N74QT] 2024/09/12 17:59:04.466654 service.go:507: DEBUG: Next connection loop in 8s
[N74QT] 2024/09/12 17:59:04.466914 quic_listen.go:150: INFO: QUIC listener (0.0.0.0:22000) shutting down
[N74QT] 2024/09/12 17:59:04.469655 syncthing.go:351: INFO: Exiting
2 
tshark -nr quic.pcap -Y quic
   16   0.312019 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 0, PADDING, CRYPTO
   17   3.684027 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 1, PADDING, CRYPTO
   18   3.684453  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=c4d499dd, SCID=dc0aabc6
   19   3.684470  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=c4d499dd, SCID=dc0aabc6
   20   3.684476  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 3, ACK
   21   4.193932 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 2, PADDING, CRYPTO
   22   4.194108  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 6, ACK
   23   4.297808 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 3, PADDING, CRYPTO
   24   4.298183  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 7, ACK
   27   4.406043 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 4, PADDING, CRYPTO
   31   4.406371  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 8, ACK
   36   4.509741 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 5, PADDING, CRYPTO
   37   4.509994  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 9, ACK
   39   4.563788 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 6, PADDING, CRYPTO
   40   4.564033  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 10, ACK
   49   4.695753 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 7, PADDING, CRYPTO
   50   4.695896  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 11, ACK
   51   4.753694 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=31d16937f74e116ae477, SCID=c4d499dd, PKN: 8, PADDING, CRYPTO
   52   4.753951  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=c4d499dd, SCID=dc0aabc6, PKN: 12, ACK
   71   5.286934  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=c4d499dd, SCID=dc0aabc6
   72   5.286952  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=c4d499dd, SCID=dc0aabc6
   73  15.482018 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=54a5ff480c62790f80ff2edcc296db, SCID=a240bbe4, PKN: 0, PADDING, CRYPTO
   74  15.583919 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=54a5ff480c62790f80ff2edcc296db, SCID=a240bbe4, PKN: 1, PADDING, CRYPTO
   75  15.584286  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=a240bbe4, SCID=08d31ca8, PKN: 1, ACK
   76  15.671884 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=54a5ff480c62790f80ff2edcc296db, SCID=a240bbe4, PKN: 2, PADDING, CRYPTO
   77  15.672210  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=a240bbe4, SCID=08d31ca8, PKN: 2, ACK
   78  15.742487 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=54a5ff480c62790f80ff2edcc296db, SCID=a240bbe4, PKN: 3, PADDING, CRYPTO
   79  15.742787  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=a240bbe4, SCID=08d31ca8, PKN: 5, ACK
   80  15.830124 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=54a5ff480c62790f80ff2edcc296db, SCID=a240bbe4, PKN: 4, PADDING, CRYPTO
   81  15.830488  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=a240bbe4, SCID=08d31ca8, PKN: 6, ACK
   82  15.884268  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=a240bbe4, SCID=08d31ca8
   83  15.884330  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=a240bbe4, SCID=08d31ca8
   84  17.485187  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=a240bbe4, SCID=08d31ca8
   85  17.485205  10.y.y.y → 10.x.x.x QUIC 958 Handshake, DCID=a240bbe4, SCID=08d31ca8
   86  25.972604 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=a14bd380581e8826, SCID=105eab5a, PKN: 0, PADDING, CRYPTO
   87  26.183995 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=a14bd380581e8826, SCID=105eab5a, PKN: 1, PADDING, CRYPTO
   88  26.184290  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=105eab5a, SCID=2db50197, PKN: 3, ACK
   89  26.272170 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=a14bd380581e8826, SCID=105eab5a, PKN: 2, PADDING, CRYPTO
   90  26.272517  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=105eab5a, SCID=2db50197, PKN: 4, ACK
   91  26.374413  10.y.y.y → 10.x.x.x QUIC 951 Handshake, DCID=105eab5a, SCID=2db50197
   92  26.374459  10.y.y.y → 10.x.x.x QUIC 951 Handshake, DCID=105eab5a, SCID=2db50197
   93  27.675759 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=2db50197, SCID=105eab5a, PKN: 3, PADDING, PING
   94  27.676072  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=105eab5a, SCID=2db50197, PKN: 7, ACK
   95  27.975923  10.y.y.y → 10.x.x.x QUIC 951 Handshake, DCID=105eab5a, SCID=2db50197
   96  27.975942  10.y.y.y → 10.x.x.x QUIC 951 Handshake, DCID=105eab5a, SCID=2db50197
   97  30.275497 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=2db50197, SCID=105eab5a, PKN: 4, PADDING, PING
   98  30.275753  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=105eab5a, SCID=2db50197, PKN: 10, ACK
   99  34.378200  10.y.y.y → 10.x.x.x QUIC 951 Handshake, DCID=105eab5a, SCID=2db50197
  100  34.378218  10.y.y.y → 10.x.x.x QUIC 951 Handshake, DCID=105eab5a, SCID=2db50197
  101  34.967441 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=2db50197, SCID=105eab5a, PKN: 5, PADDING, PING
  102  34.967690  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=105eab5a, SCID=2db50197, PKN: 11, ACK
  103  40.997868 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=4202eefc31b9a0dbe828f2f2b44c, SCID=cb37cdbb, PKN: 0, PADDING, CRYPTO
  104  41.193809 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=4202eefc31b9a0dbe828f2f2b44c, SCID=cb37cdbb, PKN: 1, PADDING, CRYPTO
  105  41.194075  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=cb37cdbb, SCID=6f485373, PKN: 1, ACK
  106  41.269574 10.x.x.x → 10.y.y.y  QUIC 1322 Initial, DCID=4202eefc31b9a0dbe828f2f2b44c, SCID=cb37cdbb, PKN: 2, PADDING, CRYPTO
  107  41.269874  10.y.y.y → 10.x.x.x QUIC 83 Initial, DCID=cb37cdbb, SCID=6f485373, PKN: 4, ACK
  108  41.399935  10.y.y.y → 10.x.x.x QUIC 960 Handshake, DCID=cb37cdbb, SCID=6f485373
  109  41.399955  10.y.y.y → 10.x.x.x QUIC 960 Handshake, DCID=cb37cdbb, SCID=6f485373
  110  43.002442  10.y.y.y → 10.x.x.x QUIC 960 Handshake, DCID=cb37cdbb, SCID=6f485373
  111  43.002461  10.y.y.y → 10.x.x.x QUIC 960 Handshake, DCID=cb37cdbb, SCID=6f485373
3

listenAddress1 is intentionally miswritten so I can disable it from from config during testing QUIC while I don’t have to delete it completely. they’re ignored

4

the single node is an old fedora core 22 machine and there is no way I can change that. the other node with all services is an EL7 clone

5

This would indicate that there isn’t any reply from the other side.

Can you start one side with the following environment variable?

QUIC_GO_LOG_LEVEL=DEBUG
1 Like
6

peer x.x.x An error occurred, Body is limited to 32000 characters, you entered 43421.txt (42.8 KB)

peer y.y.y An error occurred, Body is limited to 32000 characters, you entered 43421 yyy.txt (98.4 KB)

8

wait. I just re-tested using netcat and I am not receiving everything that I paste on one end. I need to dig what’s happening down at ip/udp level. I was fooled initially by only typing a few characters, but pasted a copy paste from a random webpage and not all text went through!

1 Like
9

yup, one sending side is losing ipsec sequence numbers - application is sending data, on the wire goes out less packets than what came from the userspace.

definitely not a syncthing issue. will retest after I find a workaround. probably tcp handles this with retransmissions, that’s why it “works”

1 Like
10

After a bit more investigation today, my conclusion is quic is not going well with small mtu.

I simulated the connection with caddy webserver on one side and a recent curl client on the other and forced curl to go over udp exclusively. I choose caddy because it is based on the same quic-go project like syncthing.

However caddy + curl manage to talk to each other and establish handshake and transfer data, whereas syncthing does not.

Given that my tests show no significant speed advantage over tcp for this high latency low bandwidth cellular link, I am giving up on quic anyway.

But conclusion is there is still something wrong on syncthing quic, however I am not going to pursue troubleshooting further.

The netcat issue I observed could be some terminal wtf, as doing it via cat file | nc works, while mouse pasting doesn’t.

Anyway it’s a 10 year old system probably full of bugs to which nobody would allocate further resources to debug this corner case. I’ll see if a LAN client on modern OS though works fine with quic.

11

I’m curious though why would QUIC_GO_LOG_LEVEL=DEBUG say these in the logs (the attached long text logs)

2024/09/16 19:27:18 server Dropping a packet that is too small to be a valid Initial (41 bytes)
2024/09/16 19:27:18 server Dropping a packet that is too small to be a valid Initial (41 bytes)
2024/09/16 19:27:18 server Dropping a packet that is too small to be a valid Initial (41 bytes)
2024/09/16 19:27:18 server Dropping a packet that is too small to be a valid Initial (41 bytes)
2024/09/16 19:27:18 server Dropping long header packet of type Handshake (916 bytes)
2024/09/16 19:27:18 server Dropping long header packet of type Handshake (916 bytes)
2024/09/16 19:27:19 Tracking 0 connection IDs and 0 reset tokens.
2024/09/16 19:27:20 server Dropping long header packet of type Handshake (916 bytes)
2024/09/16 19:27:20 server Dropping long header packet of type Handshake (916 bytes)
12

You’d need to ask on the quic issue tracker. We’re just users of a library.

13

That might trigger a few bugs. quic-go disables GSO on these old installations. Maybe you’re hitting some other UDP quirks as well.