Web GUI refusing connections

InteXX · May 26, 2021, 11:31pm

I had this running quite well on our ReadyNAS device. In fact, it synced 1.3TB before it quit.

But I had to restart the device for something else, and afterward the Syncthing service wasn’t running:

root@BACKUP1:~# systemctl status syncthing@admin
● syncthing@admin.service - Syncthing - Open Source Continuous File Synchronization for admin
   Loaded: loaded (/lib/systemd/system/syncthing@.service; enabled; vendor preset: enabled)
   Active: activating (auto-restart) (Result: exit-code) since Wed 2021-05-26 15:02:48 AKDT; 827ms ago
     Docs: man:syncthing(1)
  Process: 11996 ExecStart=/usr/bin/syncthing serve --no-browser --no-restart --logflags=0 (code=exited, status=1/FAILURE)
 Main PID: 11996 (code=exited, status=1/FAILURE)

May 26 15:02:48 BACKUP1 systemd[1]: syncthing@admin.service: Unit entered failed state.
May 26 15:02:48 BACKUP1 systemd[1]: syncthing@admin.service: Failed with result 'exit-code'.

Oddly, however, when I ran the same command just a few seconds later, I got this:

root@BACKUP1:~# systemctl status syncthing@admin
● syncthing@admin.service - Syncthing - Open Source Continuous File Synchronization for admin
   Loaded: loaded (/lib/systemd/system/syncthing@.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2021-05-26 15:03:11 AKDT; 290ms ago
     Docs: man:syncthing(1)
 Main PID: 12242 (syncthing)
   CGroup: /system.slice/system-syncthing.slice/syncthing@admin.service
           ├─12242 /usr/bin/syncthing serve --no-browser --no-restart --logflags=0
           └─12251 /usr/bin/syncthing serve --no-browser --no-restart --logflags=0

May 26 15:03:11 BACKUP1 systemd[1]: Started Syncthing - Open Source Continuous File Synchronization for admin.
May 26 15:03:11 BACKUP1 syncthing[12242]: [start] INFO: syncthing v1.15.1 "Fermium Flea" (go1.16.3 linux-amd64) deb@build.syncthing.net 2021-04-06 08:42:29 UTC [noupgrade]
May 26 15:03:11 BACKUP1 syncthing[12242]: [start] INFO: Using large-database tuning
May 26 15:03:12 BACKUP1 syncthing[12242]: [V4C2B] INFO: My ID: [REDACTED]

Did my simple act of checking on the status start the service? Don’t systemd services auto start?

Anyway, now the GUI won’t respond. Chrome returns an ERR_CONNECTION_REFUSED.

Also, the lone peer (an RPi device with a USB drive attached) reports this:

unexpected device id, expected [REDACTED] got [REDACTED] (15:18:09)

What to make of all this? How can I get things back up and running and make sure the service auto starts correctly?

Nummer378 · May 26, 2021, 11:40pm

Yes and No. This depends on the type of the service (e.g user vs system service) and if the service is enabled or not.

Your configuration shows Loaded: loaded (/lib/systemd/system/syncthing@.service; enabled; vendor preset: enabled), which means that the service is enabled and auto-starting at system boot.

Systemd usually auto-restarts services when they crash. When you first executed the command, the service had just crashed and was in the process of restarting automatically, see your inital output:

Active: activating (auto-restart) (Result: exit-code) since Wed 2021-05-26 15:02:48 AKDT; 827ms ago

Naturally, a few seconds after the auto-restart everything is up and running again. As to why it crashed in the first place - no idea, probably need to look at more detailed logs.

InteXX · May 27, 2021, 2:08am

Thanks for the info, that helps.

I’d love to, but I don’t know how to get at them.

The FAQ provides us this:

“If you’re running a process manager like systemd, check there”

Unfortunately, however, this isn’t helpful if one isn’t familiar with exactly where that location is.

Are you suspecting that the logs might tell us why the browser can’t connect to the GUI, as well as why the peer is getting the unexpected device id?

AudriusButkevicius · May 27, 2021, 7:21am

Yes, but this is a systemd question how to access the logs.

There are tons of package managers under the sun, we can’t list how to check logs for everyone of them.

I am sure a quick google search will answer your question of how to do it.

bt90 · May 27, 2021, 9:33am

You can check the logs using:

journalctl -u syncthing@admin

InteXX · May 27, 2021, 8:29pm

I have to admit you lost me with that one.

To my knowledge, I’m not using a package manager. Further, I’m not sure how a package manager is related to the log file location.

Google searches for this problem turned up empty, which is why I posted here.

InteXX · May 27, 2021, 8:33pm

OK, that worked.

It seems I’m caught in a loop, with the service constantly restarting and then crashing:

May 27 12:17:47 BACKUP1 systemd[1]: Started Syncthing - Open Source Continuous File Synchronization for admin.
May 27 12:17:47 BACKUP1 syncthing[25918]: [start] INFO: syncthing v1.15.1 "Fermium Flea" (go1.16.3 linux-amd64) deb@build.syncthing.net 2021-04-06 08:42:29 UTC [noupgrade]
May 27 12:17:47 BACKUP1 syncthing[25918]: [start] INFO: Using large-database tuning
May 27 12:17:47 BACKUP1 syncthing[25918]: [V4C2B] INFO: My ID: [REDACTED]
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Single thread SHA256 performance is 252 MB/s using minio/sha256-simd (233 MB/s using crypto/sha256).
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Hashing performance is 214.79 MB/s
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Overall send rate is unlimited, receive rate is unlimited
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Listen (BEP/quic): listen udp 0.0.0.0:22000: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Using discovery mechanism: global discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Using discovery mechanism: global discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Using discovery mechanism: global discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: c.S.listenerSupervisor: Failed service 'quic://0.0.0.0:22000' (1.000000 failures of 2.000000), restarting: true, error: listen udp 0.0.0.0:22000: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Using discovery mechanism: IPv4 local broadcast discovery on port 21027
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Using discovery mechanism: IPv6 local multicast discovery on address [ff12::8384]:21027
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Listen (BEP/quic): listen udp 0.0.0.0:22000: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Listen (BEP/tcp): listen tcp 0.0.0.0:22000: listen: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: c.S.listenerSupervisor: Failed service 'quic://0.0.0.0:22000' (1.999998 failures of 2.000000), restarting: true, error: listen udp 0.0.0.0:22000: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: c.S.listenerSupervisor: Entering the backoff state.
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: c.S.listenerSupervisor: Failed service 'tcp://0.0.0.0:22000' (2.999997 failures of 2.000000), restarting: false, error: listen tcp 0.0.0.0:22000: listen: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Listen (BEP/quic): listen udp 0.0.0.0:22000: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: c.S.listenerSupervisor: Entering the backoff state.
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: c.S.listenerSupervisor: Failed service 'quic://0.0.0.0:22000' (3.999984 failures of 2.000000), restarting: false, error: listen udp 0.0.0.0:22000: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Ready to synchronize "Files" [REDACTED] (sendreceive)
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] WARNING: Failed starting API: listen tcp 0.0.0.0:8384: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) shutting down
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Failed initial scan of sendreceive folder "Files" [REDACTED]
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] WARNING: Starting API/GUI: listen tcp 0.0.0.0:8384: bind: address already in use
May 27 12:17:48 BACKUP1 syncthing[25918]: [V4C2B] INFO: Exiting
May 27 12:17:48 BACKUP1 systemd[1]: syncthing@admin.service: Main process exited, code=exited, status=1/FAILURE
May 27 12:17:48 BACKUP1 systemd[1]: syncthing@admin.service: Unit entered failed state.
May 27 12:17:48 BACKUP1 systemd[1]: syncthing@admin.service: Failed with result 'exit-code'.
May 27 12:17:49 BACKUP1 systemd[1]: syncthing@admin.service: Service hold-off time over, scheduling restart.
May 27 12:17:49 BACKUP1 systemd[1]: Stopped Syncthing - Open Source Continuous File Synchronization for admin.

Apparently there’s some sort of ‘shadow process’ already using these ports.

I’m completely lost on how to troubleshoot this (let alone fix it).

bt90 · May 27, 2021, 8:51pm

bind: address already in use

You can use the following command to check which process is using the port:

sudo netstat -tulpn

InteXX · May 27, 2021, 9:30pm

Aha. I’m a bit closer now, thank you.

I’ve got these seven entries for Syncthing:

root@BACKUP1:~# netstat -tulpn
tcp        0      0 127.0.0.1:8384          0.0.0.0:*               LISTEN      5904/syncthing
tcp6       0      0 :::22000                :::*                    LISTEN      5904/syncthing
udp        0      0 0.0.0.0:21027           0.0.0.0:*                           5904/syncthing
udp        0      0 0.0.0.0:42292           0.0.0.0:*                           5904/syncthing
udp6       0      0 :::21027                :::*                                5904/syncthing
udp6       0      0 :::22000                :::*                                5904/syncthing
udp6       0      0 :::35869                :::*                                5904/syncthing

I assume from this that only the first two are actually listening. Please confirm.

I believe the 8384 entry gives us our clue. Notice how it’s listening on the loopback only, not any IP (my preference).

That’s not how it should be working. Here’s the relevant entry from my config.xml:

<gui enabled="true" tls="false" debugging="false">
  <address>0.0.0.0:8384</address>
  <user>npg.admin</user>
  <password>[REDACTED]</password>
  <apikey>[REDACTED]</apikey>
  <theme>default</theme>
</gui>

Keeping in mind that this only began after a device restart, there must be another ‘instance’ of the service configured to start up at boot time.

Can you think of a way I might be able to track this other one down?

AudriusButkevicius · May 27, 2021, 10:00pm

Check the process tree ps auxwwf | grep syncthing. You should see who it’s running as, and potentially if the home directory is overriden.

InteXX · May 27, 2021, 10:38pm

Yep, it’s doubled up alright:

root@BACKUP1:~# ps auxwwf | grep syncthing
root      5860  0.0  0.2 726364 18336 ?        Ssl  May19   0:25 /usr/bin/syncthing serve --no-browser --no-restart --logflags=0
root      5904  0.2  0.8 796448 70480 ?        SNl  May19  30:08  \_ /usr/bin/syncthing serve --no-browser --no-restart --logflags=0
root      6208  0.0  0.0  17836   984 pts/0    S+   14:33   0:00  |       \_ grep syncthing
admin     6184  1.0  0.1 723228 15964 ?        Ssl  14:33   0:00 /usr/bin/syncthing serve --no-browser --no-restart --logflags=0
admin     6195 70.0  0.2 861604 23976 ?        Rl   14:33   0:00  \_ /usr/bin/syncthing serve --no-browser --no-restart --logflags=0

I betcha this is a throwback from this earlier problem. I betcha that original instance is still installed and is creating havoc.

I knew I wanted to remove that first installation completely—now I know why.

What would your next step be, if this were on your system?

AudriusButkevicius · May 27, 2021, 10:47pm

Not sure. Undo whatever you did when you first installed it.

I guess you could look at the rest of the process tree to see if you can track down what launched it etc.

Given it came back after reboot, something does start it, so I think just killing it won’t help.

InteXX · May 27, 2021, 11:53pm

Bingo, that was it. I just needed a gentle nudge in the right direction

I did this:

root@BACKUP1:~# systemctl status syncthing@root.service

…saw that it was running, and then did this:

root@BACKUP1:~# systemctl stop syncthing@root.service
root@BACKUP1:~# systemctl disable syncthing@root.service

A quick:

root@BACKUP1:~# systemctl status syncthing@root.service

…revealed that it was truly dead, so I tried browsing to the GUI. Success.

Everything fell into place on its own with the peer, and 3GB of new/updated files synced without me having to do anything more.

Just to be safe, I rebooted the device and ran another ps auxwwf | grep syncthing. Problem solved. (Although I would someday like to learn how to fully clean out those files/settings from when I was incorrectly running the service under root.)

So thanks for the nudge

system · June 26, 2021, 11:54pm

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