v0.11.x UPnP: no devices found

We’re unable to get a UPnP mapping on the new versions using BT Business Hub 5.

Syncthing output (STTRACE=net,discovery,upnp):

[LOBIZ] 2015/05/12 16:25:49.911074 main.go:466: INFO: syncthing v0.11.3 (go1.4.2 windows-amd64 default) unknown-user@syncthing-builder 2015-05-10 12:59:12 UTC [LOBIZ] 2015/05/12 16:25:49.912077 main.go:467: INFO: My ID: LOBIZSP [LOBIZ] 2015/05/12 16:25:49.919080 main.go:738: INFO: Database block cache capacity 129245 KiB [LOBIZ] 2015/05/12 16:25:51.709135 main.go:793: INFO: Starting web GUI on https://127.0.0.1:–/ [LOBIZ] 2015/05/12 16:25:53.691676 main.go:868: INFO: Starting local discovery announcements [LOBIZ] 2015/05/12 16:25:53.694679 discover.go:131: INFO: Local discovery over IPv6 unavailable [LOBIZ] 2015/05/12 16:25:53.694679 main.go:873: INFO: Starting global discovery announcements [LOBIZ] 2015/05/12 16:25:53.696680 main.go:646: OK: Ready to synchronize – (read-write) [LOBIZ] 2015/05/12 16:25:53.696680 main.go:646: OK: Ready to synchronize – (read-write) [LOBIZ] 2015/05/12 16:25:53.696680 main.go:646: OK: Ready to synchronize – (read-write) [LOBIZ] 2015/05/12 16:25:53.696680 main.go:662: INFO: Device IKHQUNT is “-- (—PC)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.696680 main.go:662: INFO: Device ZOMRXIP is “-- (—air.home)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.696680 main.go:662: INFO: Device GEZFM5M is “-- (—SL01)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.696680 main.go:662: INFO: Device GSYS4AN is “-- (–OFFICE)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.696680 main.go:662: INFO: Device IRJM6IM is “-- (—FL01)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.697681 main.go:662: INFO: Device KFFEBFZ is “-- (—HPL02)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.697681 main.go:662: INFO: Device HX6RX5P is “-- (AHPL03)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.697681 main.go:662: INFO: Device LOBIZSP is “Michael Jephcote (—ZSD01)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.697681 main.go:662: INFO: Device WNTMTSY is “-- (—HPL01)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.697681 main.go:662: INFO: Device AGNFWQA is “Michael Jephcote (IDEA-PC)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.697681 main.go:662: INFO: Device CLFSA4C is “-- (—FL02)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.698682 main.go:662: INFO: Device MTTP3XP is “-- (—HP)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.698682 main.go:662: INFO: Device 5U6PMMC is “sync.–” at [—] [LOBIZ] 2015/05/12 16:25:53.698682 main.go:662: INFO: Device E56VAWH is " – (—DZS01)" at [dynamic] [LOBIZ] 2015/05/12 16:25:53.698682 main.go:662: INFO: Device FZFLQHV is “-- (USER-PC)” at [dynamic] [LOBIZ] 2015/05/12 16:25:53.701684 connections.go:206: DEBUG: listening on 0.0.0.0:– [LOBIZ] 2015/05/12 16:25:53.710690 connections.go:282: DEBUG: dial 5U6PMMC sync.–:-- [LOBIZ] 2015/05/12 16:25:53.713693 usage_report.go:98: INFO: Starting usage reporting [LOBIZ] 2015/05/12 16:25:53.714693 upnpsvc.go:46: INFO: No UPnP device detected

Using an external UPnP tester (http://noeld.com/programs.asp?cat=dstools) the hub is found:

Are you sure STTRACE actually included upnp in that run? There’s very little information indeed from that package in the log, and none of it is debug level…?

That’s what I was thinking, but it’s definitely set within SyncTrayzor (and I’d restarted SyncTrayzor several times to make sure).

I will try running Syncthing from the command-line when I am in tomorrow and report back.

1 Like

Hmm, this definitely used to work from within SyncTrayzor. I’ll test it again later.

It looks like the STTRACE string may be cut off at the first comma, as there is debug output matching net but none of what I would expect from discovery or upnp.

Just tested, everything’s fine. The parsing works, it’s set correctly, and I get the correct output (lines containing upnp.go and discover.go). I would suggest that @Rewt0r typo’d the value in some way?

I’ve just tried this from the command line and the debug output is the same?

set STTRACE=net,discovery,upnp
syncthing.exe -home data\syncthing

[LOBIZ] 2015/05/13 10:31:07.694017 main.go:466: INFO: syncthing v0.11.3 (go1.4.2 windows-amd64 default) unknown-user@syncthing-builder 2015-05-10 12:59:12 UTC [LOBIZ] 2015/05/13 10:31:07.696019 main.go:467: INFO: My ID: LOBIZ [LOBIZ] 2015/05/13 10:31:07.697019 main.go:738: INFO: Database block cache capacity 129245 KiB [LOBIZ] 2015/05/13 10:31:10.223272 main.go:793: INFO: Starting web GUI on http://127.0.0.1:–/ [LOBIZ] 2015/05/13 10:31:11.923597 main.go:868: INFO: Starting local discovery announcements [LOBIZ] 2015/05/13 10:31:11.925599 discover.go:131: INFO: Local discovery over IPv6 unavailable [LOBIZ] 2015/05/13 10:31:11.925599 main.go:873: INFO: Starting global discovery announcements [LOBIZ] 2015/05/13 10:31:11.926599 main.go:646: OK: Ready to synchronize --(read-write) [LOBIZ] 2015/05/13 10:31:11.926599 main.go:646: OK: Ready to synchronize --(read-write) [LOBIZ] 2015/05/13 10:31:11.927600 main.go:646: OK: Ready to synchronize --(read-write) [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device MTTP3 is “-- (–HP)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device ZOMRX is “-- (–air.home)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device AGNFW is “Michael Jephcote (IDEA-PC)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device GSYS4 is “-- (–OFFICE)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device HX6RX is “-- (AHPL03)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device IKHQU is “-- (–PC)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device WNTMT is “-- (–HPL01)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device GEZFM is “-- (–SL01)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device KFFEB is “-- (–HPL02)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device LOBIZ is “Michael Jephcote (–ZSD01)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device 5U6PM is “sync.–” at [sync.–:--] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device CLFSA is “-- (–FL02)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device E56VA is “-- (–DZS01)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device FZFLQ is “-- (USER-PC)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.927600 main.go:662: INFO: Device IRJM6 is “-- (–FL01)” at [dynamic] [LOBIZ] 2015/05/13 10:31:11.928600 connections.go:282: DEBUG: dial 5U6PM sync.–:-- [LOBIZ] 2015/05/13 10:31:11.930602 usage_report.go:98: INFO: Starting usage reporting [LOBIZ] 2015/05/13 10:31:11.930602 connections.go:206: DEBUG: listening on 0.0.0.0:– [LOBIZ] 2015/05/13 10:31:11.931603 upnpsvc.go:46: INFO: No UPnP device detected [LOBIZ] 2015/05/13 10:31:11.933604 discover.go:348: DEBUG: discover: Received local announcement from 192.168.1.89:21025 for LOBIZ [LOBIZ] 2015/05/13 10:31:11.933604 client_udp.go:126: DEBUG: discover udp4://announce.syncthing.net:22026: broadcast: Sending self announcement to 194.126.249.5:22026 [LOBIZ] 2015/05/13 10:31:11.957621 client_udp.go:126: DEBUG: discover udp6://announce-v6.syncthing.net:22026: broadcast: Sending self announcement to [2001:470:28:4d6::5]:22026 [LOBIZ] 2015/05/13 10:31:12.442966 connections.go:176: INFO: Established secure connection to 5U6PM at 192.168.1.89:56073-85.10.–.--:– [LOBIZ] 2015/05/13 10:31:12.442966 connections.go:178: DEBUG: cipher suite: C02F in lan: false [LOBIZ] 2015/05/13 10:31:12.443967 model.go:603: INFO: Device 5U6PM client is “syncthing v0.11.2” [LOBIZ] 2015/05/13 10:31:12.443967 model.go:608: INFO: Device 5U6PM name is “sync.–” [LOBIZ] 2015/05/13 10:31:13.090426 rwfolder.go:275: INFO: Completed initial scan (rw) of folder – [LOBIZ] 2015/05/13 10:31:13.259546 client_udp.go:223: DEBUG: discover udp4://announce.syncthing.net:22026: Lookup(LOBIZ) result: [81.149.–.--:–] [LOBIZ] 2015/05/13 10:31:13.259546 client_udp.go:142: DEBUG: discover udp4://announce.syncthing.net:22026: broadcast: Self-lookup returned: [81.149.–.--:–] [LOBIZ] 2015/05/13 10:31:15.399065 rwfolder.go:275: INFO: Completed initial scan (rw) of folder – [LOBIZ] 2015/05/13 10:31:15.626227 rwfolder.go:275: INFO: Completed initial scan (rw) of folder – [LOBIZ] 2015/05/13 10:31:18.284623 client_udp.go:142: DEBUG: discover udp6://announce-v6.syncthing.net:22026: broadcast: Self-lookup returned: [] [LOBIZ] 2015/05/13 10:31:27.831530 discover.go:348: DEBUG: discover: Received local announcement from 192.168.1.74:21025 for CLFSA [LOBIZ] 2015/05/13 10:31:27.831530 discover.go:398: DEBUG: discover: Caching CLFSA addresses: [{192.168.1.74:–2015-05-13 10:31:27.8315304 +0100 BST}] [LOBIZ] 2015/05/13 10:31:27.834519 discover.go:348: DEBUG: discover: Received local announcement from 192.168.1.89:21025 for LOBIZ [LOBIZ] 2015/05/13 10:31:37.664093 discover.go:348: DEBUG: discover: Received local announcement from 192.168.1.85:21025 for AGNFW [LOBIZ] 2015/05/13 10:31:37.665110 discover.go:398: DEBUG: discover: Caching AGNFW addresses: [{192.168.1.85:–2015-05-13 10:31:37.6640935 +0100 BST}] [LOBIZ] 2015/05/13 10:31:37.668103 discover.go:348: DEBUG: discover: Received local announcement from 192.168.1.89:21025 for LOBIZ

Looks like a bug, but it’s not obvious. Is global discovery on? Perhaps the order the services are started?

Yes, both Global and Local are on along with UPnP. Automatic Upgrades are off.

I guess this could happen if we get back an empty list of interfaces - then there’s nothing for either upnp or discovery to communicate over…

@Rewt0r can you try listing your network interfaces through the same method as upnp discovery by running a quick go script?

Sure, but I’ve never ran a Go script before. What dependencies would I need to install?

Just go. I am on holiday so I won’t be able to get a sample of what to run, but it’s basically net.Interfaces call that you need.

Sorry but I’ve never used Go before, can anyone give me a bit more detail?

package main

import (
	"fmt"
	"net"
)

func main() {
	ifaces, err := net.Interfaces()
	fmt.Printf("%#v\n", err)
	fmt.Printf("%#v\n", ifaces)
}

Script above saved into “interfaces.go”, then go run interfaces.go.

Thanks.

C:\Go\scripts>…\bin\go.exe run interfaces.go []net.Interface{net.Interface{Index:7, MTU:1500, Name:"{9DF4CEB9-8EC4-459A-8871- 800D19F45B3E}", HardwareAddr:net.HardwareAddr{0x94, 0x10, 0x3e, 0x92, 0x4, 0x97} , Flags:0x0}, net.Interface{Index:6, MTU:1500, Name:"{B6269177-53FA-49D5-9E41-7A CDEC1292F3}", HardwareAddr:net.HardwareAddr{0x94, 0x10, 0x3e, 0x92, 0x4, 0x95}, Flags:0x0}, net.Interface{Index:3, MTU:1500, Name:"{956570FD-380D-4BB2-ACA3-3C86 87B4DCEF}", HardwareAddr:net.HardwareAddr{0xfc, 0xaa, 0x14, 0x12, 0xe2, 0xa1}, F lags:0x0}}

All of the interfaces have Flags:0x0 indicating they are not up (no link). So we don’t have anywhere to send discovery packets, hence the lack of debug output as well. What does ipconfig on this box look like?

But I do have an interface that’s up? Would the fact that I’m on wireless make a difference?

C:\Go\scripts>ipconfig

Windows IP Configuration


Wireless LAN adapter Local Area Connection* 2:

   Media State . . . . . . . . . . . : Media disconnected
   Connection-specific DNS Suffix  . :

Wireless LAN adapter WiFi:

   Connection-specific DNS Suffix  . : home
   Link-local IPv6 Address . . . . . : fe80::9d69:ce06:a31a:c19f%6
   IPv4 Address. . . . . . . . . . . : 192.168.1.89
   Subnet Mask . . . . . . . . . . . : 255.255.255.0
   Default Gateway . . . . . . . . . : 192.168.1.254

Ethernet adapter Ethernet:

   Media State . . . . . . . . . . . : Media disconnected
   Connection-specific DNS Suffix  . : cmsprod.local

Tunnel adapter isatap.home:

   Media State . . . . . . . . . . . : Media disconnected
   Connection-specific DNS Suffix  . : home

Tunnel adapter Teredo Tunneling Pseudo-Interface:

   Connection-specific DNS Suffix  . :
   IPv6 Address. . . . . . . . . . . : 2001:0:9d38:6abd:1031:2e80:ae6a:b2d
   Link-local IPv6 Address . . . . . : fe80::1031:2e80:ae6a:b2d%5
   Default Gateway . . . . . . . . . : ::

I guess the workaround needed is only chcking flags on non-windows