Syncthing v1.14.0 sometimes fails to start "address already in use" Ubuntu 20.04

tomwaldnz · March 11, 2021, 4:06am

I’ve had syncthing installed on Ubuntu 20.04 for a few months and it’s been working fine. It’s an AWS t3a.micro server I turn on occasionally, running LEMP stack which I’m configuring when I get time. The server has plenty of RAM / CPU. I started the server today and found Syncthing isn’t working.

The key problems seem to be

WARNING: Starting API/GUI: listen tcp 0.0.0.0:8384: bind: address already in use

and

INFO: Failed initial scan of sendreceive folder "FOLDER1" (redacted)

An interesting observation is Syncthing sometimes starts. I can see on 7 March

Mar  7 18:00:39 ip-11-0-1-150 syncthing[3523]: [redacted] INFO: GUI and API listening on [::]:8384

I’ve tried:

Stopped the syncthing service and tried telnetting to localhost 8384 but got “connection refused”. I’ve shown the output of netstat below
Couple of server reboots - it’s an AWS EC2 instance
Downgrading to Syncthing 1.13.1 and got very similar messages. Logs below.
Checked syslog going back a while. I can see now that this was happening 22nd Jan on syncthing v1.12.1, but syncthing

I’m happy to post any parts of the config anyone thinks would be useful but a quick lok through I’m not sure what would be needed. My Linux skills are ok for a non-admin but I’m not an expert by any means.

Any ideas how to troubleshoot this would be appreciated

Syncthing 1.14 logs

Mar 11 02:58:36 ip-11-0-1-150 kernel: [    3.336642] systemd[1]: Created slice system-syncthing.slice.
Mar 11 02:58:37 ip-11-0-1-150 syncthing[482]: [start] INFO: syncthing v1.14.0 "Fermium Flea" (go1.16 linux-amd64) deb@build.syncthing.net 2021-02-26 12:21:13 UTC [noupgrade]
Mar 11 02:58:37 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: My ID: (redacted)
Mar 11 02:58:38 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Single thread SHA256 performance is 463 MB/s using minio/sha256-simd (59 MB/s using crypto/sha256).
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Hashing performance is 342.44 MB/s
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Overall send rate is unlimited, receive rate is unlimited
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Using discovery mechanism: global discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Using discovery mechanism: global discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Using discovery mechanism: global discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Using discovery mechanism: IPv4 local broadcast discovery on port 21027
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Using discovery mechanism: IPv6 local multicast discovery on address [ff12::8384]:21027
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: TCP listener ([::]:8384) starting
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Ready to synchronize "Default Folder" (default) (sendreceive)
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Ready to synchronize "FOLDER1" (redacted) (sendreceive)
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Ready to synchronize "FOLDER2" (redacted) (sendreceive)
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] WARNING: Failed starting API: listen tcp 0.0.0.0:8384: bind: address already in use
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Detected 0 NAT services
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Failed initial scan of sendreceive folder "FOLDER1" (redacted)
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Ready to synchronize "FOLDER3" (redacted) (sendreceive)
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Completed initial scan of sendreceive folder "Default Folder" (default)
Mar 11 02:58:39 ip-11-0-1-150 syncthing[482]: [XXXXX] WARNING: Starting API/GUI: listen tcp 0.0.0.0:8384: bind: address already in use
Mar 11 02:58:40 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: TCP listener ([::]:8384) shutting down
Mar 11 02:58:40 ip-11-0-1-150 syncthing[482]: [XXXXX] INFO: Exiting
Mar 11 02:58:40 ip-11-0-1-150 systemd[1]: syncthing@st.service: Main process exited, code=exited, status=1/FAILURE
Mar 11 02:58:40 ip-11-0-1-150 systemd[1]: syncthing@st.service: Failed with result 'exit-code'.
Mar 11 02:58:45 ip-11-0-1-150 systemd[1]: syncthing@st.service: Scheduled restart job, restart counter is at 1.

Syncthing 1.13.1 Logs

runuser -l st  -c 'syncthing -allow-newer-config'
[start] 03:56:18 INFO: syncthing v1.13.1 "Fermium Flea" (go1.15.7 linux-amd64) deb@build.syncthing.net 2021-01-11 14:15:21 UTC [noupgrade]
[start] 03:56:18 INFO: Archiving a copy of old config file format at: /home/st/.config/syncthing/config.xml.v35
[redacted] 03:56:18 INFO: My ID: (redacted)
[redacted] 03:56:19 INFO: Single thread SHA256 performance is 1192 MB/s using minio/sha256-simd (273 MB/s using crypto/sha256).
[redacted] 03:56:20 INFO: Hashing performance is 697.54 MB/s
[redacted] 03:56:20 INFO: Overall send rate is unlimited, receive rate is unlimited
[redacted] 03:56:20 INFO: Using discovery mechanism: global discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[redacted] 03:56:20 INFO: Using discovery mechanism: global discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[redacted] 03:56:20 INFO: Using discovery mechanism: global discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
[redacted] 03:56:20 INFO: Using discovery mechanism: IPv4 local broadcast discovery on port 21027
[redacted] 03:56:20 INFO: Using discovery mechanism: IPv6 local multicast discovery on address [ff12::8384]:21027
[redacted] 03:56:20 INFO: Ready to synchronize "Default Folder" (default) (sendreceive)
[redacted] 03:56:20 INFO: Ready to synchronize "FOLDER1" (o9rsc-bc79r) (sendreceive)
[redacted] 03:56:20 INFO: Ready to synchronize "FOLDER2" (trmva-rhvay) (sendreceive)
[redacted] 03:56:20 INFO: TCP listener ([::]:8384) starting
[redacted] 03:56:20 INFO: Ready to synchronize "FOLDER3" (zeteq-4qytf) (sendreceive)
[redacted] 03:56:20 INFO: Completed initial scan of sendreceive folder "Default Folder" (default)
[redacted] 03:56:20 WARNING: Failed starting API: listen tcp 0.0.0.0:8384: bind: address already in use
[redacted] 03:56:20 INFO: Failed initial scan of sendreceive folder "FOLDER1" (redacted)
[redacted] 03:56:20 INFO: Failed initial scan of sendreceive folder "FOLDER3" (redacted)
[redacted] 03:56:20 INFO: Failed initial scan of sendreceive folder "FOLDER2" (redacted)
[redacted] 03:56:20 INFO: Detected 0 NAT services
[redacted] 03:56:20 WARNING: Starting API/GUI: listen tcp 0.0.0.0:8384: bind: address already in use
[redacted] 03:56:21 INFO: TCP listener ([::]:8384) shutting down
[redacted] 03:56:21 INFO: Exiting

Telnet

systemctl stop syncthing@st.service
telnet localhost 8384
Trying 127.0.0.1...
telnet: Unable to connect to remote host: Connection refused

Netstat

netstat -ltnp
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.53:53           0.0.0.0:*               LISTEN      420/systemd-resolve
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      852/sshd: /usr/sbin
tcp        0      0 0.0.0.0:443             0.0.0.0:*               LISTEN      565/nginx: master p
tcp        0      0 0.0.0.0:3306            0.0.0.0:*               LISTEN      587/mysqld
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      565/nginx: master p
tcp6       0      0 :::22                   :::*                    LISTEN      852/sshd: /usr/sbin
tcp6       0      0 :::33060                :::*                    LISTEN      587/mysqld

calmh · March 11, 2021, 5:40am

You’ve configured it to use the same port for the sync listen address and the gui. Reset the sync listen port back to default and you’ll be fine.

tomwaldnz · March 11, 2021, 6:24am

Thanks @calmh that makes sense! Do you have any tips where that config is done, or a documentation page link / to search for? I’m still fairly new to Syncthing.

bt90 · March 11, 2021, 7:14am

@calmh i didn’t have my first coffee but isn’t the listenAddress example in the docs wrong?

https://docs.syncthing.net/users/config.html#config-file-format

tomwaldnz · March 11, 2021, 7:23am

@bt90 I think you’re right - looks like the and section are both saying to use port 8384, clearly that’s not going to work. I found the config.xml file and I have configured both services for the same port - just like the documentation says to do!

Should we specify ports there, or should we just leave it as “default” as I’ve put in the “My PC” section below.

Current Docs

  <gui enabled="true" tls="false" debugging="false">
    <address>127.0.0.1:8384</address>
  </gui>
  <options>
    <listenAddress>tcp://0.0.0.0:8384</listenAddress>
  </options>

My PC

  <gui enabled="true" tls="false" debugging="false">
    <listenAddress>default</listenAddress>
  </gui>
  <options>
    <listenAddress>tcp://0.0.0.0:21027</listenAddress>
  </options>

tomwaldnz · March 11, 2021, 7:35am

Ok, this is resolved now thanks to @calmh working out the problem and @bt90 pointing me in the right direction I changed my config file ( /home/st/.config/syncthing/config.xml ) from this

<options>
    <listenAddress>tcp://0.0.0.0:8384</listenAddress>

to this

<options>
    <listenAddress>default</listenAddress>

Another unrelated quick query…

I see the following in the Syncthing log on my PC, 20 times in a row. I also seem to be using a relay server to connect from my PC to my AWS server. Is there a guide about this kind of thing, or should I post another question?

Connected to myself (redacted) at [::]:22000-x.x.x.x:22000/quic-client/TLS1.3-TLS_AES_128_GCM_SHA256 - should not happen

bt90 · March 11, 2021, 8:18am

This kind of thing can happen with two or more devices in behind the same router AFAIK. Your device tries several addresses to connect to the other device. If it tries to connect to the external address with the default port it will connect to itself.

That said this isn’t really that problematic and the logging is overly dramatic.

Are ports 22000/tcp and 22000/udp open in the firewall of your VM?

IMHO the firewall section of the docs should tell you everything you need to know

imsodin · March 11, 2021, 9:06am

Good catch: user/config: Fix incorrect listen address by imsodin · Pull Request #626 · syncthing/docs · GitHub

tomwaldnz · March 11, 2021, 5:57pm

Thanks, I opened the server ports and have a direct connection now I’ll read the firewall docs again too.

system · April 10, 2021, 5:57pm

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