syncthing / syncthing

Open Source Continuous File Synchronization
https://forum.syncthing.net/
Mozilla Public License 2.0
61.85k stars 4.12k forks source link

UPnP error messages #9324

Open peterGo opened 5 months ago

peterGo commented 5 months ago

After upgrading to syncthing v1.27.2, there are numerous UPnP error messages.

For example,

[664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 43417 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 48502 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718)

[664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 40832 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 14000 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 63899 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 24079 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 24030 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 45446 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 13399 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 14567 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 34823 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718) [664CR] 2024/01/06 00:07:57 INFO: Couldn't add port mapping for 192.168.1.11 (external port 24535 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718)

Reference:

Add UPnP support for IPv6 https://github.com/syncthing/syncthing/issues/7406

bt90 commented 5 months ago

Let's dissect this:

INFO: Couldn't add port mapping for 192.168.1.11 (external port 43417 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718)

Your router won't accept the mapping because it conflicts with an existing one. This happens for every external port we've tried, which leads me to believe that your router has faulty conflict detection logic.

We have seen this problem with AVM FritzBox devices. In this particular case, any mapping to the same internal port on a different LAN IP generated this error. The manufacturer has confirmed this as a bug.

INFO: New external port opened: external TCP address(es) [192.168.201.90:31845] to local address [::]:22000.

This looks like a successful mapping, although I'm a bit confused by the IP here. All other attempts used 192.168.1.11. Does your machine have multiple IPs on the same network?

calmh commented 5 months ago

Or it is because we already have a mapping on that port and are trying again because we're looping over multiple announced ... somethings? If so this would be a problem as we might create infinite amount of mappings?

bt90 commented 5 months ago

Or it is because we already have a mapping on that port

Conflict detection is based on the tuple external port + internal IP + internal port. Unless the vendor has screwed up, we shouldn't be able to trigger that many conflicts because we use a different external port each time. The default port is only used on the first attempt.

and are trying again because we're looping over multiple announced ... somethings?

This used to be the case. We now prioritise IGDv2 when the router announces support for both IGDv1 and IGDv2. In practice, we should end up with less noise than before.

If so this would be a problem as we might create infinite amount of mappings?

Syncthing hasn't been able to create a mapping for 192.168.1.11 and the number of attempts is limited. This mechanism is in place because there is no guarantee that the external port isn't already mapped to another Syncthing instance or occupied by another service.

peterGo commented 5 months ago

The WiFi router is a Netgear R6220:

AC1200 WiFi Router (R6220)
Dual-Band WiFi Router
https://www.netgear.com/home/wifi/routers/r6220/

Support / R6220
R6220 — AC1200 Smart WiFi Router
Model / Version: R6220
https://www.netgear.com/support/product/r6220
Documentation and Downloads

The WiFi router has been reset to restore the factory settings.

The WiFi router has been updated to firmware version V1.1.0.114_1.0.1.

After running syncthing v1.27.2 "Gold Grasshopper" on several Linux and Windows machines, only one entry appears in the UPnP Portmap Table:

R6220 UPnP

There are numerous log information messages of the form:

INFO: Couldn't add port mapping for 192.168.1.2 (external port 11578 -> internal port 22000/TCP): UPnP Error: ConflictInMappingEntry (718)

The WiFi router LAN is used to share multiple Linux and Windows machines. Network addresses are obtained using DHCP. The WiFi router has Ethernet network connections to the internet and a laser printer.

acolomb commented 5 months ago

I can confirm that there are numerous messages of this type, presumably because we are trying port mappings that either already succeeded previously, thus conflict, or are somehow inappropriate for the router. And we do try that again every few minutes, which makes for a log full of these lines.

I guess we need to dig deeper into that retry mechanism and revisit #9010, @maxi0604 ?

bt90 commented 5 months ago

The problem is that we can't tell if that port is occupied by other nodes or if we already have our port mapped.

If we can live without predictable external ports, we could let the router handle this for us using AddAnyPortMapping:

Like AddPortMapping() action, AddAnyPortMapping() action also creates a port mapping specified with the same arguments. The behaviour differs only on the case where the specified port is not free, because in that case the gateway reserves any free NewExternalPort and NewProtocol pair and returns the NewReservedPort. It is up to the vendors to define an algorithm which finds a free port. It is encouraged to use this new action instead of the former one AddPortMapping() action, because it is more efficient, and it will be compatible with future potential solutions based on port range NAT solution also called "fractional address" within the IETF. The goal of "fractional address" NAT solution is to cope with the IPv4 public address exhaustion, by providing the same IPv4 public address to several IGDs, where each IGD is allocated with a different port range

bt90 commented 5 months ago

As this only works for IGDv2, we would either have to keep the retry logic for IGDv1, or do the sensible thing and drop IGDv1 support.

A router that supports IGDv1 but not IGDv2 is well over a decade old. Syncthing's non-working UPnP support should be the least of those people's worries. We're probably doing them a favour by not poking any more holes in the Swiss cheese of security vulnerabilities these devices present.

peterGo commented 5 months ago

@bt90

I opened this Syncthing UPnP Port Table issue for a 9-year old (2014) WiFi router.

However, Syncthing UPnP Port Table works for a 14-year old (2010) WiFi router.

wnr2000v3 UPnP

The issue does not appear to be a simple matter of WiFi router age.

bt90 commented 5 months ago

Going back to your initial logs, could you explain which IPs are assigned to this machine?

peterGo commented 5 months ago

@bt90

bt90 commented 5 months ago
  • 192.168.201.90 is the router Internet IP Address

Your provider uses regular LAN IPs for CGNAT? :eyes:

In that case the following log would describe a successful mapping:

[664CR] 2024/01/06 00:07:57 INFO: New external port opened: external TCP address(es) [192.168.201.90:31845] to local address [::]:22000.

However, this mapping isn't worth much if your router is actually behind CGNAT.

I opened this Syncthing UPnP Port Table issue for a 9-year old (2014) WiFi router.

However, Syncthing UPnP Port Table works for a 14-year old (2010) WiFi router.

UPnP is a treasure trove of broken implementations, even on today's routers. We can only try to follow the specification as closely as possible and hope for the best. There are and always will be devices out there that don't follow the specification, and it's hard to track down what's wrong because the implementations are mostly vendor-specific black boxes to us.

If this is one of those cases where the manufacturer has screwed up, our options are limited.

Could you capture the UPnP interaction between your device and the router via Wireshark?

BoGreen commented 5 months ago

An internet search did take me here, as I am facing the same problem. Just to leave my two cents here: Above comments gave me a clue what to look for, so I rather quickly was able to identify my Synology NAS occupying namely TCP port 22000. So thanks for the hints I found here!

clexp commented 2 weeks ago

I too have the avm fritzbox. I got:

`chris@nas04:~$ syncthing [start] 2024/06/06 13:10:32 INFO: syncthing v1.27.8 "Gold Grasshopper" (go1.22.3 linux-amd64) debian@github.syncthing.net 2024-05-30 08:49:22 UTC [noupgrade] [DNRLX] 2024/06/06 13:10:32 INFO: My ID: DNRLXXY-RGKAMWT-AI7XCNE-VWK63AY-ZXFBSWV-UDNMNAR-EALWHN7-DEOVKQF [DNRLX] 2024/06/06 13:10:32 INFO: Single thread SHA256 performance is 513 MB/s using minio/sha256-simd (96 MB/s using crypto/sha256). [DNRLX] 2024/06/06 13:10:33 INFO: Hashing performance is 317.79 MB/s [DNRLX] 2024/06/06 13:10:33 INFO: Detected upgrade from v1.27.7-rc.1 to v1.27.8 [DNRLX] 2024/06/06 13:10:33 INFO: Overall send rate is unlimited, receive rate is unlimited 2024/06/06 13:10:33 failed to sufficiently increase receive buffer size (was: 208 kiB, wanted: 7168 kiB, got: 5120 kiB). See https://github.com/quic-go/quic-go/wiki/UDP-Buffer-Sizes for details. [DNRLX] 2024/06/06 13:10:33 INFO: Stored folder metadata for "default" is 737h0m0s old; recalculating [DNRLX] 2024/06/06 13:10:33 INFO: Using discovery mechanism: global discovery server https://discovery.syncthing.net/v2/?noannounce&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW [DNRLX] 2024/06/06 13:10:33 INFO: Using discovery mechanism: global discovery server https://discovery-v4.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW [DNRLX] 2024/06/06 13:10:33 INFO: Relay listener (dynamic+https://relays.syncthing.net/endpoint) starting [DNRLX] 2024/06/06 13:10:33 INFO: Using discovery mechanism: global discovery server https://discovery-v6.syncthing.net/v2/?nolookup&id=LYXKCHX-VI3NYZR-ALCJBHF-WMZYSPK-QG6QJA3-MPFYMSO-U56GTUK-NA2MIAW [DNRLX] 2024/06/06 13:10:33 INFO: Using discovery mechanism: IPv4 local broadcast discovery on port 21027

[DNRLX] 2024/06/06 13:10:33 INFO: TCP listener ([::]:22000) starting [DNRLX] 2024/06/06 13:10:33 INFO: QUIC listener ([::]:22000) starting [DNRLX] 2024/06/06 13:10:33 INFO: Ready to synchronize "Default Folder" (default) (sendreceive) [DNRLX] 2024/06/06 13:10:33 INFO: Completed initial scan of sendreceive folder "Default Folder" (default) [DNRLX] 2024/06/06 13:10:33 INFO: GUI and API listening on 127.0.0.1:8384 [DNRLX] 2024/06/06 13:10:33 INFO: Access the GUI via the following URL: http://127.0.0.1:8384/ [DNRLX] 2024/06/06 13:10:33 INFO: My name is "nas04" [DNRLX] 2024/06/06 13:10:33 INFO: Cleaned away old file config.xml.v0 [DNRLX] 2024/06/06 13:10:52 INFO: quic://0.0.0.0:22000 detected NAT type: Port restricted NAT [DNRLX] 2024/06/06 13:10:52 INFO: quic://0.0.0.0:22000 resolved external address quic://217.155.11.138:22000 (via stun.syncthing.net:3478) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 22342 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 52858 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 37553 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 11319 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 6963 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 55683 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 29524 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 39579 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 50752 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 13635 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 48142 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 50121 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 60109 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 14925 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 14156 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 44341 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 4557 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 25272 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 29434 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Couldn't add port mapping for 192.168.178.52 (external port 27283 -> internal port 22000/TCP): UPnP Error: Not available Action (403) [DNRLX] 2024/06/06 13:10:53 INFO: Detected 3 NAT services [DNRLX] 2024/06/06 13:11:11 INFO: Joined relay relay://89.58.51.154:22067`

So I think it joined something? 89.58.51.154? a server in germany

I am trying to set up syncthing on my nas, an ubuntu box, a ZFS mirror, a samba server and (somewhat underused) install of nextcloud. The fritzbox lists the nextcloud and you can go to it. Mapping to the samba server is a bit more flaky - my crap settings (not that my family actually save anything to it).

So what I am getting here is I cannot use syncthing because my provider gave me a fritzbox?

So I ssh'd into my headless nas box, thinking I would share my nas folder with my home folder. But sync thing has a local host web control panel, which I cannot see, headless....

...ok so found a github post indicating you can change the gui port to external, you just need to find the config file. https://gist.github.com/pjobson/c833bfc3b2f7f53db23486f94be9ab6f but I have no such files. So it did not create the config files on the first run, it did not complete startup on the first run? Not sure where to go with this.

acolomb commented 2 weeks ago

Please take this to our forum, that's the right place. Most of your troubles are probably not even related to UPnP.