UPnP: tries to open other ports even after successful AddPortMapping

Support
1

With one router (standard in the UK, the BT Home Hub) I see that Syncthing keeps on trying to open other ports even if the first port mapping succeeds with AddPortMapping (WANIPConnection). It fails right after with WANPPPConnection on the same port (because it is already mapped with the first call) and then switches to another port and the same sequence repeats. I end up with 10 ports opened but Syncthing failing to realize the mappings succeeded.

Is it missing that the WANIP mapping succeeded and reacts to the WANPPP mapping error on the same port?

v0.14.42

[6JY3H] 2017/12/28 07:09:04.683830 upnp.go:421: DEBUG: SOAP Request URL: http://192.168.1.254:46698/ctl/IPConn
[6JY3H] 2017/12/28 07:09:04.683845 upnp.go:422: DEBUG: SOAP Action: 
[6JY3H] 2017/12/28 07:09:04.683856 upnp.go:423: DEBUG: SOAP Request:

<?xml version="1.0" ?>
    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
    <s:Body><u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1">
    <NewRemoteHost></NewRemoteHost>
    <NewExternalPort>65422</NewExternalPort>
    <NewProtocol>TCP</NewProtocol>
    <NewInternalPort>22000</NewInternalPort>
    <NewInternalClient>192.168.1.100</NewInternalClient>
    <NewEnabled>1</NewEnabled>
    <NewPortMappingDescription>syncthing-65422</NewPortMappingDescription>
    <NewLeaseDuration>3600</NewLeaseDuration>
    </u:AddPortMapping></s:Body>
    </s:Envelope>

[6JY3H] 2017/12/28 07:09:04.867154 upnp.go:432: DEBUG: SOAP Response: 200 OK

<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:AddPortMappingResponse xmlns:u="urn:schemas-upnp-org:service:WANPPPConnection:1"/></s:Body></s:Envelope>


[6JY3H] 2017/12/28 07:09:04.867220 upnp.go:421: DEBUG: SOAP Request URL: http://192.168.1.254:46698/ctl/PPPConn
[6JY3H] 2017/12/28 07:09:04.867235 upnp.go:422: DEBUG: SOAP Action: 
[6JY3H] 2017/12/28 07:09:04.867247 upnp.go:423: DEBUG: SOAP Request:

<?xml version="1.0" ?>
    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
    <s:Body><u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANPPPConnection:1">
    <NewRemoteHost></NewRemoteHost>
    <NewExternalPort>65422</NewExternalPort>
    <NewProtocol>TCP</NewProtocol>
    <NewInternalPort>22000</NewInternalPort>
    <NewInternalClient>192.168.1.100</NewInternalClient>
    <NewEnabled>1</NewEnabled>
    <NewPortMappingDescription>syncthing-65422</NewPortMappingDescription>
    <NewLeaseDuration>3600</NewLeaseDuration>
    </u:AddPortMapping></s:Body>
    </s:Envelope>

[6JY3H] 2017/12/28 07:09:05.039166 upnp.go:432: DEBUG: SOAP Response: 500 Internal Server Error

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>718</errorCode><errorDescription>ConflictInMappingEntry</errorDescription></UPnPError></detail></s:Fault></s:Body></s:Envelope>

[6JY3H] 2017/12/28 07:09:05.039314 service.go:312: DEBUG: Error getting new lease on UPnP_BTHomeHub5.0B-1_A8D3F7BE5F5B AddPortMapping: 500 Internal Server Error
[6JY3H] 2017/12/28 07:09:05.039360 upnp.go:421: DEBUG: SOAP Request URL: http://192.168.1.254:46698/ctl/IPConn
[6JY3H] 2017/12/28 07:09:05.039374 upnp.go:422: DEBUG: SOAP Action: 
[6JY3H] 2017/12/28 07:09:05.039384 upnp.go:423: DEBUG: SOAP Request:

<?xml version="1.0" ?>
    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
    <s:Body><u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1">
    <NewRemoteHost></NewRemoteHost>
    <NewExternalPort>55520</NewExternalPort>
    <NewProtocol>TCP</NewProtocol>
    <NewInternalPort>22000</NewInternalPort>
    <NewInternalClient>192.168.1.100</NewInternalClient>
    <NewEnabled>1</NewEnabled>
    <NewPortMappingDescription>syncthing-55520</NewPortMappingDescription>
    <NewLeaseDuration>3600</NewLeaseDuration>
    </u:AddPortMapping></s:Body>
    </s:Envelope>

[6JY3H] 2017/12/28 07:09:05.269215 upnp.go:432: DEBUG: SOAP Response: 200 OK

<?xml version="1.0"?>
<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><u:AddPortMappingResponse xmlns:u="urn:schemas-upnp-org:service:WANPPPConnection:1"/></s:Body></s:Envelope>


[6JY3H] 2017/12/28 07:09:05.269302 upnp.go:421: DEBUG: SOAP Request URL: http://192.168.1.254:46698/ctl/PPPConn
[6JY3H] 2017/12/28 07:09:05.269318 upnp.go:422: DEBUG: SOAP Action: 
[6JY3H] 2017/12/28 07:09:05.269332 upnp.go:423: DEBUG: SOAP Request:

<?xml version="1.0" ?>
    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
    <s:Body><u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANPPPConnection:1">
    <NewRemoteHost></NewRemoteHost>
    <NewExternalPort>55520</NewExternalPort>
    <NewProtocol>TCP</NewProtocol>
    <NewInternalPort>22000</NewInternalPort>
    <NewInternalClient>192.168.1.100</NewInternalClient>
    <NewEnabled>1</NewEnabled>
    <NewPortMappingDescription>syncthing-55520</NewPortMappingDescription>
    <NewLeaseDuration>3600</NewLeaseDuration>
    </u:AddPortMapping></s:Body>
    </s:Envelope>

[6JY3H] 2017/12/28 07:09:05.659042 upnp.go:432: DEBUG: SOAP Response: 500 Internal Server Error

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/"><s:Body><s:Fault><faultcode>s:Client</faultcode><faultstring>UPnPError</faultstring><detail><UPnPError xmlns="urn:schemas-upnp-org:control-1-0"><errorCode>718</errorCode><errorDescription>ConflictInMappingEntry</errorDescription></UPnPError></detail></s:Fault></s:Body></s:Envelope>

[6JY3H] 2017/12/28 07:09:05.659160 service.go:312: DEBUG: Error getting new lease on UPnP_BTHomeHub5.0B-1_A8D3F7BE5F5B AddPortMapping: 500 Internal Server Error
[6JY3H] 2017/12/28 07:09:05.659200 upnp.go:421: DEBUG: SOAP Request URL: http://192.168.1.254:46698/ctl/IPConn
[6JY3H] 2017/12/28 07:09:05.659214 upnp.go:422: DEBUG: SOAP Action: 
[6JY3H] 2017/12/28 07:09:05.659224 upnp.go:423: DEBUG: SOAP Request:

<?xml version="1.0" ?>
    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/" s:encodingStyle="http://schemas.xmlsoap.org/soap/encoding/">
    <s:Body><u:AddPortMapping xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1">
    <NewRemoteHost></NewRemoteHost>
    <NewExternalPort>35156</NewExternalPort>
    <NewProtocol>TCP</NewProtocol>
    <NewInternalPort>22000</NewInternalPort>
    <NewInternalClient>192.168.1.100</NewInternalClient>
    <NewEnabled>1</NewEnabled>
    <NewPortMappingDescription>syncthing-35156</NewPortMappingDescription>
    <NewLeaseDuration>3600</NewLeaseDuration>
    </u:AddPortMapping></s:Body>
    </s:Envelope>
2

The router is announcing both an IP connection and a PPP connection, and Syncthing is accordingly requesting a mapping on each. Look closely at the urn in addportmapping and you’ll see they differ.

But the router doesn’t allow mapping the same port on both, apparently, so this fails.

I’m not sure who is in error. Someone should dig through the UPnP spec. At the very least we should probably not redo the one that succeeded just because the second mapping fails.

3

yes this is correct, the router is announcing both IP & PPP (see below the 2 urls) but does not allow the same port mapping. Then, the first mapping works fine (the IP one), why can’t we stop here, use it and ignore the following PPP connection conflict error message?

[6JY3H] 2017/12/28 08:20:03.131786 upnp.go:352: DEBUG: http://192.168.1.254:46698/rootDesc.xml - no services of type urn:schemas-upnp-org:service:WANIPConnection:1  found on connection.
[6JY3H] 2017/12/28 08:20:03.131805 upnp.go:361: DEBUG: http://192.168.1.254:46698/rootDesc.xml - found urn:schemas-upnp-org:service:WANIPConnection:1 with URL http://192.168.1.254:46698/ctl/IPConn
[6JY3H] 2017/12/28 08:20:03.131811 upnp.go:352: DEBUG: http://192.168.1.254:46698/rootDesc.xml - no services of type urn:schemas-upnp-org:service:WANPPPConnection:1  found on connection.
[6JY3H] 2017/12/28 08:20:03.131818 upnp.go:361: DEBUG: http://192.168.1.254:46698/rootDesc.xml - found urn:schemas-upnp-org:service:WANPPPConnection:1 with URL http://192.168.1.254:46698/ctl/PPPConn
[6JY3H] 2017/12/28 08:20:03.134988 upnp.go:125: DEBUG: UPnP discovery result UPnP_BTHomeHub5.0B-1_A8D3F7BE5F5B with services:
[6JY3H] 2017/12/28 08:20:03.134998 upnp.go:127: DEBUG: * [urn:upnp-org:serviceId:WANIPConn1] http://192.168.1.254:46698/ctl/IPConn
[6JY3H] 2017/12/28 08:20:03.135003 upnp.go:127: DEBUG: * [urn:upnp-org:serviceId:WANPPPConn1] http://192.168.1.254:46698/ctl/PPPConn
4

Probably we should use a different port for each connection, we don’t know if IP or PPP is the one used so being satisfied with IP would be wrong in the general case.

5

Yes, very good idea! This is easy to implement and would avoid this potential issue - we should stop looking for port with IP once one has been found as well.

There are millions of such NAT router in the UK I think, this is the British Telecom router provided at the moment.

6

In the meantime, you can map port 22000 manually and disable UPnP in Syncthing.

7

Yes sure, thanks for your reactivity . Should I open a ticket on GitHub explaining the issue?

8

I don’t think this actually breaks anything. We should just report the port mapping that succeeded.

9

It breaks because we failed to set up a mapping on PPP (and probably consider the whole thing failed?).

10

Yeah, the doc string explicitly states that:

// AddPortMapping adds a port mapping to all relevant services on the
// specified InternetGatewayDevice. Port mapping will fail and return an error
// if action is fails for _any_ of the relevant services. For this reason, it
// is generally better to configure port mapping for each individual service
// instead.
11

yes this is what is happening, there are 2 services (IP, PPP): the first succeeds and the 2nd fails, it will have added unecessarily one mapping that is valid but forgot and unused and it will move to the next port.

With 5 devices on the network, this is opening 5*10=50 ports and reopening them all every hour - using the IP service.

In the loop, any failure exits the whole function:

func (n *IGD) AddPortMapping(protocol nat.Protocol, internalPort, externalPort int, description string, duration time.Duration) (int, error) {
	for _, service := range n.services {
		err := service.AddPortMapping(n.localIPAddress, protocol, internalPort, externalPort, description, duration)
		if err != nil {
			return externalPort, err
		}
	}
	return externalPort, nil
}
12

If you can, make a pull request fixing this. We could refactor upnp package to return a IGD per service, fixing this.

13

I can try something but I need to be clear about the logic if we loop through the services instead of just requesting it at the NAT level. Is the objective to open one port with each service? If we manage to open port A with Service A and port B with Service B which one do we use?

14

We advertise both to discovery. The logic should be to return an IGD struct per service, instead of a single IGD for multiple services. The multiple IGD case is already handled.

15

Ok and the below loop needs to be run for each service, isn’t it?

	for i := 0; i < 10; i++ {
		// Then try up to ten random ports.
		extPort = 1024 + predictableRand.Intn(65535-1024)
		name := fmt.Sprintf("syncthing-%d", extPort)
		port, err = natd.AddPortMapping(TCP, intPort, extPort, name, leaseTime)
		if err == nil {
			extPort = port
			goto findIP
		}
		l.Debugln("Error getting new lease on", natd.ID(), err)
}
16

Yes, but it doesn’t matter than the first one will fail on one of them, as the second one should succeed. Or predictable random could be seeded from tye IGD name (where IGD name can be uuid + service name).

17

The quick fix I had in mind was failing for mapping only if all the services fail for the port. If one service succeeds we should be able to move forward, we have a connection with an open port. This only touches func (n *IGD) AddPortMapping(protocol nat.Protocol, internalPort, externalPort int, description string, duration time.Duration) (int, error).

This is not perfect but the current implementation seems worse to me, repeating 10 times, ignoring what worked and flooding the working service with new mappings.

18

I agree that existing implementation is suboptimal, but if we’re fixing it, we should fix it the right way I guess, by splitting out each service into a separate IGD.

19

You are right, then I need to study the code a little more to see all the implications before I can commit.

20

It’s fairly trivial:

This function needs to return multiple IGDs, one per service, and have different UUID for each service I guess.

Also, we should somehow seed predictable random with UUID to prevent multiple services hitting the same port.