Upnp wierd behavior

AlroneRhyn · September 7, 2016, 7:31pm

Hi Guys,

Sorry AudriusButkevicius beeing a noob posting support request on github

Here is the thing :

I’ve got an issue with my new ISP : my discosrv seems to annouce the private router address instead of the public router address (192.168.1.254). I can’t find why !

Architecture : arsenic (1.50) and kipsi (1.2) are syncthing devices on the same LAN. arsenic and the discosrv are on the same debian. Arsenic and kipsi doesn’t have the Local Discovery activated, but NAT yes. They both can talk to my discosrv through its nated public ip thanks to a port redirection.

When i activate relay, it’s working, but i shouldn’t need it.

Here is my syncthing startup :

c@a:~$ STTRACE=upnp syncthing

[...] 2016/09/07 21:16:13.116218 upnp.go:150: DEBUG: Starting discovery of device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
[...] 2016/09/07 21:16:13.117067 upnp.go:150: DEBUG: Starting discovery of device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
[...] 2016/09/07 21:16:13.117536 upnp.go:165: DEBUG: Sending search request for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
[...] 2016/09/07 21:16:13.117773 upnp.go:173: DEBUG: Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0
[...] 2016/09/07 21:16:13.118355 upnp.go:165: DEBUG: Sending search request for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
[...] 2016/09/07 21:16:13.118558 upnp.go:196: DEBUG: Handling UPnP response:

HTTP/1.1 200 OK
SERVER: Linux/2.6 UPnP/1.0 fbxigdd/1.1
LOCATION: http://192.168.1.254:5678/desc/root
EXT:
CACHE-CONTROL: max-age=1800
ST: urn:schemas-upnp-org:device:InternetGatewayDevice:1
USN: uuid:igd73616d61-6a65-7374-650a-68a3780ccd8a::urn:schemas-upnp-org:device:InternetGatewayDevice:1


[...] 2016/09/07 21:16:13.118900 upnp.go:173: DEBUG: Listening for UPnP response for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0
[...] 2016/09/07 21:16:13.129387 upnp.go:354: DEBUG: http://192.168.1.254:5678/desc/root - no services of type urn:schemas-upnp-org:service:WANIPConnection:1  found on connection.
[...] 2016/09/07 21:16:13.129614 upnp.go:363: DEBUG: http://192.168.1.254:5678/desc/root - found urn:schemas-upnp-org:service:WANIPConnection:1 with URL http://192.168.1.254:5678/control/wan_ip_connection
[...] 2016/09/07 21:16:13.129879 upnp.go:354: DEBUG: http://192.168.1.254:5678/desc/root - no services of type urn:schemas-upnp-org:service:WANPPPConnection:1  found on connection.
[...] 2016/09/07 21:16:13.131002 upnp.go:124: DEBUG: UPnP discovery result igd73616d61-6a65-7374-650a-68a3780ccd8a with services:
[...] 2016/09/07 21:16:13.131106 upnp.go:126: DEBUG: * [urn:upnp-org:serviceId:WANIPConn1] http://192.168.1.254:5678/control/wan_ip_connection
[...] 2016/09/07 21:16:23.117926 upnp.go:192: DEBUG: Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:1 on eth0 finished.
[...] 2016/09/07 21:16:23.118635 upnp.go:192: DEBUG: Discovery for device type urn:schemas-upnp-org:device:InternetGatewayDevice:2 on eth0 finished.
[...] 2016/09/07 21:16:23.119714 upnp.go:423: DEBUG: SOAP Request URL: http://192.168.1.254:5678/control/wan_ip_connection
[...] 2016/09/07 21:16:23.119821 upnp.go:424: DEBUG: SOAP Action: 
[...] 2016/09/07 21:16:23.119906 upnp.go:425: 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>63542</NewExternalPort>
    <NewProtocol>TCP</NewProtocol>
    <NewInternalPort>22000</NewInternalPort>
    <NewInternalClient>192.168.1.50</NewInternalClient>
    <NewEnabled>1</NewEnabled>
    <NewPortMappingDescription>syncthing-63542</NewPortMappingDescription>
    <NewLeaseDuration>1800</NewLeaseDuration>
    </u:AddPortMapping></s:Body>
    </s:Envelope>

[...] 2016/09/07 21:16:23.125629 upnp.go:434: 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:WANIPConnection:1"></u:AddPortMappingResponse></s:Body></s:Envelope>

[...] 2016/09/07 21:16:23.126144 upnp.go:423: DEBUG: SOAP Request URL: http://192.168.1.254:5678/control/wan_ip_connection
[...] 2016/09/07 21:16:23.126339 upnp.go:424: DEBUG: SOAP Action: 
[...] 2016/09/07 21:16:23.126517 upnp.go:425: 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:GetExternalIPAddress xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1" /></s:Body>
    </s:Envelope>

[...] 2016/09/07 21:16:23.129607 upnp.go:434: 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:GetExternalIPAddressResponse xmlns:u="urn:schemas-upnp-org:service:WANIPConnection:1"><NewExternalIPAddress>$PUBLIC_IP</NewExternalIPAddress></u:GetExternalIPAddressResponse></s:Body></s:Envelope>

[...] 2016/09/07 21:16:23.130418 structs.go:32: INFO: New NAT port mapping: external TCP address $PUBLIC_IP:63542 to local address 0.0.0.0:22000.
[...] 2016/09/07 21:16:23.130651 service.go:61: INFO: Detected 1 NAT device

Here is my disco server debug :

b@a:~/# /usr/local/bin/discosrv -cert /var/discosrv/certs/cert.pem -key /var/discosrv/certs/key.pem -debug

stdiscosrv v0.14.5 (go1.7 linux-amd64) jenkins@build.syncthing.net 2016-08-23 08:42:09 UTC

Server ID ID is TADA

[...] GE[...] T /v2/?ID=$ID1

[...] GET /v2/?ID=$ID1 completed in 435.996µs 

[...] POST /v2/

[...] updateID in 162.328µs

[...] insertID in 250.917µs

[...] commit in 9.825µs

[...] POST /v2/ completed in 1.161886ms 

[...] GET /v2/?ID=$ID2

[...] GET /v2/?ID=$ID2 completed in 1.079609ms 

[...] GET /v2/?ID=$ID3

[...] GET /v2/?ID=$ID3 completed in 452.659µs 

[...] GET /v2/?ID=$ID4

[...] getAddresses in 1.868088ms

[...] GET /v2/?ID=$ID4 completed in 3.327429ms 

[...] POST /v2/

[...] updateID in 741.453µs

[...] commit in 29.726µs

[...] POST /v2/ completed in 5.103378ms 

Stats: 0.01 announces/s, 0.01 queries/s, 0.00 answers/s, 0.00 errors/s

[...] GET /v2/?ID=$ID4

[...] getAddresses in 1.70056ms

[...] GET /v2/?ID=$ID4 completed in 3.437106ms

You can see here that my UPnp is working :

Here are addresses reveiced from the discosrv :

Address                      
dynamic
tcp://192.168.1.254:22000
tcp://192.168.1.254:63542

Here is the error loop trace with STTRACE=all

Reconnect loop
[...] 2016/09/07 21:01:43.964934 service.go:319: $ID
[...] 2016/09/07 21:01:43.965757 cache.go:92: $ID at global@https://foo.bar:8443/v2/
[...] 2016/09/07 21:01:43.966095 cache.go:93: DEBUG:   cache: {[tcp://192.168.1.254:22001 tcp://192.168.1.254:15007] {63608871608 582925625 0xeab620} true {0 0 <nil>} 0}
[...] 2016/09/07 21:01:43.967047 cache.go:138: $ID
[...] 2016/09/07 21:01:43.967397 cache.go:139: DEBUG:   addresses:  [tcp://192.168.1.254:15007 tcp://192.168.1.254:22001]
[...] 2016/09/07 21:01:43.968253 service.go:368: $ID tcp://192.168.1.254:15007
[...] 2016/09/07 21:01:43.969400 tcp_dial.go:38: DEBUG: dial tcp 192.168.1.254:15007: getsockopt: connection refused
[...] 2016/09/07 21:01:43.970025 service.go:373: $ID tcp://192.168.1.254:15007 dial tcp 192.168.1.254:15007: getsockopt: connection refused
[...] 2016/09/07 21:01:43.970695 service.go:368: $ID tcp://192.168.1.254:22001
[...] 2016/09/07 21:01:43.971529 tcp_dial.go:38: DEBUG: dial tcp 192.168.1.254:22001: getsockopt: connection refused
[...] 2016/09/07 21:01:43.972445 service.go:373: $ID tcp://192.168.1.254:22001 dial tcp 192.168.1.254:22001: getsockopt: connection refused
[...] 2016/09/07 21:01:43.973426 service.go:319: $ID
[...] 2016/09/07 21:01:43.974288 cache.go:104: $ID
[...] 2016/09/07 21:01:43.975099 cache.go:138: $ID
[...] 2016/09/07 21:01:43.975245 cache.go:139: DEBUG:   addresses:  []
[...] 2016/09/07 21:01:43.976105 service.go:319: $ID
[...] 2016/09/07 21:01:43.976962 cache.go:104: $ID
[...] 2016/09/07 21:01:43.977772 cache.go:138: $ID
[...] 2016/09/07 21:01:43.977916 cache.go:139: DEBUG:   addresses:  []
[...] 2016/09/07 21:01:43.978071 service.go:389: DEBUG: sleep until next dial 1m0s

Is there something i’m missing ?

Thanks a lot for your help, i’m struggling.

AudriusButkevicius · September 7, 2016, 8:50pm

Running a discovery server on the same network as one of the devices that is supposed to be using it is unsupported, because if your router is clever enough, it will redirect the traffic to discovery server via the local ip rather than the public ip, in which case the ip address announced will be your LAN address.

wweich · September 8, 2016, 6:13am

Some Routers are even more clever ;). Mine routes the traffic internally (so full speed) but uses the external IP and also uses/enforces the port forwarding rules.

system · October 8, 2016, 6:22am

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