[Bug?] Not all addresses are dialed

Support
1

Since quic does not seem to have the wanted effect I wanted to experiment a bit under what conditions it cannot connect. If I’m reading the following log correctly it does not even seem to try it in my case since it connects to a wrong device via tcp (which has a port forward and is behind the same NAT). After disabling the forward it instantly connects via quic.

[NGJDQ] 2019/07/12 20:48:06.220233 api.go:618: INFO: Enabled debug data for "connections"
[NGJDQ] 2019/07/12 20:48:20.883773 api.go:618: INFO: Enabled debug data for "dialer"
[NGJDQ] 2019/07/12 20:48:50.925673 service.go:343: DEBUG: Reconnect loop
[NGJDQ] 2019/07/12 20:48:50.925847 service.go:380: DEBUG: Reconnect loop for CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL [quic://80.xxx.xxx.xxx:1024 quic://80.xxx.xxx.xxx:22000 quic://80.xxx.xxx.xxx:24000 quic://[2003:xxxx]:22000 quic://[2003:xxxx]:24000 tcp://80.xxx.xxx.xxx:22000 tcp://[2003:xxxx]:22000]
[NGJDQ] 2019/07/12 20:48:50.931211 structs.go:224: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://80.xxx.xxx.xxx:22000 prio 10
[NGJDQ] 2019/07/12 20:48:50.931275 structs.go:224: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://[2003:xxxx]:22000 prio 10
[NGJDQ] 2019/07/12 20:48:50.966645 tcp_dial.go:48: DEBUG: Dial (BEP/tcp): setting traffic class: setsockopt: protocol not available
[NGJDQ] 2019/07/12 20:48:52.744545 structs.go:229: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://80.xxx.xxx.xxx:22000 success: 192.168.1.12:44084-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
[NGJDQ] 2019/07/12 20:48:52.744662 service.go:861: DEBUG: connected to CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL 10 using 192.168.1.12:44084-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305 10
[NGJDQ] 2019/07/12 20:48:52.744772 service.go:380: DEBUG: Reconnect loop for RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN [quic://80.xxx.xxx.xxx:22000 quic://80.xxx.xxx.xxx:24000 quic://[2003:yyyy]:22000 quic://[2003:yyyy]:24000 tcp://80.xxx.xxx.xxx:22000 tcp://[2003:yyyy]:22000]
[NGJDQ] 2019/07/12 20:48:52.748174 structs.go:224: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://80.xxx.xxx.xxx:22000 prio 10
[NGJDQ] 2019/07/12 20:48:52.748221 structs.go:224: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://[2003:yyyy]:22000 prio 10
[NGJDQ] 2019/07/12 20:48:52.772236 service.go:257: INFO: Connection from NOT-WANTED-DEVICE at 80.xxx.xxx.xxx:22000 (tcp-client) rejected: device is ignored
[NGJDQ] 2019/07/12 20:48:52.778160 tcp_dial.go:48: DEBUG: Dial (BEP/tcp): setting traffic class: setsockopt: protocol not available
[NGJDQ] 2019/07/12 20:48:55.193135 structs.go:229: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://80.xxx.xxx.xxx:22000 success: 192.168.1.12:44090-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
[NGJDQ] 2019/07/12 20:48:55.193297 service.go:861: DEBUG: connected to RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN 10 using 192.168.1.12:44090-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305 10
[NGJDQ] 2019/07/12 20:48:55.193393 service.go:471: DEBUG: sleep until next dial 1m0s
[NGJDQ] 2019/07/12 20:48:55.220227 service.go:257: INFO: Connection from NOT-WANTED-DEVICE at 80.xxx.xxx.xxx:22000 (tcp-client) rejected: device is ignored
[NGJDQ] 2019/07/12 20:49:00.931899 structs.go:227: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://[2003:xxxx]:22000 error: dial tcp [2003:xxxx]:22000: i/o timeout
[NGJDQ] 2019/07/12 20:49:00.932049 service.go:864: DEBUG: discarding 0 connections while connecting to CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL 10
[NGJDQ] 2019/07/12 20:49:02.748924 structs.go:227: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://[2003:yyyy]:22000 error: dial tcp [2003:yyyy]:22000: i/o timeout
[NGJDQ] 2019/07/12 20:49:02.749100 service.go:864: DEBUG: discarding 0 connections while connecting to RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN 10
[NGJDQ] 2019/07/12 20:49:55.193916 service.go:343: DEBUG: Reconnect loop
[NGJDQ] 2019/07/12 20:49:55.337617 service.go:380: DEBUG: Reconnect loop for CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL [quic://80.xxx.xxx.xxx:1024 quic://80.xxx.xxx.xxx:22000 quic://80.xxx.xxx.xxx:24000 quic://[2003:xxxx]:22000 quic://[2003:xxxx]:24000 tcp://80.xxx.xxx.xxx:22000 tcp://[2003:xxxx]:22000]
[NGJDQ] 2019/07/12 20:49:55.340640 structs.go:224: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://80.xxx.xxx.xxx:22000 prio 10
[NGJDQ] 2019/07/12 20:49:55.340685 structs.go:224: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://[2003:xxxx]:22000 prio 10
[NGJDQ] 2019/07/12 20:49:55.381732 tcp_dial.go:48: DEBUG: Dial (BEP/tcp): setting traffic class: setsockopt: protocol not available
[NGJDQ] 2019/07/12 20:49:57.174254 structs.go:229: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://80.xxx.xxx.xxx:22000 success: 192.168.1.12:44142-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
[NGJDQ] 2019/07/12 20:49:57.174438 service.go:861: DEBUG: connected to CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL 10 using 192.168.1.12:44142-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305 10
[NGJDQ] 2019/07/12 20:49:57.207200 service.go:257: INFO: Connection from NOT-WANTED-DEVICE at 80.xxx.xxx.xxx:22000 (tcp-client) rejected: device is ignored
[NGJDQ] 2019/07/12 20:49:57.223813 service.go:380: DEBUG: Reconnect loop for RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN [quic://80.xxx.xxx.xxx:22000 quic://80.xxx.xxx.xxx:24000 quic://[2003:yyyy]:22000 quic://[2003:yyyy]:24000 tcp://80.xxx.xxx.xxx:22000 tcp://[2003:yyyy]:22000]
[NGJDQ] 2019/07/12 20:49:57.228402 structs.go:224: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://80.xxx.xxx.xxx:22000 prio 10
[NGJDQ] 2019/07/12 20:49:57.228726 structs.go:224: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://[2003:yyyy]:22000 prio 10
[NGJDQ] 2019/07/12 20:49:57.273602 tcp_dial.go:48: DEBUG: Dial (BEP/tcp): setting traffic class: setsockopt: protocol not available
[NGJDQ] 2019/07/12 20:49:59.074320 structs.go:229: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://80.xxx.xxx.xxx:22000 success: 192.168.1.12:44146-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
[NGJDQ] 2019/07/12 20:49:59.074482 service.go:861: DEBUG: connected to RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN 10 using 192.168.1.12:44146-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305 10
[NGJDQ] 2019/07/12 20:49:59.074583 service.go:471: DEBUG: sleep until next dial 1m0s
[NGJDQ] 2019/07/12 20:49:59.101366 service.go:257: INFO: Connection from NOT-WANTED-DEVICE at 80.xxx.xxx.xxx:22000 (tcp-client) rejected: device is ignored
[NGJDQ] 2019/07/12 20:50:05.341291 structs.go:227: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://[2003:xxxx]:22000 error: dial tcp [2003:xxxx]:22000: i/o timeout
[NGJDQ] 2019/07/12 20:50:05.341530 service.go:864: DEBUG: discarding 0 connections while connecting to CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL 10
[NGJDQ] 2019/07/12 20:50:07.229343 structs.go:227: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://[2003:yyyy]:22000 error: dial tcp [2003:yyyy]:22000: i/o timeout
[NGJDQ] 2019/07/12 20:50:07.229514 service.go:864: DEBUG: discarding 0 connections while connecting to RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN 10
[NGJDQ] 2019/07/12 20:50:59.074804 service.go:343: DEBUG: Reconnect loop
[NGJDQ] 2019/07/12 20:50:59.074938 service.go:380: DEBUG: Reconnect loop for CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL [quic://80.xxx.xxx.xxx:1024 quic://80.xxx.xxx.xxx:22000 quic://80.xxx.xxx.xxx:24000 quic://[2003:xxxx]:22000 quic://[2003:xxxx]:24000 tcp://80.xxx.xxx.xxx:22000 tcp://[2003:xxxx]:22000]
[NGJDQ] 2019/07/12 20:50:59.078153 structs.go:224: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://80.xxx.xxx.xxx:22000 prio 10
[NGJDQ] 2019/07/12 20:50:59.078364 structs.go:224: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://[2003:xxxx]:22000 prio 10
[NGJDQ] 2019/07/12 20:50:59.123511 tcp_dial.go:48: DEBUG: Dial (BEP/tcp): setting traffic class: setsockopt: protocol not available
[NGJDQ] 2019/07/12 20:51:01.231781 structs.go:229: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://80.xxx.xxx.xxx:22000 success: 192.168.1.12:44202-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
[NGJDQ] 2019/07/12 20:51:01.231909 service.go:861: DEBUG: connected to CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL 10 using 192.168.1.12:44202-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305 10
[NGJDQ] 2019/07/12 20:51:01.232016 service.go:380: DEBUG: Reconnect loop for RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN [quic://80.xxx.xxx.xxx:22000 quic://80.xxx.xxx.xxx:24000 quic://[2003:yyyy]:22000 quic://[2003:yyyy]:24000 tcp://80.xxx.xxx.xxx:22000 tcp://[2003:yyyy]:22000]
[NGJDQ] 2019/07/12 20:51:01.236165 structs.go:224: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://80.xxx.xxx.xxx:22000 prio 10
[NGJDQ] 2019/07/12 20:51:01.236372 structs.go:224: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://[2003:yyyy]:22000 prio 10
[NGJDQ] 2019/07/12 20:51:01.268311 service.go:257: INFO: Connection from NOT-WANTED-DEVICE at 80.xxx.xxx.xxx:22000 (tcp-client) rejected: device is ignored
[NGJDQ] 2019/07/12 20:51:01.276445 tcp_dial.go:48: DEBUG: Dial (BEP/tcp): setting traffic class: setsockopt: protocol not available
[NGJDQ] 2019/07/12 20:51:03.022376 structs.go:229: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://80.xxx.xxx.xxx:22000 success: 192.168.1.12:44206-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305
[NGJDQ] 2019/07/12 20:51:03.022549 service.go:861: DEBUG: connected to RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN 10 using 192.168.1.12:44206-80.xxx.xxx.xxx:22000/tcp-client/TLS1.2-TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305 10
[NGJDQ] 2019/07/12 20:51:03.022682 service.go:471: DEBUG: sleep until next dial 1m0s
[NGJDQ] 2019/07/12 20:51:03.050110 service.go:257: INFO: Connection from NOT-WANTED-DEVICE at 80.xxx.xxx.xxx:22000 (tcp-client) rejected: device is ignored
[NGJDQ] 2019/07/12 20:51:09.078928 structs.go:227: DEBUG: dialing CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL tcp://[2003:xxxx]:22000 error: dial tcp [2003:xxxx]:22000: i/o timeout
[NGJDQ] 2019/07/12 20:51:09.079043 service.go:864: DEBUG: discarding 0 connections while connecting to CKHPUD6-SYDTIOZ-Z2ZUZYL-2QZVZ65-7OD6LHS-CGXE6F3-R6QW6H7-XU35MQL 10
[NGJDQ] 2019/07/12 20:51:11.237067 structs.go:227: DEBUG: dialing RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN tcp://[2003:yyyy]:22000 error: dial tcp [2003:yyyy]:22000: i/o timeout
[NGJDQ] 2019/07/12 20:51:11.237213 service.go:864: DEBUG: discarding 0 connections while connecting to RYYMNZO-FM4MI6X-AKIKQBA-BTMR7ZI-RBGJ45G-DFT4EYK-YVAQELM-B473YAN 10
2

It’s not dialing on quic because tcp has higher prio and sucessfully establishes a connection. Unfortunately shortly after said tcp connection times out, but at dial time that is not yet known.

3

The funny thing is, if I temporarily block the connection to the wrong device and a quic connection is established, after unblocking the “successful” connection does not break the quic connection because the disconnect happens before the connection switch.

Not sure if this case is really common, but it could explain some cases where relay is still used instead of quic (relay is successful because the other side will dial the relay).

4

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.