Rewt0r
(Michael Jephcote)
May 12, 2015, 3:31pm
1
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:
calmh
(Jakob Borg)
May 12, 2015, 4:37pm
2
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…?
Rewt0r
(Michael Jephcote)
May 12, 2015, 7:08pm
3
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
canton7
(Antony Male)
May 13, 2015, 7:02am
4
Hmm, this definitely used to work from within SyncTrayzor. I’ll test it again later.
calmh
(Jakob Borg)
May 13, 2015, 7:07am
5
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
.
canton7
(Antony Male)
May 13, 2015, 8:13am
6
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?
Rewt0r
(Michael Jephcote)
May 13, 2015, 9:33am
7
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?
Rewt0r
(Michael Jephcote)
May 13, 2015, 9:58am
9
Yes, both Global and Local are on along with UPnP. Automatic Upgrades are off.
calmh
(Jakob Borg)
May 13, 2015, 11:29am
10
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?
Rewt0r
(Michael Jephcote)
May 13, 2015, 2:16pm
12
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.
Rewt0r
(Michael Jephcote)
May 14, 2015, 10:34am
14
Sorry but I’ve never used Go before, can anyone give me a bit more detail?
Zillode
(Zillode)
May 14, 2015, 7:03pm
15
package main
import (
"fmt"
"net"
)
func main() {
ifaces, err := net.Interfaces()
fmt.Printf("%#v\n", err)
fmt.Printf("%#v\n", ifaces)
}
calmh
(Jakob Borg)
May 15, 2015, 6:08am
16
Script above saved into “interfaces.go”, then go run interfaces.go
.
calmh
(Jakob Borg)
May 15, 2015, 12:29pm
18
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?
Rewt0r
(Michael Jephcote)
May 15, 2015, 12:31pm
19
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