Opened 7 years ago

Last modified 15 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 Gert Döring

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?

comment:2 Changed 7 years ago by Antonio Quartulli

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 6 years ago by phulshof

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.

Last edited 6 years ago by phulshof (previous) (diff)

comment:4 Changed 6 years ago by krzee king

I ended up figuring out that the problem went away when i changed the server to use openssl instead of mbedtls.

comment:5 Changed 6 years ago by phulshof

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 phulshof

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. The PUSH_REQUESTs are never forwarded to the OpenVPN-NL layer, so no replies are sent as a result, causing the client to disconnect after not having received a reply after 12 attempts.

Last edited 5 years ago by phulshof (previous) (diff)

comment:7 Changed 5 years ago by phulshof

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 Steffan Karger

This seems to be the same issue as described in #859. If that is true, then this is not mbed-related (the report in #859 uses OpenSSL), but might be exposed more in mbed builds due to e.g. different timing or different behaviour.

comment:9 Changed 3 years ago by Gert Döring

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 15 months ago by Gert Döring

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.

Note: See TracTickets for help on using tickets.