v0.14.40 fails to connect


(Wolf) #21

Hei.

Like janc1 I am using syncthing in a local environment. Thus only “Local Discovery” is activated, but I see the same entries of KCP being started on :22020 and it’s outbound connection to a stun.* domain. The domain changes, it always starts with “stun.” After that the connection is handed over from KCP to TCP.

Allow me to ask, from under my tinfoil hat, how can I persuade Syncthing to * not * start KCP? I would like Syncthing to stay private (in the sense of not announcing its presence to anybody outside this local network). At least until I choose to activate options like NAT traversal, global discovery or relaying. Maybe this could be made as an option in a future version?

I’d be ready to edit the config file or set an option in the advanced config, if that was possible?
Any solution?

Small update: Blocking the ports stun 3478 and ndmp 10000 hands over the connection from KCP to TCP, then the connection fails. Syncthing then picks it up again.
Looks roughly like this:

INFO: Established secure connection to YYYY at [::]:22020-192.168.254.21:22020 (kcp-client)
INFO: Established secure connection to YYYY at 192.168.254.34:49529-192.168.254.21:22000 (tcp-client)
INFO: Replacing old connection [::]:22020-192.168.254.21:22020/kcp-client with 192.168.254.34:49529-192.168.254.21:22000/tcp-client for YYYY
INFO: Connection to YYYY closed: reading length: broken pipe
INFO: Connected to already connected device (YYYY)

#22

specifically:

and

Also:


(Wolf) #23

Thanks! Sorry, I’ve not found those. I do not quite understand the last quote - thats for a future development, correct?


#24

Yes, that is a suggestion how to remake the listen address field, as currently default means tcp://:22000, {relay adress}, {kcp address}.


(usernamegoeshere) #25

My distant win10 x64 machine is back again with nonconnecting at all.

rebooted the syncthing and logs stop there with stun detected the kcp stuff externally

thats all it is

it never connects home to its single neighbor peer the linux machine

what the heck is wrong here? :(( syncthing is nonusable for this setup here. where can i mail in sensitive log data i dont wana post the filenames and sharenames here that hint to private and sensitive data.

is there a direct email contact for this? the main developers? thanks for helping. 0.14.40 is really dead for me, it very seldomly conncects

last contact back home to the linux machine of this win10 x64 machine was on november 10th :frowning:


#26

0.14.40 doesn’t work for me either. 0.14.39 is fine. Wouldn’t it be relatively easy to diff the code between the versions and track down the reason for this?


(Audrius Butkevicius) #27

We know what code has changed, that’s not the problem. We don’t know why it doesn’t work for some users.

We need to gather as many logs as possible, from both sides of devices to understand what’s happening. Reverting to an older version and not helping us debug will not make the issue go away in future releases.


(usernamegoeshere) #28

The project maintainer or original author replied to me as private message that he wouldnt take my log files, as I wont post all my share names and internal messages onto this public board. So i am out i definitely wont post this kind of sentitive information into the public.

I can share this from the linux machine, this is what the screen window shows for the last few days as only logmessages:

[3PKT3] 04:48:46 INFO: kcp://0.0.0.0:22020 resolved external address kcp://84.189.33.5:22020 (via stun.counterpath.net:3478)
[3PKT3] 05:14:50 INFO: Removing NAT port mapping: external TCP address 87.176.82.175:51852, NAT 75802409-bccb-40e7-8e6c-3810D51EDC03 is no longer available.
[3PKT3] 05:14:50 INFO: New NAT port mapping: external TCP address 84.189.33.5:51852 to local address 0.0.0.0:22000.
[3PKT3] 05:14:50 INFO: Removing NAT port mapping: external TCP address 87.176.82.175:13762, NAT 75802409-bccb-40e7-9f6c-3810D51EDC03 is no longer available.
[3PKT3] 05:14:50 INFO: New NAT port mapping: external TCP address 84.189.33.5:13762 to local address 0.0.0.0:22000.
[3PKT3] 13:31:25 INFO: Sent usage report (version 3)
[3PKT3] 04:47:43 INFO: kcp://0.0.0.0:22020 resolved external address kcp://87.176.85.36:22020 (via stun.counterpath.net:3478)
[3PKT3] 04:52:40 INFO: Removing NAT port mapping: external TCP address 84.189.33.5:51852, NAT 75802409-bccb-40e7-8e6c-3810D51EDC03 is no longer available.
[3PKT3] 04:52:40 INFO: New NAT port mapping: external TCP address 87.176.85.36:51852 to local address 0.0.0.0:22000.
[3PKT3] 04:52:40 INFO: Removing NAT port mapping: external TCP address 84.189.33.5:13762, NAT 75802409-bccb-40e7-9f6c-3810D51EDC03 is no longer available.
[3PKT3] 04:52:40 INFO: New NAT port mapping: external TCP address 87.176.85.36:13762 to local address 0.0.0.0:22000.
[3PKT3] 13:31:27 INFO: Sent usage report (version 3)
[3PKT3] 04:46:36 INFO: kcp://0.0.0.0:22020 resolved external address kcp://84.189.33.31:22020 (via stun.counterpath.net:3478)
[3PKT3] 05:00:40 INFO: Removing NAT port mapping: external TCP address 87.176.85.36:13762, NAT 75802409-bccb-40e7-9f6c-3810D51EDC03 is no longer available.
[3PKT3] 05:00:40 INFO: New NAT port mapping: external TCP address 84.189.33.31:13762 to local address 0.0.0.0:22000.
[3PKT3] 05:00:40 INFO: Removing NAT port mapping: external TCP address 87.176.85.36:51852, NAT 75802409-bccb-40e7-8e6c-3810D51EDC03 is no longer available.
[3PKT3] 05:00:40 INFO: New NAT port mapping: external TCP address 84.189.33.31:51852 to local address 0.0.0.0:22000.
[3PKT3] 08:57:58 INFO: kcp://0.0.0.0:22020 detected NAT type: Restricted NAT
[3PKT3] 09:01:30 INFO: kcp://0.0.0.0:22020 detected NAT type: Full cone NAT
[3PKT3] 13:31:28 INFO: Sent usage report (version 3)

the windows machine shows after a little few minutes after a restart:

[IOEPM] 15:31:26 INFO: Detected 2 NAT devices
[IOEPM] 15:31:28 INFO: Joined relay relay://212.25.15.128:22067
[IOEPM] 15:31:35 INFO: kcp://0.0.0.0:22020 detected NAT type: Port restricted NAT
[IOEPM] 15:31:35 INFO: kcp://0.0.0.0:22020 resolved external address kcp://88.130.49.164:38094 (via stun.voipbuster.com:3478)
[IOEPM] 16:01:17 INFO: Sent usage report (version 3)

thats all and never shows anything therafter.


(usernamegoeshere) #29

The windows machine gotton restarted this afternoon or so. Nothing happened. The linux machine restarted the screen right now, and these two nodes of the pack (others are involved too but all last connected on the 10th of november 2017) are connecting right now after the linux machine has restarted (syncthing process) as well

there is something wrong with the connection loop speaking in a laymans way.


(Audrius Butkevicius) #30

run with STTRACE=connections env var on both sides, and post logs after both sides not connecting for 10-20 minutes


(usernamegoeshere) #31

These two machines I can grab hold of, are connecting right now after both sides have restarted. How is this gonna help now? Wouldnt we need “logs” from when no connection is possible?

Normal logs from right after the restart of the linux syncthing process at the end of the log it writes:

[3PKT3] 22:32:27 INFO: Established secure connection to IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB at [::]:22020-88.130.49.164:38094 (kcp-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[3PKT3] 22:32:27 INFO: Device IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB client is "syncthing v0.14.40" named "SMULAP01"
[3PKT3] 22:32:36 INFO: New NAT port mapping: external TCP address 84.189.33.31:13762 to local address 0.0.0.0:22000.
[3PKT3] 22:32:36 INFO: New NAT port mapping: external TCP address 84.189.33.31:51852 to local address 0.0.0.0:22000.
[3PKT3] 22:32:36 INFO: Detected 3 NAT devices
[3PKT3] 22:32:38 INFO: Joined relay relay://37.120.167.213:22067
2017-11-13 22:32:56
$ [3PKT3] 22:33:01 INFO: Established secure connection to IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB at 192.168.188.38:22000-88.130.49.164:38117 (tcp-server) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[3PKT3] 22:33:01 INFO: Replacing old connection [::]:22020-88.130.49.164:38094/kcp-server with 192.168.188.38:22000-88.130.49.164:38117/tcp-server for IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB
[3PKT3] 22:33:01 INFO: Connection to IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB closed: reading length: broken pipe
[3PKT3] 22:33:01 INFO: Device IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB client is "syncthing v0.14.40" named "SMULAP01"

smulap01 is the win10 x64 machine that i can admin right now remotely.


(usernamegoeshere) #32

Where do I attach then rather lengthy and extensive logfiles? or is there a special mail or development address to submit to? I already asked before.

I am seeing tcp with an ipv6 address, at the end permission denied, although the linux machine does have ipv6 dual stack

[3PKT3] 2017/11/13 22:41:20.648963 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://88.130.49.164:22000
[3PKT3] 2017/11/13 22:41:22.717589 structs.go:32: INFO: New NAT port mapping: external TCP address 84.189.33.31:13762 to local address 0.0.0.0:22000.
[3PKT3] 2017/11/13 22:41:22.759975 structs.go:32: INFO: New NAT port mapping: external TCP address 84.189.33.31:51852 to local address 0.0.0.0:22000.
[3PKT3] 2017/11/13 22:41:22.760185 service.go:61: INFO: Detected 3 NAT devices
[3PKT3] 2017/11/13 22:41:24.296859 static.go:93: INFO: Joined relay relay://89.46.70.108:22067
[3PKT3] 2017/11/13 22:41:30.649346 tcp_dial.go:36: DEBUG: dial tcp 88.130.49.164:22000: i/o timeout
[3PKT3] 2017/11/13 22:41:30.649457 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://88.130.49.164:22000 dial tcp 88.130.49.164:22000: i/o timeout
[3PKT3] 2017/11/13 22:41:30.649529 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://[2001:16b8:46b0:8700:81d2:778a:2744:2c2e]:22000
[3PKT3] 2017/11/13 22:41:30.700418 tcp_dial.go:36: DEBUG: dial tcp [2001:16b8:46b0:8700:81d2:778a:2744:2c2e]:22000: getsockopt: permission denied
[3PKT3] 2017/11/13 22:41:30.700520 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://[2001:16b8:46b0:8700:81d2:778a:2744:2c2e]:22000 dial tcp [2001:16b8:46b0:8700:81d2:778a:2744:2c2e]:22000: getsockopt: permission denied

(usernamegoeshere) #33

windows10 x64 machine:

[IOEPM] 2017/11/13 22:38:38.133852 tcp_listen.go:69: INFO: TCP listener ([::]:22000) starting
[IOEPM] 2017/11/13 22:38:38.133852 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:38:38.133852 service.go:344: DEBUG: Reconnect loop for 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5
[IOEPM] 2017/11/13 22:38:38.157890 kcp_listen.go:89: INFO: KCP listener ([::]:22020) starting
[IOEPM] 2017/11/13 22:38:38.205486 main.go:871: INFO: Device IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB is "SMULAP01" at [dynamic]
[IOEPM] 2017/11/13 22:38:38.205486 main.go:871: INFO: Device 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 is "linux-smu-dpg" at [dynamic]
[IOEPM] 2017/11/13 22:38:38.214510 gui.go:357: INFO: GUI and API listening on 127.0.0.1:8384
[IOEPM] 2017/11/13 22:38:38.214510 gui.go:358: INFO: Access the GUI via the following URL: http://127.0.0.1:8384/
......
[IOEPM] 2017/11/13 22:38:41.789043 service.go:400: DEBUG: dial 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 kcp://84.189.33.31:22020
[IOEPM] 2017/11/13 22:38:41.789043 kcp_dial.go:42: DEBUG: dial kcp://84.189.33.31:22020 using existing conn on [::]:22020
[IOEPM] 2017/11/13 22:38:41.940468 service.go:417: DEBUG: initial rampup; sleep 1s and update to 2s
[IOEPM] 2017/11/13 22:38:41.940468 service.go:284: INFO: Established secure connection to 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 at [::]:22020-84.189.33.31:22020 (kcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[IOEPM] 2017/11/13 22:38:41.940468 model.go:1485: INFO: Device 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 client is "syncthing v0.14.40" named "linux-smu-dpg"
[IOEPM] 2017/11/13 22:38:42.049747 kcp_listen.go:120: DEBUG: connect from 84.189.33.31:22020
[IOEPM] 2017/11/13 22:38:42.270805 service.go:247: INFO: Connected to already connected device (3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5)
.....
[IOEPM] 2017/11/13 22:38:42.941708 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:38:42.941708 service.go:344: DEBUG: Reconnect loop for 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5
[IOEPM] 2017/11/13 22:38:42.941708 service.go:395: DEBUG: Not dialing using KCP Dialer as priority is less than current connection (50 >= 50)
[IOEPM] 2017/11/13 22:38:42.941708 service.go:395: DEBUG: Not dialing using KCP Dialer as priority is less than current connection (50 >= 50)
[IOEPM] 2017/11/13 22:38:42.941708 service.go:395: DEBUG: Not dialing using Relay Dialer as priority is less than current connection (200 >= 50)
[IOEPM] 2017/11/13 22:38:42.941708 service.go:395: DEBUG: Not dialing using Relay Dialer as priority is less than current connection (200 >= 50)
[IOEPM] 2017/11/13 22:38:42.941708 service.go:395: DEBUG: Not dialing using Relay Dialer as priority is less than current connection (200 >= 50)
[IOEPM] 2017/11/13 22:38:42.941708 service.go:400: DEBUG: dial 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 tcp://84.189.33.31:13762
[IOEPM] 2017/11/13 22:38:48.628206 service.go:61: INFO: Detected 2 NAT devices
[IOEPM] 2017/11/13 22:38:52.942354 tcp_dial.go:36: DEBUG: dial tcp 84.189.33.31:13762: i/o timeout
[IOEPM] 2017/11/13 22:38:52.942354 service.go:405: DEBUG: dial failed 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 tcp://84.189.33.31:13762 dial tcp 84.189.33.31:13762: i/o timeout
[IOEPM] 2017/11/13 22:38:52.942354 service.go:400: DEBUG: dial 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 tcp://84.189.33.31:22000
[IOEPM] 2017/11/13 22:38:52.998662 tcp_dial.go:47: DEBUG: failed to set traffic class: operation not supported
[IOEPM] 2017/11/13 22:38:53.129412 static.go:93: INFO: Joined relay relay://37.120.167.213:22067
[IOEPM] 2017/11/13 22:38:53.180006 service.go:417: DEBUG: initial rampup; sleep 2s and update to 4s
[IOEPM] 2017/11/13 22:38:53.230010 model.go:1210: INFO: Connection to 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 closed: reading length: EOF
[IOEPM] 2017/11/13 22:38:53.230010 service.go:284: INFO: Established secure connection to 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 at 192.168.178.37:54288-84.189.33.31:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[IOEPM] 2017/11/13 22:38:53.231011 model.go:1485: INFO: Device 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 client is "syncthing v0.14.40" named "linux-smu-dpg"
[IOEPM] 2017/11/13 22:38:55.180448 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:38:55.180448 service.go:417: DEBUG: initial rampup; sleep 4s and update to 8s
[IOEPM] 2017/11/13 22:38:57.515036 kcp_listen.go:247: INFO: kcp://0.0.0.0:22020 detected NAT type: Port restricted NAT
[IOEPM] 2017/11/13 22:38:57.515036 kcp_listen.go:260: INFO: kcp://0.0.0.0:22020 resolved external address kcp://88.130.49.164:38094 (via stun.xten.com:3478)
[IOEPM] 2017/11/13 22:38:59.180917 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:38:59.180917 service.go:417: DEBUG: initial rampup; sleep 8s and update to 16s
[IOEPM] 2017/11/13 22:39:07.181702 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:39:07.181702 service.go:417: DEBUG: initial rampup; sleep 16s and update to 32s
[IOEPM] 2017/11/13 22:39:23.181805 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:39:23.181805 service.go:417: DEBUG: initial rampup; sleep 32s and update to 1m4s
[IOEPM] 2017/11/13 22:39:55.182871 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:39:55.182871 service.go:421: DEBUG: sleep until next dial 1m0s
[IOEPM] 2017/11/13 22:40:48.806343 model.go:1210: INFO: Connection to 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 closed: reading length: read tcp 192.168.178.37:54288->84.189.33.31:22000: wsarecv: Eine vorhandene Verbindung wurde vom Remotehost geschlossen.
[IOEPM] 2017/11/13 22:40:55.182878 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:40:55.182878 service.go:344: DEBUG: Reconnect loop for 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5
[IOEPM] 2017/11/13 22:40:55.182878 service.go:400: DEBUG: dial 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 kcp://84.189.33.31:22020
[IOEPM] 2017/11/13 22:40:55.182878 kcp_dial.go:42: DEBUG: dial kcp://84.189.33.31:22020 using existing conn on [::]:22020
[IOEPM] 2017/11/13 22:41:05.183264 service.go:405: DEBUG: dial failed 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 kcp://84.189.33.31:22020 i/o timeout
[IOEPM] 2017/11/13 22:41:05.183264 service.go:400: DEBUG: dial 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 kcp://[2003:d5:6bc9:1c00:e2cb:4eff:feba:599e]:22020
[IOEPM] 2017/11/13 22:41:05.183767 kcp_dial.go:42: DEBUG: dial kcp://[2003:d5:6bc9:1c00:e2cb:4eff:feba:599e]:22020 using existing conn on [::]:22020
[IOEPM] 2017/11/13 22:41:12.711411 service.go:421: DEBUG: sleep until next dial 24s
[IOEPM] 2017/11/13 22:41:12.712420 service.go:284: INFO: Established secure connection to 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 at [::]:22020-[2003:d5:6bc9:1c00:e2cb:4eff:feba:599e]:22020 (kcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[IOEPM] 2017/11/13 22:41:12.712420 model.go:1485: INFO: Device 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 client is "syncthing v0.14.40" named "linux-smu-dpg"
[IOEPM] 2017/11/13 22:41:36.712416 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:41:36.712416 service.go:344: DEBUG: Reconnect loop for 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5
[IOEPM] 2017/11/13 22:41:36.712416 service.go:395: DEBUG: Not dialing using KCP Dialer as priority is less than current connection (50 >= 50)
[IOEPM] 2017/11/13 22:41:36.712416 service.go:395: DEBUG: Not dialing using KCP Dialer as priority is less than current connection (50 >= 50)
[IOEPM] 2017/11/13 22:41:36.712416 service.go:395: DEBUG: Not dialing using Relay Dialer as priority is less than current connection (200 >= 50)
[IOEPM] 2017/11/13 22:41:36.712416 service.go:395: DEBUG: Not dialing using Relay Dialer as priority is less than current connection (200 >= 50)
[IOEPM] 2017/11/13 22:41:36.712416 service.go:395: DEBUG: Not dialing using Relay Dialer as priority is less than current connection (200 >= 50)
[IOEPM] 2017/11/13 22:41:36.712416 service.go:400: DEBUG: dial 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 tcp://84.189.33.31:13762
[IOEPM] 2017/11/13 22:41:46.714023 tcp_dial.go:36: DEBUG: dial tcp 84.189.33.31:13762: i/o timeout
[IOEPM] 2017/11/13 22:41:46.714023 service.go:405: DEBUG: dial failed 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 tcp://84.189.33.31:13762 dial tcp 84.189.33.31:13762: i/o timeout
[IOEPM] 2017/11/13 22:41:46.714023 service.go:400: DEBUG: dial 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 tcp://84.189.33.31:22000
[IOEPM] 2017/11/13 22:41:46.768765 tcp_dial.go:47: DEBUG: failed to set traffic class: operation not supported
[IOEPM] 2017/11/13 22:41:46.933003 service.go:421: DEBUG: sleep until next dial 1m0s
[IOEPM] 2017/11/13 22:41:46.980839 model.go:1210: INFO: Connection to 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 closed: reading length: EOF
[IOEPM] 2017/11/13 22:41:46.988222 service.go:284: INFO: Established secure connection to 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 at 192.168.178.37:54303-84.189.33.31:22000 (tcp-client) (TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305)
[IOEPM] 2017/11/13 22:41:46.989223 model.go:1485: INFO: Device 3PKT34I-LCMZM54-NCM6EN4-N43HBTD-AYV5GP7-TJNAY2H-XIZEDNR-SHIHNQ5 client is "syncthing v0.14.40" named "linux-smu-dpg"
[IOEPM] 2017/11/13 22:42:46.933400 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:42:46.933400 service.go:421: DEBUG: sleep until next dial 1m0s
[IOEPM] 2017/11/13 22:43:46.934117 service.go:317: DEBUG: Reconnect loop
[IOEPM] 2017/11/13 22:43:46.934957 service.go:421: DEBUG: sleep until next dial 1m0s

(Audrius Butkevicius) #34

It seems TCP connections are failing, yet it’s not obvious why.


(OllyG) #35

I’ve noticed that Syncthing v0.14.40 works on my 64bit windows machine, but not my 32bit one. The 64bit machine connects to my android device and syncs fine, the 32bit machine doesn’t connect to anything. Restarting Syncthing on the 32bit machine causes it to hang, but I can exit Syncthing by closing it’s window.


(usernamegoeshere) #36

I am getting errors again today on the win10 x64 machine, the ioepmyd one:

as seen from the linux machine log files messages:

[3PKT3] 2017/11/14 11:06:50.357019 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://88.130.49.12:22000
[3PKT3] 2017/11/14 11:07:00.274872 tcp_listen.go:103: DEBUG: connect from 84.44.212.110:59372
[3PKT3] 2017/11/14 11:07:00.274970 tcp_listen.go:112: DEBUG: failed to set traffic class: operation not supported
[3PKT3] 2017/11/14 11:07:00.357426 tcp_dial.go:36: DEBUG: dial tcp 88.130.49.12:22000: i/o timeout
[3PKT3] 2017/11/14 11:07:00.357472 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://88.130.49.12:22000 dial tcp 88.130.49.12:22000: i/o timeout
[3PKT3] 2017/11/14 11:07:00.357503 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://[2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000
[3PKT3] 2017/11/14 11:07:00.410654 tcp_dial.go:36: DEBUG: dial tcp [2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000: getsockopt: permission denied
[3PKT3] 2017/11/14 11:07:00.410699 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://[2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000 dial tcp [2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000: getsockopt: permission denied

(usernamegoeshere) #37

Restarted both the linux and this win10 machine, but now they dont connect at all:

[3PKT3] 2017/11/14 11:13:28.717633 service.go:344: DEBUG: Reconnect loop for IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB
[3PKT3] 2017/11/14 11:13:28.718098 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB kcp://88.130.49.12:22020
[3PKT3] 2017/11/14 11:13:28.718630 kcp_dial.go:42: DEBUG: dial kcp://88.130.49.12:22020 using existing conn on [::]:22020
[3PKT3] 2017/11/14 11:13:38.719487 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB kcp://88.130.49.12:22020 i/o timeout
[3PKT3] 2017/11/14 11:13:38.719592 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB kcp://88.130.49.12:3931
[3PKT3] 2017/11/14 11:13:38.719749 kcp_dial.go:42: DEBUG: dial kcp://88.130.49.12:3931 using existing conn on [::]:22020
[3PKT3] 2017/11/14 11:13:48.720370 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB kcp://88.130.49.12:3931 i/o timeout
[3PKT3] 2017/11/14 11:13:48.720475 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB kcp://[2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22020
[3PKT3] 2017/11/14 11:13:48.720652 kcp_dial.go:42: DEBUG: dial kcp://[2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22020 using existing conn on [::]:22020
[3PKT3] 2017/11/14 11:13:58.721302 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB kcp://[2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22020 i/o timeout
[3PKT3] 2017/11/14 11:13:58.721677 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB relay://85.214.40.227:22067/?id=VEMACDI-63R5WKY-TAOSKTV-MCTWSFT-JLSXK4X-J52L2F5-T6LZIV5-EHRREAX&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=:22070&providedBy=
[3PKT3] 2017/11/14 11:13:58.917822 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB relay://85.214.40.227:22067/?id=VEMACDI-63R5WKY-TAOSKTV-MCTWSFT-JLSXK4X-J52L2F5-T6LZIV5-EHRREAX&pingInterval=1m0s&networkTimeout=2m0s&sessionLimitBps=0&globalLimitBps=0&statusAddr=:22070&providedBy= Incorrect response code 1: not found
[3PKT3] 2017/11/14 11:13:58.917919 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://88.130.49.12:22000
[3PKT3] 2017/11/14 11:14:07.025624 tcp_listen.go:103: DEBUG: connect from 84.44.212.110:59468
[3PKT3] 2017/11/14 11:14:07.025725 tcp_listen.go:112: DEBUG: failed to set traffic class: operation not supported
[3PKT3] 2017/11/14 11:14:07.210947 service.go:247: INFO: Connected to already connected device (Y5C6IPN-6UYQGUJ-TJROKQ6-BQTCU7C-Q6O27CJ-5R6IVUU-RCK2O35-2M462A5)
[3PKT3] 2017/11/14 11:14:08.918340 tcp_dial.go:36: DEBUG: dial tcp 88.130.49.12:22000: i/o timeout
[3PKT3] 2017/11/14 11:14:08.918788 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://88.130.49.12:22000 dial tcp 88.130.49.12:22000: i/o timeout
[3PKT3] 2017/11/14 11:14:08.919117 service.go:400: DEBUG: dial IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://[2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000
[3PKT3] 2017/11/14 11:14:08.970368 tcp_dial.go:36: DEBUG: dial tcp [2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000: getsockopt: permission denied
[3PKT3] 2017/11/14 11:14:08.970506 service.go:405: DEBUG: dial failed IOEPMYD-LL5ZH6Z-ORZL7KH-FJ4Q7KB-B2N7WTK-FELNT7A-Y5JQI3F-6HXIRAB tcp://[2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000 dial tcp [2001:16b8:46cc:6a00:718a:1d65:e8f9:518]:22000: getsockopt: permission denied

(Jakob Borg) #38

Looks like it’s only seeing “global” addresses (public v4, v6) where the v4 times out and the v6 is denied (maybe box doesn’t have working v6?). If they are on the same LAN I’d start by troubleshooting why local discovery doesn’t work. Firewalls dropping the packets? Local discovery disabled? Wireless AP blocking broadcasts? If they are not on the same lan, the timeout on v4 and permission denied on v6 are the root cause.


(usernamegoeshere) #39

They are not on the same lan. Thats when I speak about “external” nodes and so on. Two separate lans, and I cant control if they have fully working ipv6 global addresses or not.

I have now manually set from default listening entry to tcp4://… for the linux machine and restarated both linux and win10 syncthing

now they connect again. before they would not connect not even after both processes on both ends had been restarted

i strongly suspect that those discovery servers and the bulk data that is being transfered, registered or looked up on or with the help of discovery servers is severly affected by the addition or prefering of this new kcp method or similar to this.

i am only rather a layman and didnt look at your source code but this is what i suspect after looking at all this trouble.

machines dont have trouble when being on the same lan, i have several other machines every now and then every few days that are showing up physically in the lan of the linux machine (main headquarter place so to speak).

some machines are external most of the times, like this win 10 machine for example.

some other win10 machine (surface, lap…) or some mac are sometimes present in the lan and sometimes external.

thats all i can say. the connection logic is flawed with this current release.


(Florian Reitmeir) #40

Hi, i’m new to syncthing… and the .40 version was/is my first. And … it did not work for me the last days.

So i have now a mixed setup… and resolved the issue for me.

3 Clients, 1x Debian stretch / .39 1x Windows 10, .40 1x Android, .40

the Debian is the “server”. I first changed the “default” to "tcp://0.0.0.0:22000" i own a public IP, but with this setup, there is no connection possible. (firewall port forwarding was tested)

I did now setup a RelayServer, and changed the to the default value on all machines. But did configure my own relay on the windows und android. Now it works fine.

So after reading the thread, it looks like there is Problem with the , the tcp:// is obivous not enough to get a connection working.

if some tells me how to get some good logs/debug level i will provide them.