UPnP not happening

#1

I am running 0.14.36 and have NAT Traversal enabled in the settings. The router syncthing is behind is UPnP enabled (other apps successfully use it that way). However, I can’t see anything in the logs about syncthing attempting to create UPnP port mapping. This is confirmed by checking the mapped ports with upnpc.

Any ideas on how I can get UPnP working?

(Simon) #2

Enable the upnp debug facility. In your version probably only through STTRACE env var, but I’d generally just upgrade first, which besides many other benefits will give you a log view in the web UI and we don’t actually debug ancient versions.

(Audrius Butkevicius) #3

It probably fails to find upnp devices, potentially because of firewalls or network configuration.

#4

Ok, I upgraded to 1.1.1 and enabled upnp debugging via the GUI. Don’t see anything in the logs yet besides:

2019-05-03 06:25:37 Detected 1 NAT service

How often will it attempt to create a port mapping?

#5

Here are the logs:

2019-05-03 06:55:27 Starting discovery of device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
2019-05-03 06:55:27 Starting discovery of device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
2019-05-03 06:55:27 Sending search request for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
2019-05-03 06:55:27 Sending search request for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
2019-05-03 06:55:27 Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
2019-05-03 06:55:27 Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
2019-05-03 06:55:37 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0 finished.
2019-05-03 06:55:37 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0 finished.
(Jakob Borg) #6

I don’t think Syncthing logs created port mappings, so this is not a good basis for assuming port mappings don’t happen.

#7

My basis is that checking the ports with the upnpc command does not show any that syncthing would use.

(Audrius Butkevicius) #8

If you provided the full logs it might be more obvious.

#9

Here are the full logs from the restart:

2019-05-05 16:03:25 syncthing v1.1.1 "Erbium Earthworm" (go1.11.5 linux-amd64) unknown-user@9b54055ad277 2019-04-16 18:39:31 UTC
2019-05-05 16:03:25 My ID: KTBACKG-ZALUFDI-QBZ77VB-JGL6P4F-7OOWJHE-XHBC7VB-WIKAXRX-BCUPYAS
2019-05-05 16:03:26 Single thread SHA256 performance is 316 MB/s using minio/sha256-simd (196 MB/s using crypto/sha256).
2019-05-05 16:03:27 Hashing performance is 272.71 MB/s
2019-05-05 16:03:28 Ready to synchronize "Default Folder" (default) (sendreceive)
2019-05-05 16:03:28 Ready to synchronize "radarr" (gndsh-mnvsv) (sendreceive)
2019-05-05 16:03:28 Ready to synchronize "sonarr" (zhhqc-nsznn) (sendreceive)
2019-05-05 16:03:28 Overall send rate is unlimited, receive rate is unlimited
2019-05-05 16:03:28 Using discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2019-05-05 16:03:28 Using discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2019-05-05 16:03:28 ...
2019-05-05 16:03:28 Using discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2019-05-05 16:03:28 Completed initial scan of sendreceive folder "Default Folder" (default)
2019-05-05 16:03:28 TCP listener ([::]:22000) starting
2019-05-05 16:03:28 Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
2019-05-05 16:03:28 Completed initial scan of sendreceive folder "radarr" (gndsh-mnvsv)
2019-05-05 16:03:28 GUI and API listening on [::]:8384
2019-05-05 16:03:28 Access the GUI via the following URL: http://127.0.0.1:8384/
2019-05-05 16:03:28 My name is "plex-sync"
2019-05-05 16:03:28 Device PULDPYB-UCMUIQ7-IK6PVG6-IYABRWH-3WFGRXJ-2DJCJ2G-BLBOFAN-K5Q4LQG is "whatbox.ca" at [dynamic]
2019-05-05 16:03:28 Device XZTODMH-73XAN2I-T26WE7F-6TYW6MF-AQZKNF3-TVE35FB-H63SNEE-24SCOAP is "chadikins" at [dynamic]
2019-05-05 16:03:30 Completed initial scan of sendreceive folder "sonarr" (zhhqc-nsznn)
2019-05-05 16:03:31 Established secure connection to XZTODMH-73XAN2I-T26WE7F-6TYW6MF-AQZKNF3-TVE35FB-H63SNEE-24SCOAP at 172.17.0.3:36748-198.27.241.245:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
2019-05-05 16:03:31 Device XZTODMH-73XAN2I-T26WE7F-6TYW6MF-AQZKNF3-TVE35FB-H63SNEE-24SCOAP client is "syncthing v0.14.54" named "298eaebc24e6" at 172.17.0.3:36748-198.27.241.245:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
2019-05-05 16:03:48 Detected 1 NAT service
2019-05-05 16:04:02 Enabled debug data for "upnp"
2019-05-05 16:04:14 Joined relay relay://172.245.135.170:22067
2019-05-05 16:08:44 Established secure connection to PULDPYB-UCMUIQ7-IK6PVG6-IYABRWH-3WFGRXJ-2DJCJ2G-BLBOFAN-K5Q4LQG at 172.17.0.3:34108-172.245.135.170:22067/relay-server/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
2019-05-05 16:08:44 Device PULDPYB-UCMUIQ7-IK6PVG6-IYABRWH-3WFGRXJ-2DJCJ2G-BLBOFAN-K5Q4LQG client is "syncthing v1.1.1" named "whatbox.ca" at 172.17.0.3:34108-172.245.135.170:22067/relay-server/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
(Audrius Butkevicius) #10

You enabled upnp logging after upnp discovery cycle has completed, so there is not much use out of these logs. I suggest you enable logging via an env var before startup.

#11

Ok, after enabling STTRACE=upnp, here are the logs:

2019-05-07 07:35:15 syncthing v1.1.1 "Erbium Earthworm" (go1.11.5 linux-amd64) unknown-user@9b54055ad277 2019-04-16 18:39:31 UTC
2019-05-07 07:35:15 My ID: KTBACKG-ZALUFDI-QBZ77VB-JGL6P4F-7OOWJHE-XHBC7VB-WIKAXRX-BCUPYAS
2019-05-07 07:35:15 Single thread SHA256 performance is 315 MB/s using minio/sha256-simd (196 MB/s using crypto/sha256).
2019-05-07 07:35:16 Hashing performance is 272.12 MB/s
2019-05-07 07:35:17 Ready to synchronize "sonarr" (zhhqc-nsznn) (sendreceive)
2019-05-07 07:35:17 Ready to synchronize "Default Folder" (default) (sendreceive)
2019-05-07 07:35:17 Ready to synchronize "radarr" (gndsh-mnvsv) (sendreceive)
2019-05-07 07:35:17 Overall send rate is unlimited, receive rate is unlimited
2019-05-07 07:35:17 Using discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2019-05-07 07:35:17 Using discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2019-05-07 07:35:17 ...
2019-05-07 07:35:17 Using discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW
2019-05-07 07:35:17 TCP listener ([::]:22000) starting
2019-05-07 07:35:17 Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting
2019-05-07 07:35:17 Starting discovery of device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
2019-05-07 07:35:17 Sending search request for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
2019-05-07 07:35:17 Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
2019-05-07 07:35:17 Starting discovery of device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
2019-05-07 07:35:17 Sending search request for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
2019-05-07 07:35:17 Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
2019-05-07 07:35:17 Completed initial scan of sendreceive folder "Default Folder" (default)
2019-05-07 07:35:17 Completed initial scan of sendreceive folder "radarr" (gndsh-mnvsv)
2019-05-07 07:35:17 GUI and API listening on [::]:8384
2019-05-07 07:35:17 Access the GUI via the following URL: http://127.0.0.1:8384/
2019-05-07 07:35:17 My name is "plex-sync"
2019-05-07 07:35:17 Device PULDPYB-UCMUIQ7-IK6PVG6-IYABRWH-3WFGRXJ-2DJCJ2G-BLBOFAN-K5Q4LQG is "whatbox.ca" at [dynamic]
2019-05-07 07:35:17 Device XZTODMH-73XAN2I-T26WE7F-6TYW6MF-AQZKNF3-TVE35FB-H63SNEE-24SCOAP is "chadikins" at [dynamic]
2019-05-07 07:35:19 Established secure connection to XZTODMH-73XAN2I-T26WE7F-6TYW6MF-AQZKNF3-TVE35FB-H63SNEE-24SCOAP at 172.17.0.3:47148-198.27.241.245:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
2019-05-07 07:35:19 Device XZTODMH-73XAN2I-T26WE7F-6TYW6MF-AQZKNF3-TVE35FB-H63SNEE-24SCOAP client is "syncthing v0.14.54" named "298eaebc24e6" at 172.17.0.3:47148-198.27.241.245:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
2019-05-07 07:35:22 Completed initial scan of sendreceive folder "sonarr" (zhhqc-nsznn)
2019-05-07 07:35:27 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0 finished.
2019-05-07 07:35:27 Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0 finished.
2019-05-07 07:35:37 Detected 1 NAT service
2019-05-07 07:35:51 Joined relay relay://199.181.238.100:22067

The UPnP router definitely works (confirmed with upnpc -l), but I’m thinking this is not working because the syncthing is running inside a Docker container…

(Audrius Butkevicius) #12

Docker has it’s own networking, so it won’t work, it’s probably discovering something that is not your gateway.

You need to run with --net=host, also capture the logs from the console not the web ui as the logs in the web ui are partial.

1 Like
#13

Yeah, running it with --net=host seemed to work, the NAT port mapping is now created. Thanks for your help.