Repository: syncthing/syncthing (language: go)

Issue:
UPnP error messages
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: New external port opened: external TCP address(es) [192.168.201.90:31845] to local address [::]:22000.
[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



Discussion / hints:
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?
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?
> 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.
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](https://github.com/syncthing/syncthing/assets/4561296/04f3a3a3-834e-46e8-8dd6-7f1999820ff2)

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. 

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 ?
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
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.
@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](https://github.com/syncthing/syncthing/assets/4561296/0ad2df15-a2d6-4f79-974b-0b86b6928b1e)

The issue does not appear to be a simple matter of WiFi router age.

Going back to your initial logs, could you explain which IPs are assigned to this machine?

* `192.168.1.11`
* `192.168.201.90`
@bt90

- `192.168.1.11` is the machine DHCP IP Address
- `192.168.201.90` is the router Internet IP Address

> * `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?
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!

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: Using discovery mechanism: IPv6 local multicast discovery on address [ff12::8384]: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.  
Please take this to our forum, that's the right place. Most of your troubles are probably not even related to UPnP. 
@bt90 
> 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.

Sorry to bother, but would you happen to still have the link to that? I have an AVM Fritz!Box router and I'd hope that the manufacturer also suggests a workaround or provides a patch :p

Also, shouldn't syncthing be falling back to [relaying](https://docs.syncthing.net/users/relaying.html) then?

---

Edit: Found my supposed answer in the [syncthing forum thread here](https://forum.syncthing.net/t/couldnt-add-port-mapping-for-192-168-178-xx-error-conflictinmappingentry-718/21605/2?u=lucidbrot). "It is supposedly fixed in Fritz!OS 7.80". So I guess my problem might be not the same, as I already have that version. ...
@bt90 @acolomb Tagging you as you worked/reviewed and seem knowledgable about this upnp stuff: Is there an actual indication of broken functionality here?

I have very little knowledge of this and looking at the logs it's not entirely clear, as error messages are mixed with informational messages of successful upnp operations. From a cursory glance it's not clear to me if things are working as intended and we are just too verbose with accompanying failed attempts, or if there's actual degraded functionality that could/should be improved/fixed.

Regardless of which of the two it is, it looks like there's potential to reduce the verboseness. We don't need to spam the log with the same error over and over (just different port, I assume those are retries). A single message surely would suffice (if attempted ports are important info, those can be added to that single log entry). 
@imsodin we should really try to turn down the logging a bit. UPnP interaction usually follows two patterns:

* success on the first or second try
* ten iteration death spiral spamming the log

I think it's enough to log successful attempts and a single warning/error for the last failure, since the root cause is identical anyway.

Fix patch:
diff --git a/lib/nat/service.go b/lib/nat/service.go
index d0644c31992..2db3f1a088f 100644
--- a/lib/nat/service.go
+++ b/lib/nat/service.go
@@ -259,7 +259,7 @@ func (s *Service) verifyExistingLocked(ctx context.Context, mapping *Mapping, na
 			// entry always has the external port.
 			responseAddrs, err := s.tryNATDevice(ctx, nat, mapping.address, extAddrs[0].Port, leaseTime)
 			if err != nil {
-				l.Debugf("Failed to renew %s -> %v open port on %s", mapping, extAddrs, id)
+				l.Infof("Failed to renew %s -> %v open port on %s: %s", mapping, extAddrs, id, err)
 				mapping.removeAddressLocked(id)
 				change = true
 				continue
@@ -311,7 +311,7 @@ func (s *Service) acquireNewLocked(ctx context.Context, mapping *Mapping, nats m
 
 		addrs, err := s.tryNATDevice(ctx, nat, mapping.address, 0, leaseTime)
 		if err != nil {
-			l.Debugf("Failed to acquire %s open port on %s", mapping, id)
+			l.Infof("Failed to acquire %s open port on %s: %s", mapping, id, err)
 			continue
 		}
 
@@ -359,7 +359,7 @@ func (s *Service) tryNATDevice(ctx context.Context, natd Device, intAddr Address
 			extPort = port
 			goto findIP
 		}
-		l.Debugln("Error extending lease on", natd.ID(), err)
+		l.Debugf("Error extending lease on %v (external port %d -> internal port %d): %v", natd.ID(), extPort, intAddr.Port, err)
 	}
 
 	for i := 0; i < 10; i++ {
@@ -377,7 +377,8 @@ func (s *Service) tryNATDevice(ctx context.Context, natd Device, intAddr Address
 			extPort = port
 			goto findIP
 		}
-		l.Debugf("Error getting new lease on %s: %s", natd.ID(), err)
+		err = fmt.Errorf("getting new lease on %s (external port %d -> internal port %d): %w", natd.ID(), extPort, intAddr.Port, err)
+		l.Debugf("Error %s", err)
 	}
 
 	return nil, err
diff --git a/lib/upnp/igd_service.go b/lib/upnp/igd_service.go
index f31b65d16b7..36578bc586a 100644
--- a/lib/upnp/igd_service.go
+++ b/lib/upnp/igd_service.go
@@ -206,7 +206,7 @@ func (s *IGDService) AddPortMapping(ctx context.Context, protocol nat.Protocol,
 		}
 
 		err = fmt.Errorf("UPnP Error: %s (%d)", envelope.ErrorDescription, envelope.ErrorCode)
-		l.Infof("Couldn't add port mapping for %s (external port %d -> internal port %d/%s): %s", s.LocalIPv4, externalPort, internalPort, protocol, err)
+		l.Debugf("Couldn't add port mapping for %s (external port %d -> internal port %d/%s): %s", s.LocalIPv4, externalPort, internalPort, protocol, err)
 	}
 
 	return externalPort, err


Test patch: