Concurrently is definitely the preferred method so Syncthing doesn’t have to go through 5 failed connections before getting a valid connection and starting to sync.
Why is the discovery service reporting the right external port for the other device on that network which I can connect to? It makes no sense
I don’t know, run with STTRACE=discovery to see what are the actual lookups returning.
Already have been doing that, the output doesn’t seem to show any IPs just hex output?
[xxxxx] 2014/11/25 16:45:08.200834 discover.go:434: DEBUG: discover: read external:
00000000 9d 79 bc 39 00 00 00 20 98 e2 9b fe aa 4e 67 3a |.y.9… …Ng:|
00000010 16 2d e9 df 28 52 98 87 36 be 18 c3 f6 54 c0 a5 |.-…(R…6…T…|
00000020 4e e3 b7 d4 b4 93 44 90 00 00 00 01 00 00 00 04 |N…D…|
00000030 51 62 41 c1 00 00 6e 70 00 00 00 00 |QbA…np…|
[xxxxx] 2014/11/25 16:45:08.200834 discover.go:286: DEBUG: discover: external lookup check: [81.255.255.193:28272]
[xxxxx] 2014/11/25 16:45:12.202996 discover.go:434: DEBUG: discover: read external:
00000000 9d 79 bc 39 00 00 00 20 d1 a5 12 72 59 fd bf 14 |.y.9… …rY…|
00000010 cf 7c 05 c3 a9 e1 58 7b 6e b4 6a 15 2d 0c 96 70 |.|…X{n.j.-…p|
00000020 1e 9e 65 15 64 28 c0 79 00 00 00 01 00 00 00 04 |…e.d(.y…|
00000030 55 0a fa 92 00 00 6e 70 00 00 00 00 |U…np…|
[xxxxx] 2014/11/25 16:45:17.466880 discover.go:434: DEBUG: discover: read external:
00000000 9d 79 bc 39 00 00 00 20 43 bb fe d6 f9 b5 a7 de |.y.9… C…|
00000010 36 f2 62 ad a8 ee 44 20 60 04 3a 54 79 e1 1c 0c |6.b…D .:Ty...| 00000020 52 7c c2 42 bd 7c 24 2e 00 00 00 01 00 00 00 04 |R|.B.|$.........| 00000030 51 8a c9 85 00 00 55 f0 00 00 00 00 |Q.....U.....| [xxxxx] 2014/11/25 16:45:17.779066 discover.go:434: DEBUG: discover: read external: 00000000 9d 79 bc 39 00 00 00 20 78 77 e8 38 4c 54 c2 ec |.y.9... xw.8LT..| 00000010 dc 0e 04 0f a0 23 89 71 26 f3 e1 ad 60 d6 03 37 |.....#.q&...…7|
00000020 62 ed 5e 81 7e ca c1 64 00 00 00 01 00 00 00 04 |b.^.~…d…|
00000030 51 8a c9 85 00 00 55 f0 00 00 00 00 |Q…U…|
[xxxxx] 2014/11/25 16:45:18.087195 discover.go:434: DEBUG: discover: read external:
00000000 9d 79 bc 39 00 00 00 20 7d d8 ad 87 b6 d7 08 62 |.y.9… }…b|
00000010 96 56 37 e6 c8 d0 65 bf c3 7f 52 6e dd e3 50 2f |.V7…e…Rn…P/|
00000020 a1 db 7e 79 09 db d9 05 00 00 00 01 00 00 00 04 |…~y…|
00000030 d9 2b e5 1f 00 00 c1 8c 00 00 00 00 |.+…|
[xxxxx] 2014/11/25 16:45:18.351976 discover.go:434: DEBUG: discover: read external:
00000000 9d 79 bc 39 00 00 00 20 a8 21 b3 19 be 9a da 15 |.y.9… .!..|
00000010 b2 cc d4 77 67 2e 96 0a 79 7a dc 1a 12 28 4d c8 |…wg…yz…(M.|
00000020 b5 ca 90 4d 4c cf fb d7 00 00 00 01 00 00 00 04 |…ML…|
00000030 1f 36 57 bb 00 00 7a af 00 00 00 00 |.6W…z…|
[] 2014/11/25 16:45:18.592759 discover.go:434: DEBUG: discover: read external:
00000000 9d 79 bc 39 00 00 00 20 c5 4a 8f bc f1 81 3c 04 |.y.9… .J…<.|
00000010 49 8c 8d 82 1b 09 61 17 fb 83 82 f9 d1 2f c0 13 |I…a…/…|
00000020 31 e8 29 e4 54 0d 4c b2 00 00 00 01 00 00 00 04 |1.).T.L…|
00000030 d9 2b e5 1f 00 00 55 f0 00 00 00 00 |.+…U…|
[xxxxx] 2014/11/25 16:45:18.906054 discover.go:434: DEBUG: discover: read external:
00000000 9d 79 bc 39 00 00 00 20 e0 76 32 31 d5 77 60 39 |.y.9… .v21.w`9|
00000010 e3 01 8a 4a ee f0 51 81 27 3f fb 8d 85 b8 e8 71 |…J…Q.’?..q|
00000020 8b 40 53 4d aa d4 c3 ed 00 00 00 01 00 00 00 04 |.@SM…|
00000030 51 8a c9 85 00 00 55 f0 00 00 00 00 |Q…U…|
TDRJX7V-> 81.255.255.193:28272
2GSRE4S-> 85.255.255.146:28272
IO575VX-> 81.255.255.133:22000
PB36QOC-> 81.255.255.133:22000
PXMK3B5-> 217.255.255.31:49548
VAQ3GGN-> 31.255.255.187:31407
YVFI7PH-> 217.255.255.31:22000
4B3DEMO-> 81.255.255.133:22000
That’s the mappings you get from the announce server. Why are the mappings like this, ask your UPnP device. I guess one of the nodes just fails to get a mapping advertising an incorrrect port.
I can see that all devices in 81.255.255.133 are failing, as well as one device in 217.255.255.31
81.255.255.133 is failing for internal and external clients (firewall issue I have no access to - waiting for them to allow the ports)
The thing is - our server is getting the correct mapping for YVFI7PH whereas my Laptop is not, that mapping came from my laptop. I’ve enabled discovery logging on our server now in order to get the mapping that receives but this device isn’t currently online so I’m just waiting for it to come back on.
Also how did you convert the IPs into that?
Last line (always offset 00000030): 51 8a c9 85 is the 4 bytes representing an IP in hex, 51 hex is 81 in dec, etc, etc. 00 00 55 f0 is the 4 byte (16 bit) integer representing the port, 55f0 in hex is 22000 in dec
Basically, if one of your machines made false announcements, you should probably restart it and make sure UPnP works. Then give an hour or two for the announce cache to clear, or reconfigure the IP address of the node from dynamic to some correct address.
Is there a way to force the announce cache to be cleared?
I have a feeling that there is an issue with BT Hubs UPnP function… Problems seem to be arising from clients connected to either BT Home Hub or BT Business Hub 
and thanks for explaining which parts of the debug information I need to use.
So the cache entries are only valid for an hour, and given they are not re-advertised, they expire. But it seems that entries for the same IP with a new port should be updated instantly, given the announcement arrives: https://github.com/syncthing/discosrv/blob/master/main.go#L345
OK after further testing I have found out the following:
We are receiving the wrong mapping from the discovery server - our central server is also unable to connect to these clients until it receives a connection from the client then it receives the correct mapping.
Discovery server response:
Nov 26 11:27:03 my-host syncthing[19194]: 00000000 9d 79 bc 39 00 00 00 20 a8 21 b3 19 be 9a da 15 |.y.9… .!..| Nov 26 11:27:03 my-host syncthing[19194]: 00000010 b2 cc d4 77 67 2e 96 0a 79 7a dc 1a 12 28 4d c8 |…wg…yz…(M.| Nov 26 11:27:03 my-host syncthing[19194]: 00000020 b5 ca 90 4d 4c cf fb d7 00 00 00 01 00 00 00 04 |…ML…| Nov 26 11:27:03 my-host syncthing[19194]: 00000030 1f 36 57 bb 00 00 6e 70 00 00 00 00 |.6W…np…|
Nov 26 11:27:33 my-host syncthing[19194]: [2GSRE] 2014/11/26 11:27:33.033049 main.go:965: DEBUG: connect from 31.255.255.187:51382 Nov 26 11:27:33 my-host syncthing[19194]: [2GSRE] 2014/11/26 11:27:33.281825 main.go:920: INFO: Established secure connection to VAQ3GGN at 192.168.1.248:28272-31.255.255.187:51382
Or is that just using the connection it received rather than making a connection to them as well?
I’ve also just noticed that my laptop isn’t putting anything into the log for UPnP mapping other than Local Discovery. There are no errors either… Is there an extra flag I need to set in STTRACE?
Perhaps global discovery is disabled, or the server address is unset? As for you getting incorrect mappings, it’s your servers fault for advertising wrong stuff. It most likely advertises wrong stuff because UPnP is failing.
All the nodes have Global+Local discovery on with dynamic addresses set. I’m seeing nothing in my laptop about the UPnP port being mapped using a Virgin Media Superhub 2ac, there aren’t even any errors! Manually forwarding the port allows devices to connect to me.
I think all of the issues being faced here are with BT and Virgin Media’s network equipment given to customers. Seems unlikely we’ll get a fix from them anytime soon… They are the biggest ISPs in the UK.
The protocol is slowly moving to DST (TLS over reliable UDP) which should not have these issues at all.
But you are not alone, as I have a plus.net Thomson router, which supports UPnP and works with uTorrent, Skype et al, but it doesn’t seem to be working with Syncthing so I end up mapping ports manually.
There might be something wrong with the UPnP code, but I haven’t had a chance to fire up Wireshark to investigate what’s wrong.
Does Syncthing manage to find the UPnP devices, or does it just say 0 devices found?
It says 0 devices found on my Laptop so that would be using the SuperHub. All the other devices get a successful mapping (those using BT Hubs) but still unable to connect to those.
So what the mappings look like on the BT hubs? I think it prints a message what was mapped to what.
I’m just waiting to receive a log from one of those devices.
In the mean time I have downloaded a UPnP tester from: http://noeld.com/programs.asp?cat=dstools and that shows as though syncthing already mapped a port through UPnP but didn’t log it? I know it was done by Syncthing as I’ve looked at the source and it adds the description “syncthing”
The SuperHub 2ac is running 1900/tcp open sip FedoraCore/6 UPnP/1.1 MiniUPnPd/1.7
Very bizarre. I’ve just changed the listening port on Syncthing and once it restarted this appeared in the log:
[AAW47] 2014/11/26 13:31:05.360249 main.go:618: INFO: Starting web GUI on https://127.0.0.1:8080/ [AAW47] 2014/11/26 13:31:05.974670 upnp.go:106: INFO: Starting UPnP discovery… [AAW47] 2014/11/26 13:31:11.976508 upnp.go:133: INFO: UPnP discovery complete (found 1 device). [AAW47] 2014/11/26 13:31:12.023767 main.go:742: INFO: Created UPnP port mapping for external port 28470 on UPnP device ‘VMDG490’ (192.168.0.1). [AAW47] 2014/11/26 13:31:12.023767 main.go:1085: INFO: Starting local discovery announcements
I then restarted the server again and it produced the same output. Seems intermittent with the Virgin Media one, not sure why. I will wait for the log from one of the BT clients and post the UPnP logs from it once received.
Yeah, so if you change the listen port I am sure it will get a new mapping as its a 1:1 thing.
Now if you STTRACE=discovery you’ll see that it’s most likely announcing the correct (mapped) port, and then clients querying discovery should get the right port too.
The devices that are not working are probably having issues getting the mapping in the first place.
From one of the BT devices:
[YVFI7] 2014/11/26 15:00:50.766271 upnp.go:106: INFO: Starting UPnP discovery… [YVFI7] 2014/11/26 15:00:54.182568 upnp.go:276: INFO: Invalid IGD response: invalid device UUID UPnP_BThomeHub2.0B_988b5dab637d (continuing anyway) [YVFI7] 2014/11/26 15:00:54.183575 upnp.go:276: INFO: Invalid IGD response: invalid device UUID UPnP_BThomeHub2.0B_988b5dab637d (continuing anyway) [YVFI7] 2014/11/26 15:00:54.184575 upnp.go:276: INFO: Invalid IGD response: invalid device UUID UPnP_BThomeHub2.0B_988b5dab637d (continuing anyway) [YVFI7] 2014/11/26 15:00:56.767888 upnp.go:133: INFO: UPnP discovery complete (found 3 devices). [YVFI7] 2014/11/26 15:01:03.281759 main.go:742: INFO: Created UPnP port mapping for external port 30737 on UPnP device ‘BT Home Hub 2.0 Media Gateway’ (192.168.1.254).