Opened 7 years ago
Last modified 21 months ago
#880 new Bug / Defect
SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Reported by: | krzee king | Owned by: | |
---|---|---|---|
Priority: | major | Milestone: | release 2.6 |
Component: | Generic / unclassified | Version: | OpenVPN 2.4.0 (Community Ed) |
Severity: | Not set (select this one, unless your'e a OpenVPN developer) | Keywords: | |
Cc: | plaisthos |
Description
I have come across an issue in 2.4rc1 (i asked dazo if its been seen yet, since we're past rc1 and he did not think so).
I have a server that currently only has a single client (until I finish a migration). If I connect the client, and then disconnect / reconnect it, I have awhile where I only get:
Sat Apr 29 12:05:31 2017 us=322963 SENT CONTROL [theygot]: 'PUSH_REQUEST' (status=1)
Sat Apr 29 12:05:36 2017 us=450560 SENT CONTROL [theygot]: 'PUSH_REQUEST' (status=1)
Sat Apr 29 12:05:41 2017 us=576189 SENT CONTROL [theygot]: 'PUSH_REQUEST' (status=1)
Sat Apr 29 12:05:46 2017 us=802110 SENT CONTROL [theygot]: 'PUSH_REQUEST' (status=1)
Sat Apr 29 12:05:52 2017 us=28164 SENT CONTROL [theygot]: 'PUSH_REQUEST' (status=1)
while the server (verb 4) shows nothing in the log.
The client disconnects after not getting a response to the push_request, and this persists for awhile unless I restart the server process or wait (I'm not sure how long)
client: #daemon client remote <server.com> 1194 port 1194 proto udp4 dev tun comp-lzo no ca ca.crt cert 5151.crt key 5151.key persist-key persist-tun tls-crypt crypt.key up up.sh script-security 2 verb 4 auth SHA256 tls-version-min 1.2 ns-cert-type server log vpn.log
server: cd /etc/openvpn/new_ec daemon local <ip> port 1194 proto udp4 dev rpn3 dev-type tun comp-lzo no ca ca.crt cert theygot.crt key theygot.key dh none server 10.9.70.0 255.255.255.0 topology subnet keepalive 10 120 persist-key persist-tun tls-crypt crypt.key verb 4 auth SHA256 tls-version-min 1.2 ifconfig-pool-persist ipp.txt log theygot.log ns-cert-type client management 127.0.0.1 13370
I have not tried updating to the latest 2.4 code yet, I apologize if it's already fixed.
Change History (10)
comment:1 Changed 7 years ago by
comment:2 Changed 7 years ago by
there is a timer on the server side for which it won't reply to a push-request multiple times within a short timeframe. if you disconnect almost right after connection, it is possible to hit this scenario.
Can this be the case?
comment:3 Changed 7 years ago by
I think I can confirm this problem. I'm currently using OpenVPN-NL 2.4.4, and I'm experiencing a similar issue. Here are my test results:
Server: OpenVPN-NL 2.3.9
Client: OpenVPN-NL 2.3.9
Actions: Connect client to server. Kill the client, and restart the client.
Results: Connection re-established after about 19 seconds.
Server: OpenVPN-NL 2.4.4
Client: OpenVPN-NL 2.3.9
Actions: Connect client to server. Kill the client, and restart the client.
Results: Connection not re-established within 15 minutes.
Server: OpenVPN-NL 2.4.4
Client: OpenVPN-NL 2.4.4
Actions: Connect client to server. Kill the client, and restart the client.
Results: Connection re-established after about 86 seconds.
Actions: Rerun the test.
Results: Connection re-established after about 838 seconds.
Server: OpenVPN-NL 2.4.4
Client: OpenVPN-NL 2.3.9
Actions: Connect client to server. Kill the client, wait about 60 seconds, and restart the client.
Results: Connection re-established after about 65 seconds (including the 60 second wait time).
In e.g. the case of 2.4.4 server with 2.3.9 client, I see the same PUSH requests in the client log file. After 12 requests, the client closes the connection, and tries again. The server continues to hold its tunnel open; the client never completes the tunnel setup. This behavior is reproducible.
The difference between the 2.3.9 client and 2.4.4 client behavior appears to be the restart pause. It is fixed for the 2.3.9 client (2 seconds), and increasing for the 2.4.4 client (reconnected after the restart pause hits 80 seconds).
The duration of the initial connection seems to have no impact (I tried 10 seconds upto 2 minutes), but using --nobind seems to resolve the issue.
comment:4 Changed 7 years ago by
I ended up figuring out that the problem went away when i changed the server to use openssl instead of mbedtls.
comment:5 Changed 7 years ago by
You might be on to something here:
OpenVPN-NL 2.3.9 uses PolarSSL.
OpenVPN-NL 2.4.4 uses mbed TLS.
comment:6 Changed 5 years ago by
Having retested the issue with OpenVPN-NL 2.4.6, I can report that the issue still exists. From what I've learned, it appears to be an issue within mbed TLS.
comment:7 Changed 5 years ago by
Looking at the logs, there are some notable differences. I assumed for the moment that the TLS calls are logged before the received message, since the message first needs to be decoded (and the client reports a 13 byte plaintext with 42 byte ciphertext).
This is the log of the initial connection:
Fri Jan 26 09:35:30 2018 us=253552 client1/10.11.11.10:1194 write tls_write_ciphertext 42 bytes
Fri Jan 26 09:35:30 2018 us=253581 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:6743): => read
Fri Jan 26 09:35:30 2018 us=253609 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:3721): => read record
Fri Jan 26 09:35:30 2018 us=253636 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2208): => fetch input
Fri Jan 26 09:35:30 2018 us=253664 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2366): in_left: 0, nb_want: 5
Fri Jan 26 09:35:30 2018 us=253692 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2390): in_left: 0, nb_want: 5
Fri Jan 26 09:35:30 2018 us=253721 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2391): ssl->f_recv(_timeout)() returned 5 (-0xfffffffb)
Fri Jan 26 09:35:30 2018 us=253748 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2403): <= fetch input
Fri Jan 26 09:35:30 2018 us=253777 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2208): => fetch input
Fri Jan 26 09:35:30 2018 us=253804 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2366): in_left: 5, nb_want: 42
Fri Jan 26 09:35:30 2018 us=253832 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2390): in_left: 5, nb_want: 42
Fri Jan 26 09:35:30 2018 us=253860 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2391): ssl->f_recv(_timeout)() returned 37 (-0xffffffdb)
Fri Jan 26 09:35:30 2018 us=253887 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2403): <= fetch input
Fri Jan 26 09:35:30 2018 us=253914 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:1576): => decrypt buf
Fri Jan 26 09:35:30 2018 us=253956 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2051): <= decrypt buf
Fri Jan 26 09:35:30 2018 us=253984 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:3754): <= read record
Fri Jan 26 09:35:30 2018 us=254012 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:7042): <= read
Fri Jan 26 09:35:30 2018 us=254038 client1/10.11.11.10:1194 read tls_read_plaintext 13 bytes
Fri Jan 26 09:35:30 2018 us=254068 client1/10.11.11.10:1194 ACK reliable_send_timeout 604800 [6]
Fri Jan 26 09:35:30 2018 us=254100 client1/10.11.11.10:1194 PUSH: Received control message: 'PUSH_REQUEST'
This is the log of the request after the reconnect:
Fri Jan 26 09:35:42 2018 us=558215 client1/10.11.11.10:1194 write tls_write_ciphertext 42 bytes
Fri Jan 26 09:35:42 2018 us=558244 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:6743): => read
Fri Jan 26 09:35:42 2018 us=558271 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:3721): => read record
Fri Jan 26 09:35:42 2018 us=558299 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2208): => fetch input
Fri Jan 26 09:35:42 2018 us=558327 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2366): in_left: 0, nb_want: 5
Fri Jan 26 09:35:42 2018 us=558355 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2390): in_left: 0, nb_want: 5
Fri Jan 26 09:35:42 2018 us=558384 client1/10.11.11.10:1194 ACK reliable_can_send active=0 current=0 : [6]
Fri Jan 26 09:35:42 2018 us=558412 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:6743): => read
Fri Jan 26 09:35:42 2018 us=558439 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:3721): => read record
Fri Jan 26 09:35:42 2018 us=558466 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2208): => fetch input
Fri Jan 26 09:35:42 2018 us=558493 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2366): in_left: 0, nb_want: 5
Fri Jan 26 09:35:42 2018 us=558521 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2390): in_left: 0, nb_want: 5
Fri Jan 26 09:35:42 2018 us=558550 client1/10.11.11.10:1194 ACK write ID 5 (ack->len=1, n=1)
Fri Jan 26 09:35:42 2018 us=558582 client1/10.11.11.10:1194 ACK reliable_send_timeout 604800 [6]
Fri Jan 26 09:35:42 2018 us=558614 PO_CTL rwflags=0x0002 ev=5 arg=0x563eb8ff1858
Fri Jan 26 09:35:42 2018 us=558641 PO_CTL rwflags=0x0000 ev=4 arg=0x563eb8fe80a8
Fri Jan 26 09:35:42 2018 us=558671 I/O WAIT Tr|Tw|Sr|SW [1/165054]
Fri Jan 26 09:35:42 2018 us=558703 PO_WAIT[0,0] fd=5 rev=0x00000004 rwflags=0x0002 arg=0x563eb8ff1858
Fri Jan 26 09:35:42 2018 us=558729 I/O WAIT status=0x0002
Fri Jan 26 09:35:42 2018 us=558764 client1/10.11.11.10:1194 UDPv4 WRITE [62] to [AF_INET]10.11.11.10:1194: P_ACK_V1 kid=0 pid=[ #8 ] [ 5 ]
Fri Jan 26 09:35:42 2018 us=558829 client1/10.11.11.10:1194 ACK reliable_can_send active=0 current=0 : [6]
Fri Jan 26 09:35:42 2018 us=558859 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:6743): => read
Fri Jan 26 09:35:42 2018 us=558886 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:3721): => read record
Fri Jan 26 09:35:42 2018 us=558914 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2208): => fetch input
Fri Jan 26 09:35:42 2018 us=558941 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2366): in_left: 0, nb_want: 5
Fri Jan 26 09:35:42 2018 us=558970 client1/10.11.11.10:1194 mbed TLS msg (/srv/slave_openvpn/.jenkins/workspace/OpenVPN-NL-2.4-build/arch/64-bit/distro/ubuntu_xenial/servertype/build/openvpn-nl/mbedtls/library/ssl_tls.c:2390): in_left: 0, nb_want: 5
Fri Jan 26 09:35:42 2018 us=558999 client1/10.11.11.10:1194 ACK reliable_send_timeout 604800 [6]
Fri Jan 26 09:35:42 2018 us=559029 PO_CTL rwflags=0x0001 ev=5 arg=0x563eb8ff1858
Fri Jan 26 09:35:42 2018 us=559056 PO_CTL rwflags=0x0001 ev=4 arg=0x563eb8fe80a8
Fri Jan 26 09:35:42 2018 us=559086 I/O WAIT TR|Tw|SR|Sw [1/165054]
Fri Jan 26 09:35:43 2018 us=725320 I/O WAIT status=0x0020
Fri Jan 26 09:35:43 2018 us=725415 MULTI: REAP range 0 -> 16
As you can see, the message is never actually decrypted after the reconnect, and as such the server will never receive it.
comment:8 Changed 5 years ago by
comment:9 Changed 3 years ago by
Cc: | plaisthos added |
---|---|
Milestone: | → release 2.6 |
The nobind
reference made me re-discover this ticket.
Ticket #1316 has something which looks similar on first glance, but there it's "the data channel keys are desynchronized" while this one seems to be "the TLS layer is desynchronized".
Could you test this with a release/2.5 or git master server? Especially with today's patches for #1316 merged.
comment:10 Changed 21 months ago by
any testers? There's quite a few shenannigans in the TLS handshake, but much of this has been rewritten for 2.6 - so it would be really nice to understand whether the problems can be reproduced with a 2.6_rc1 server or not.
not sure what to do with this one. I haven't heard any other reports, and the only thing I could see that would explain this is "the network went away" or "something with tls-crypt went awry so the server is ignoring all incoming packets"
Can this be reproduced?