Announce Server Offline permanently on IPv6-only nodes

hobarrera · August 27, 2014, 11:32pm

I followed through the getting starting guide , installed syncthings on two nodes (my main laptop and my main desktop), added each other’s node, and share a repo, but both say permanently “Announce Server Offline”.

First run:

$ [N2QHE] 20:21:11 INFO: syncthing v0.9.5 (go1.3.1 linux-amd64 default) wimpr1m@wimpr1m 2014-08-20 16:14:32 UTC
[N2QHE] 20:21:11 INFO: My ID: N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD
[N2QHE] 20:21:11 INFO: Waiting for parent to exit...
[N2QHE] 20:21:11 INFO: Continuing
[N2QHE] 20:21:11 INFO: Starting web GUI on http://127.0.0.1:8080/
[N2QHE] 20:21:11 INFO: Performing initial repository scan
[N2QHE] 20:21:14 INFO: No UPnP gateway detected
[N2QHE] 20:21:14 INFO: Sending local discovery announcements
[N2QHE] 20:21:14 INFO: Sending global discovery announcements
[N2QHE] 20:21:14 OK: Ready to synchronize default (read-write)
[N2QHE] 20:21:14 INFO: Node N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD is "athena.barrera.io" at [dynamic]
[N2QHE] 20:21:14 INFO: Starting usage reporting
[N2QHE] 20:22:40 INFO: Restarting
[N2QHE] 20:22:40 OK: Exiting

After having restarted with both nodes having added each other:

STTRACE=net syncthing
[N2QHE] 2014/08/27 20:35:55.651078 main.go:269: INFO: syncthing v0.9.5 (go1.3.1 linux-amd64 default) wimpr1m@wimpr1m 2014-08-20 16:14:32 UTC
[N2QHE] 2014/08/27 20:35:55.651194 main.go:270: INFO: My ID: N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD
[N2QHE] 2014/08/27 20:35:55.659048 main.go:436: INFO: Starting web GUI on http://127.0.0.1:8080/
[N2QHE] 2014/08/27 20:35:55.671108 main.go:460: INFO: Performing initial repository scan
[N2QHE] 2014/08/27 20:35:58.671477 main.go:593: INFO: No UPnP gateway detected
[N2QHE] 2014/08/27 20:35:58.671752 main.go:595: DEBUG: UPnP: read udp4 0.0.0.0:60442: i/o timeout
[N2QHE] 2014/08/27 20:35:58.671975 main.go:995: INFO: Sending local discovery announcements
[N2QHE] 2014/08/27 20:35:58.672178 main.go:1000: INFO: Sending global discovery announcements
[N2QHE] 2014/08/27 20:35:58.672351 main.go:507: OK: Ready to synchronize default (read-write)
[N2QHE] 2014/08/27 20:35:58.672666 main.go:523: INFO: Node N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD is "athena.barrera.io" at [dynamic]
[N2QHE] 2014/08/27 20:35:58.672998 main.go:523: INFO: Node RBMRJJN-VGWVNEF-K2ZYTSG-DVLJLK7-SJIZRTB-RQNMVJ3-RPKC7W5-C26QXQQ is "hyperion.barrera.io" at [dynamic]
[N2QHE] 2014/08/27 20:35:58.674333 usage_report.go:93: INFO: Starting usage reporting
[N2QHE] 2014/08/27 20:35:58.675029 main.go:856: DEBUG: listening on 0.0.0.0:22000

I haven’t found much more information regarding why it might say this, or how to debug it. My internet is clearly working since I’m right now posting this from one of the machines involved.

Update: I came across similar threads, and let me clarify: Both nodes are connected straight to the internet, and are completely unfiltered. There are no firewalls of any kind involved.

Update2: I run SSTRACE=discover. Sounds like an actual issue, can somebody confirm this? These nodes are IPv6 only with NAT64 for backwards-compatibility, so syncthings should not attempt to use IPv4:

$ STTRACE=discover syncthing                                                                                                     
[N2QHE] 2014/08/27 20:39:30.639985 main.go:269: INFO: syncthing v0.9.5 (go1.3.1 linux-amd64 default) wimpr1m@wimpr1m 2014-08-20 16:14:32 UTC
[N2QHE] 2014/08/27 20:39:30.640150 main.go:270: INFO: My ID: N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD
[N2QHE] 2014/08/27 20:39:30.643461 main.go:436: INFO: Starting web GUI on http://127.0.0.1:8080/
[N2QHE] 2014/08/27 20:39:30.655509 main.go:460: INFO: Performing initial repository scan
[N2QHE] 2014/08/27 20:39:33.655865 main.go:593: INFO: No UPnP gateway detected
[N2QHE] 2014/08/27 20:39:33.655942 main.go:995: INFO: Sending local discovery announcements
[N2QHE] 2014/08/27 20:39:33.655956 main.go:1000: INFO: Sending global discovery announcements
[N2QHE] 2014/08/27 20:39:33.655975 main.go:507: OK: Ready to synchronize default (read-write)
[N2QHE] 2014/08/27 20:39:33.656133 main.go:523: INFO: Node N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD is "athena.barrera.io" at [dynamic]
[N2QHE] 2014/08/27 20:39:33.656239 main.go:523: INFO: Node RBMRJJN-VGWVNEF-K2ZYTSG-DVLJLK7-SJIZRTB-RQNMVJ3-RPKC7W5-C26QXQQ is "hyperion.barrera.io" at [dynamic]
[N2QHE] 2014/08/27 20:39:33.656264 usage_report.go:93: INFO: Starting usage reporting
[N2QHE] 2014/08/27 20:39:35.720702 discover.go:380: DEBUG: discover: dial udp 194.126.249.5:22026: network is unreachable; no external lookup
[N2QHE] 2014/08/27 20:39:35.720854 discover.go:163: DEBUG: discover: announcing 0.0.0.0:22000: &net.TCPAddr{IP:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x0, 0x0, 0x0, 0x0}, Port:22000, Zone:""}
[N2QHE] 2014/08/27 20:39:35.720918 discover.go:234: DEBUG: discover: send announcement -> 194.126.249.5:22026
00000000  9d 79 bc 39 00 00 00 20  6e a0 72 47 89 7f 77 c4  |.y.9... n.rG..w.|
00000010  8d e9 c4 3c bf 3a 6a 87  6e 99 e2 bb 6a f7 39 45  |...<.:j.n...j.9E|
00000020  a4 3b 73 84 fb de 92 2b  00 00 00 01 00 00 00 00  |.;s....+........|
00000030  00 00 55 f0 00 00 00 00                           |..U.....|
[N2QHE] 2014/08/27 20:39:35.720952 discover.go:240: DEBUG: discover: warning: write udp: network is unreachable
[N2QHE] 2014/08/27 20:39:36.753934 discover.go:380: DEBUG: discover: dial udp 194.126.249.5:22026: network is unreachable; no external lookup
[N2QHE] 2014/08/27 20:39:38.782269 discover.go:380: DEBUG: discover: dial udp 194.126.249.5:22026: network is unreachable; no external lookup
[N2QHE] 2014/08/27 20:39:42.837449 discover.go:380: DEBUG: discover: dial udp 194.126.249.5:22026: network is unreachable; no external lookup

Update3: Updated title to reflect the actual issue.

calmh · August 28, 2014, 5:42am

Syncthing will send packets to the IP that the announce server resolves to. You should probably double check your NAT setup?

jpjp · August 28, 2014, 7:31am

Does it re-resolve the ip if the network isn’t fully up when syncthing starts?

calmh · August 28, 2014, 9:13am

Yep, it does that nowadays. We see above that it tries to send the discovery packets:

[N2QHE] 2014/08/27 20:39:35.720702 discover.go:380: DEBUG: discover: dial udp 194.126.249.5:22026: network is unreachable; no external lookup

But IPv4 is not reachable here, so that doesn’t work. I would guess that the NAT64 stuff should rewrite the DNS reply for announce.syncthing.net so that it gets an IPv6 address instead, but that doesn’t seem to have happened.

hobarrera · August 28, 2014, 2:09pm

There’s only NAT64, no NAT. What would you want me to check about it?

hobarrera · August 28, 2014, 2:12pm

Indeed, DNS64 does this:

$ dig +short AAAA announce.syncthing.net
64:ff9b::c27e:f905

Which is equivalent to 64:ff9b::194.126.249.5. The ISP gateway then maps the 64:ff9b::/96 block to the entire IPv4 namespace, which is how I access any IPv4-only host.

It would seem that the problem is that synceverything is prefering IPv4, agains the OS preferred settings, and even in a complete lack of IPv4 routes.

calmh · August 28, 2014, 6:23pm

Looks like the Go resolver, which is what is used in the static binaries, looks up A and AAAA addresses and uses all of the results, in order. Since the binary is statically linked, it has no way to talk to the system resolver library.

http://golang.org/src/pkg/net/dnsclient_unix.go#L310

I would guess that a dynamic binary built for your system would have the behavior you expect.

hobarrera · August 28, 2014, 6:49pm

If the go resolver returns both the A and AAAA records, then shouldn’t syncthing be trying all of them in order, instead of failing over and over with the first result.

calmh · August 28, 2014, 6:51pm

I don’t know, I haven’t tested it. It sounds like that would be desirable.

hobarrera · August 28, 2014, 6:57pm

How would I have to alter the build process to get such a binary?

calmh · August 28, 2014, 7:21pm

Hmm, if you built it locally, I would think you already got it. What does file and ldd on the binary say? If ldd gives a list if libraries, including libc.so, then it should be using the system resolver.

hobarrera · August 28, 2014, 7:42pm

Apparently, it should be using the system resolver:

$ ldd $(which syncthing )
        linux-vdso.so.1 (0x00007fff6a5fc000)
        libpthread.so.0 => /usr/lib/libpthread.so.0 (0x00007f82537a7000)
        libc.so.6 => /usr/lib/libc.so.6 (0x00007f82533f9000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f82539c5000)

Or am I mistaken?

calmh · August 28, 2014, 7:56pm

Indeed! But then, http://golang.org/src/pkg/net/ipsock.go#L75

hobarrera · August 29, 2014, 12:39am

Ugh, just awful. So, by default, IPv4 is used, even if I have no IPv4 addresses on my networks, without retrying anything else? I’ve come across these sort of issues before with golang, which I why I constantly claim it’s very ill-suited for network applications.

Is there any workaround we can do for now, or do we need for upstream to fix this?

hobarrera · August 29, 2014, 12:52am

Indeed, it looks like and issue in golang I’ve come across before: https://code.google.com/p/go/issues/detail?id=8124

Am I mistaken in thinking there are no workarounds?

calmh · August 29, 2014, 12:06pm

You could just set the announce server address to [64:ff9b::c27e:f905]::22026.

It’ll still get a v4 packet from whatever it is that does your v6-to-v4 NAT and use that as the public address for your node, though.

It wouldn’t be terribly difficult to just add an AAAA record for the discovery server and let it use the v6 addresses it sees that way. Although obviously there are corner cases with then answer questions on v4 with v6 addresses etc… The interoperability here is a bit painful.

Or you could just skip the global discovery and use dynamic DNS or similar.

hobarrera · August 29, 2014, 1:02pm

That sort of works - I no longer get Announce Server Offline, but each node still sees the other offline.

Thinking about it carefully, this will not work. The announce server will receive a packet with an origin address of a shared IPv4 address (shared via NAT64). It would then relate my node with that IP, which actually belongs to an ISP-level gateway which has that IPv4 address.

Of course there might be workarounds (similar to NATPMP on traditional NATs), but considering that each machine has a public, static IPv6 address, I’d rather use that.

I don’t actually need dynamic DNS. Each machine has a publicly accesible, static, IPv6 address. There’s static DNS records for each one.

The only issue is that my laptop moves outside of my home network, so it’s IP would change there (I move to some places with IPv6, dual stack, and IPv4). If every remote location had IPv6 connectivity, I’d just use mobile IPv6, but that’s honestly not an option.

So global discovery would probably be best to keep it alive in those situations.

Does the announce server currently has an assigned IPv6 address? If so, I could run some test on my own before you add this record. (Also, since go does not try multiple DNS results, I think a differente domain would be best. eg: ipv6.announce.syncthing.net).

calmh · August 29, 2014, 2:17pm

The announce server is at 2001:470:28:4d6::5 so yeah, you could test that. I think it should handle IPv6 announces and respond with the IPv6 address, but I haven’t tested it at all.

hobarrera · August 29, 2014, 2:55pm

This has been an improvement. Using the IPv6 literal for the announce server worked (Announce Server: Online), but the nodes still see each other as disconnected:

$ STTRACE=discover syncthing 
[N2QHE] 2014/08/29 11:47:41.425835 main.go:269: INFO: syncthing v0.9.5 (go1.3.1 linux-amd64 default) wimpr1m@wimpr1m 2014-08-20 16:14:32 UTC
[N2QHE] 2014/08/29 11:47:41.426003 main.go:270: INFO: My ID: N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD
[N2QHE] 2014/08/29 11:47:41.431969 main.go:436: INFO: Starting web GUI on http://127.0.0.1:8080/
[N2QHE] 2014/08/29 11:47:41.445548 main.go:460: INFO: Performing initial repository scan
[N2QHE] 2014/08/29 11:47:44.446045 main.go:593: INFO: No UPnP gateway detected
[N2QHE] 2014/08/29 11:47:44.446322 main.go:995: INFO: Sending local discovery announcements
[N2QHE] 2014/08/29 11:47:44.446454 main.go:1000: INFO: Sending global discovery announcements
[N2QHE] 2014/08/29 11:47:44.446678 main.go:507: OK: Ready to synchronize default (read-write)
[N2QHE] 2014/08/29 11:47:44.447064 main.go:523: INFO: Node N2QHER4-JP534JE-DPJYQ6L-6OTKQ5T-XJTYV3N-L3TSRNA-EHNZYJ6-66SIVQD is "athena.barrera.io" at [dynamic]
[N2QHE] 2014/08/29 11:47:44.447486 main.go:523: INFO: Node RBMRJJN-VGWVNEF-K2ZYTSG-DVLJLK7-SJIZRTB-RQNMVJ3-RPKC7W5-C26QXQQ is "hyperion.barrera.io" at [dynamic]
[N2QHE] 2014/08/29 11:47:44.447630 discover.go:163: DEBUG: discover: announcing 0.0.0.0:22000: &net.TCPAddr{IP:net.IP{0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xff, 0xff, 0x0, 0x0, 0x0, 0x0}, Port:22000, Zone:""}
[N2QHE] 2014/08/29 11:47:44.447707 discover.go:234: DEBUG: discover: send announcement -> [2001:470:28:4d6::5]:22026
00000000  9d 79 bc 39 00 00 00 20  6e a0 72 47 89 7f 77 c4  |.y.9... n.rG..w.|
00000010  8d e9 c4 3c bf 3a 6a 87  6e 99 e2 bb 6a f7 39 45  |...<.:j.n...j.9E|
00000020  a4 3b 73 84 fb de 92 2b  00 00 00 01 00 00 00 00  |.;s....+........|
00000030  00 00 55 f0 00 00 00 00                           |..U.....|
[N2QHE] 2014/08/29 11:47:44.447830 usage_report.go:93: INFO: Starting usage reporting
[N2QHE] 2014/08/29 11:47:44.706784 discover.go:417: DEBUG: discover: read external:
00000000  9d 79 bc 39 00 00 00 20  88 59 14 a5 b5 35 aa d2  |.y.9... .Y...5..|
00000010  2b 59 c4 e4 61 d5 69 5a  a4 94 66 33 0c 60 d6 55  |+Y..a.iZ..f3.`.U|
00000020  31 7a 85 fb 74 5a f4 2f  00 00 00 01 00 00 00 10  |1z..tZ./........|
00000030  28 00 00 40 07 aa 00 01  76 d0 2b ff fe 9d de 64  |(..@....v.+....d|
00000040  00 00 55 f0 00 00 00 00                           |..U.....|
[N2QHE] 2014/08/29 11:47:45.715713 discover.go:417: DEBUG: discover: read external:
00000000  9d 79 bc 39 00 00 00 20  6e a0 72 47 89 7f 77 c4  |.y.9... n.rG..w.|
00000010  8d e9 c4 3c bf 3a 6a 87  6e 99 e2 bb 6a f7 39 45  |...<.:j.n...j.9E|
00000020  a4 3b 73 84 fb de 92 2b  00 00 00 01 00 00 00 10  |.;s....+........|
00000030  28 00 00 40 07 aa 00 01  ba e8 56 ff fe 18 7b f6  |(..@......V...{.|
00000040  00 00 55 f0 00 00 00 00                           |..U.....|
[N2QHE] 2014/08/29 11:47:45.715786 discover.go:249: DEBUG: discover: external lookup check: [2800:40:7aa:1:bae8:56ff:fe18:7bf6:22000]

I enabled STTRACE=net:

[N2QHE] 2014/08/29 11:54:11.399393 main.go:929: DEBUG: dial RBMRJJN-VGWVNEF-K2ZYTSG-DVLJLK7-SJIZRTB-RQNMVJ3-RPKC7W5-C26QXQQ 2800:40:7aa:1:76d0:2bff:fe9d:de64:22000
[N2QHE] 2014/08/29 11:54:11.399420 main.go:935: DEBUG: too many colons in address 2800:40:7aa:1:76d0:2bff:fe9d:de64:22000

(this repeats over and over). It seems that there’s some issue on how IPs are parsed, and IPv4 literals are expected (notice the missing brackets as well). Also, rather than DEBUG, this should be a WARN or ERR, IMHO.

calmh · August 29, 2014, 3:14pm

Yeah, that’s obviously a bug, should be easy to fix.