Cannot connect via proxy since upgrade to 0.13

  • device1 – NAS ARM x86 client 0.13.4
  • device 2 – Ubuntu 14.04 x64 client 0.13.4
  • device 3 - Windows client 0.13.4 + SyncTrayzor behind SOCKS5 proxy (all_proxy=socks5://socks_ip:1080, ALL_PROXY_NO_FALLBACK=1)

Using custom discovery server and custom relay server on my VPS.

discosrv - discovery_ip:8443, version 0.13, relaysrv - relay_ip:22067, version 0.12.18

device1, device2, android – connecting with each other, device3 behind SOCKS5 proxy – connection error, other devices disconnected.

This configuration perfectly work with 0.12.25 clients and discosrv 0.12, all devices can connect with each other, after upgrade to 0.13 device 3 cannot connect to other devices.

device 3 Windows client log:

[BCHLI] 08:18:06 INFO: syncthing v0.13.4 "Copper Cockroach" (go1.6.2 windows-amd64) WIN-P6RP886TVDJ\Administrator@WIN-P6RP886TVDJ 2016-05-26 09:16:08 UTC
[BCHLI] 08:18:06 INFO: My ID: xxxx
[BCHLI] 08:18:06 INFO: Single thread hash performance is ~188 MB/s
[BCHLI] 08:18:06 INFO: Ready to synchronize xxxx- xxxx - xxxx - xxxx - xxxx (readwrite)
[BCHLI] 08:18:06 INFO: Using discovery server https://discovery_ip:8443/v2/?id=XXXXXX
[BCHLI] 08:18:06 INFO: Completed initial scan (rw) of folder xxxx - xxxx - xxxx - xxxx - xxxx
[BCHLI] 08:18:06 INFO: Device CMLLGPN is "device1" at [dynamic]
[BCHLI] 08:18:06 INFO: Device FWP74MK is " device 2" at [dynamic]
[BCHLI] 08:18:06 INFO: Device XWOUZVI is "android" at [dynamic]
[BCHLI] 08:18:06 INFO: Device BCHLII5 is " device 3" at [dynamic]
[BCHLI] 08:18:06 INFO: GUI and API listening on 127.0.0.1:8384
[BCHLI] 08:18:06 INFO: Access the GUI via the following URL: https://localhost:8384/
[BCHLI] 08:18:06 INFO: Proxy settings detected
[BCHLI] 08:18:06 INFO: Proxy fallback disabled
[BCHLI] 08:18:08 INFO: Joined relay relay:// relay_ip:22067
2016/05/31 08:24:59 Supervisor connections.Service: connections.Service: Failed service 'relay:// relay_ip:22067' (1.000000 failures of 5.000000), restarting: true, error: interface conversion: net.Conn is dialer.dialerConn, not *net.TCPConn, stacktrace: goroutine 52 [running]:
github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1.1(0xc082166b60, 0x2)
	c:/jenkins/workspace/syncthing-release-windows/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/suture.go:550 +0xb6
panic(0xb7f6a0, 0xc08264b140)
	c:/go/src/runtime/panic.go:443 +0x4f7
github.com/syncthing/syncthing/lib/connections.(*relayListener).Serve(0xc082422f00)
	c:/jenkins/workspace/syncthing-release-windows/src/github.com/syncthing/syncthing/lib/connections/relay_listen.go:77 +0xc92
github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1(0xc082166b60, 0x2, 0x1e52290, 0xc082422f00)
	c:/jenkins/workspace/syncthing-release-windows/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/suture.go:556 +0x65
created by github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService
	c:/jenkins/workspace/syncthing-release-windows/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/suture.go:559 +0x58
[BCHLI] 08:25:01 INFO: Could not join relay relay:// relay_ip:22067: Incorrect response code 2: already connected

Relay debug log

2016/05/31 08:26:16 session.go:182: Session <f2f25/2442f> timed out
2016/05/31 08:26:16 session.go:212: Session <f2f25/2442f> stopping
2016/05/31 08:26:58 listener.go:105: Message protocol.Pong from YYYYYY- YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY
2016/05/31 08:26:59 session.go:176: Session <7ce19/f70b1> ended, outcomes: read tcp relay_ip:22067->YYYY_ip:27459: i/o timeout and EOF
2016/05/31 08:26:59 session.go:212: Session <7ce19/f70b1> stopping
2016/05/31 08:27:05 listener.go:38: Listener failed to accept connection from YYYY_ip:21907 . Possibly a TCP Ping.
2016/05/31 08:27:07 listener.go:250: XXXXXX- XXXXXX - XXXXXX - XXXXXX - XXXXXX - XXXXXX - XXXXXX - XXXXXX timed out
2016/05/31 08:27:07 listener.go:197: Closing connection XXXXXX - XXXXXX - XXXXXX - XXXXXX - XXXXXX - XXXXXX - XXXXXX - XXXXXX: xdr read: read tcp relay_ip:22067->relay_ip:54018: use of closed network connection
2016/05/31 08:27:57 listener.go:105: Message protocol.Pong from YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY
2016/05/31 08:29:00 listener.go:105: Message protocol.Pong from YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY
2016/05/31 08:29:05 listener.go:46: Listener accepted connection from YYYYYY_IP:53798 tls true
2016/05/31 08:29:09 listener.go:105: Message protocol.ConnectRequest from YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY
2016/05/31 08:29:09 listener.go:146: YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY is looking for BCHLII5-TJXRNJW-IJSROZN-CWGXDG2-YZKTS2Z-XSIP73K-G4TRQAM-HZRJ4AD which does not exist
2016/05/31 08:29:09 listener.go:197: Closing connection YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY: xdr read: read tcp relay_ip:22067->YYYYYY _IP:53798: use of closed network connection
2016/05/31 08:29:55 listener.go:46: Listener accepted connection from YYYYYY _IP:23803 tls true
2016/05/31 08:29:57 listener.go:105: Message protocol.Pong from YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY
2016/05/31 08:29:58 listener.go:105: Message protocol.ConnectRequest from YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY
2016/05/31 08:29:58 listener.go:146: YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY is looking for BCHLII5-TJXRNJW-IJSROZN-CWGXDG2-YZKTS2Z-XSIP73K-G4TRQAM-HZRJ4AD which does not exist
2016/05/31 08:29:58 listener.go:197: Closing connection YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY - YYYYYY: xdr read: read tcp relay_ip:22067->YYYYYY _IP:23803: use of closed network connection
1 Like

Looks like relays via proxy may be broken currently. I created a bug ticket:

I have the same (but without custom discovery and custom relay). Let me know if I can help to test something.

I’ve fixed the panics, but I think there remain issues with relays over proxy… If you like you can try the latest dev build (linked at the top of the page) for that fix and see if you get the same errors that I do. :slight_smile:

I don’t see a Windows x64 build at https://build.syncthing.net/job/syncthing/lastSuccessfulBuild. Is that not available? I can also try to build the latest github version from source (but not today).

See the “for Windows” link above :slight_smile:

Ugh :). In the meantime I got the build from github.com working. No panics anymore, but still no successful connection. Would it help to post e.g. my logfile? If yes: where, and is there a simple way to obfuscate my private details?

Here’s at least a part of it. There’s a lot of rapid ‘success’ connection messages before it hits a relay, but then it fails:

[HCSAA] 2016/05/31 11:33:32.131804 internal.go:59: DEBUG: Dialing tcp address 46.105.55.153:52067 via proxy - success, [::1]:51603 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:32.204811 internal.go:59: DEBUG: Dialing tcp address 50.3.75.246:22067 via proxy - success, [::1]:51604 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:32.283819 internal.go:59: DEBUG: Dialing tcp address 212.47.241.21:22067 via proxy - success, [::1]:51605 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:32.679859 internal.go:59: DEBUG: Dialing tcp address 104.171.113.18:10508 via proxy - success, [::1]:51606 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:32.774868 internal.go:59: DEBUG: Dialing tcp address 163.172.210.93:22067 via proxy - success, [::1]:51607 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:33.098901 internal.go:59: DEBUG: Dialing tcp address 45.62.241.165:22067 via proxy - success, [::1]:51608 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:33.169908 internal.go:59: DEBUG: Dialing tcp address 91.121.160.153:22067 via proxy - success, [::1]:51609 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:33.415932 internal.go:59: DEBUG: Dialing tcp address 144.168.43.163:22067 via proxy - success, [::1]:51610 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:33.593950 internal.go:59: DEBUG: Dialing tcp address 43.239.250.13:443 via proxy - success, [::1]:51611 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:33.725963 internal.go:59: DEBUG: Dialing tcp address 95.31.237.2:22067 via proxy - success, [::1]:51612 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:33.799971 internal.go:59: DEBUG: Dialing tcp address 37.187.105.88:22067 via proxy - success, [::1]:51613 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:34.144005 internal.go:59: DEBUG: Dialing tcp address 173.230.149.23:22067 via proxy - success, [::1]:51614 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:34.234014 internal.go:59: DEBUG: Dialing tcp address 192.166.219.89:22067 via proxy - success, [::1]:51615 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:34.330024 internal.go:59: DEBUG: Dialing tcp address 31.31.75.186:22067 via proxy - success, [::1]:51616 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:34.561047 internal.go:59: DEBUG: Dialing tcp address 212.47.253.154:22067 via proxy - success, [::1]:51617 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:34.632054 internal.go:59: DEBUG: Dialing tcp address 185.21.217.78:22067 via proxy - success, [::1]:51618 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:34.711062 internal.go:59: DEBUG: Dialing tcp address 185.120.20.7:11612 via proxy - success, [::1]:51619 -> [::1]:1080
[HCSAA] 2016/05/31 11:33:34.991090 static.go:92: INFO: Joined relay relay://185.120.20.7:11612
[HCSAA] 2016/05/31 11:33:37.767368 internal.go:65: DEBUG: Dialing tcp address discovery-v6-2.syncthing.net:443 via proxy - error proxy: failed to read connect reply from SOCKS5 proxy at localhost:1080: EOF
[HCSAA] 2016/05/31 11:33:37.774368 internal.go:65: DEBUG: Dialing tcp address discovery-v6-3.syncthing.net:443 via proxy - error proxy: failed to read connect reply from SOCKS5 proxy at localhost:1080: EOF
[HCSAA] 2016/05/31 11:33:37.775368 internal.go:65: DEBUG: Dialing tcp address discovery-v6-1.syncthing.net:443 via proxy - error proxy: failed to read connect reply from SOCKS5 proxy at localhost:1080: EOF
[HCSAA] 2016/05/31 11:33:37.792370 internal.go:59: DEBUG: Dialing tcp address discovery-v4-1.syncthing.net:443 via proxy - success, [::1]:51623 -> [::1]:1080
[HCSAA] 2016/05/31 11:35:34.165006 internal.go:65: DEBUG: Dialing tcp address <MY OTHER PC IP>:22000 via proxy - error proxy: failed to read connect reply from SOCKS5 proxy at localhost:1080: EOF

I now also notice it tries to connect to <MY OTHER PC IP>:22000 but my “other PC” is not at the default port 22000 anymore.

Last succesfull build for windows, which linked at the top of the page (https://build.syncthing.net/job/syncthing-windows/lastSuccessfulBuild/) is version 0.12.9 (syncthing-windows-amd64-v0.12.9+5-g435afa0.zip ), not 0.13.4

Yeah that matches what happens for me, unfortunately.

Woops. Fixed, I think.

Did you note my comment

A naïeve thought, but could it be that non-default ports are forgotten when using a proxy to connect?

That would be odd, but maybe not impossible.

Download from this link: https://build.syncthing.net/job/syncthing-pr-windows/ buld syncthing-windows-amd64-v0.13.4+35-g6b9f3c3.zip. My problems was resolved. I can connect android device with PC behind SOCKS proxy. Thank you for your help!

I still get panics with that version

[HCSAA] 2016/05/31 14:31:43.206320 main.go:568: INFO: syncthing v0.13.4+38-gdd34878 "Copper Cockroach" (go1.6.2 windows-386)
[HCSAA] 2016/05/31 14:31:51.263655 internal.go:59: DEBUG: Dialing tcp address 104.171.113.18:10508 via proxy - success, [::1]:50647 -> [::1]:1080
2016/05/31 14:31:51 Supervisor connections.Service: connections.Service: Failed service '(connections.serviceFunc)(0x6ec9b0)' (1.000000 failures of 5.000000), restarting: true, error: interface conversion: net.Addr is dialer.fallbackAddr, not *net.TCPAddr, stacktrace: goroutine 49 [running]:
github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1.1(0x1182b5f0, 0x0)
    c:/jenkins/workspace/syncthing-pr-windows/src/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/suture.go:550 +0x97
panic(0x9eb520, 0x114ca120)
    c:/go-386/src/runtime/panic.go:443 +0x3fd

That link is whatever the latest pull request is, and currently that’s something entirely different. Use the “for Windows” link at the top - it’s fixed now.

Still panics, but I think at different locations

[HCSAA] 2016/05/31 15:47:11.820596 main.go:568: INFO: syncthing v0.13.4+13-g1378943 "Copper Cockroach" (go1.6 windows-amd64)
[HCSAA] 2016/05/31 15:47:12.304202 internal.go:43: INFO: Proxy settings detected
[HCSAA] 2016/05/31 15:47:12.304202 internal.go:45: INFO: Proxy fallback disabled
[HCSAA] 2016/05/31 15:47:19.615838 internal.go:59: DEBUG: Dialing tcp address 91.134.217.196:22067 via proxy - success, [::1]:52584 -> [::1]:1080
2016/05/31 15:47:19 Supervisor connections.Service: connections.Service: Failed service '(connections.serviceFunc)(0x7770e0)' (1.000000 failures of 5.000000), restarting: true, error: interface conversion: net.Addr is dialer.fallbackAddr, not *net.TCPAddr, stacktrace: goroutine 49 [running]:
github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1.1(0xc08216ea90, 0x6609b7100000000)
	~/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/suture.go:550 +0xb6
panic(0xb7f100, 0xc08255d240)
	~/go/src/runtime/panic.go:426 +0x4f7
github.com/syncthing/syncthing/lib/relay/client.GetInvitationFromRelay(0xc082c7ec00, 0xec9af854babf97e5, 0xf30bfd863447ceae, 0xe42a34c3b3f18f3c, 0x85a90f2a5c6b02fd, 0xc0823e2d20, 0x1, 0x1, 0x2540be400, 0x0, ...)
	~/github.com/syncthing/syncthing/lib/relay/client/methods.go:58 +0xe4c
github.com/syncthing/syncthing/lib/connections.(*relayDialer).Dial(0xc0842b7c80, 0xec9af854babf97e5, 0xf30bfd863447ceae, 0xe42a34c3b3f18f3c, 0x85a90f2a5c6b02fd, 0xc082c7ec00, 0x0, 0x0, 0x0, 0x0, ...)
	~/github.com/syncthing/syncthing/lib/connections/relay_dial.go:32 +0xc5
github.com/syncthing/syncthing/lib/connections.(*Service).connect(0xc082f593b0)
	~/github.com/syncthing/syncthing/lib/connections/service.go:347 +0x234f
github.com/syncthing/syncthing/lib/connections.(*Service).(github.com/syncthing/syncthing/lib/connections.connect)-fm()
	~/github.com/syncthing/syncthing/lib/connections/service.go:108 +0x27
github.com/syncthing/syncthing/lib/connections.serviceFunc.Serve(0xc0836a5de0)
	~/github.com/syncthing/syncthing/lib/connections/structs.go:80 +0x20
github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService.func1(0xc08216ea90, 0x0, 0x145ebc8, 0xc0836a5de0)
	~/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/suture.go:556 +0x65
created by github.com/syncthing/syncthing/vendor/github.com/thejerf/suture.(*Supervisor).runService
	~/github.com/syncthing/syncthing/vendor/github.com/thejerf/suture/suture.go:559 +0x58

Thanks, that we can fix.

I think the offending line in code is here

msg.Address = conn.RemoteAddr().(*net.TCPAddr).IP[:]

I tried to see if I could fix something myself, but I don’t know enough about go syntax… conn.RemoteAddr() gives gives an Addr interface (https://golang.org/pkg/net/#Addr), but what does .(*net.TCPAddr) do?

Yes. Fix: https://github.com/syncthing/syncthing/pull/3230

.(*net.TCPAddr) is a type assertion, which extracts the inner type from the interface or (in this case) panics when it isn’t what we say it must be. The “root” issue here being that the code expects a regular TCP connection, which is usually a safe bet. However we’re wrapping it in a proxy connection which lies about the remote address (the actual remote address is just the proxy).

Thanks: this fixes my socks5 connection. Thanks also for the explanation :slight_smile:

1 Like