Client won't receive PUSH answer

[hildeb]

From my client log:

Wed Mar 22 23:24:44 2017 OpenVPN 2.4.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Feb 10 2017
Wed Mar 22 23:24:44 2017 library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08
Wed Mar 22 23:24:44 2017 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Wed Mar 22 23:24:44 2017 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Mar 22 23:24:44 2017 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Wed Mar 22 23:24:44 2017 TCP/UDP: Preserving recently used remote address: [AF_INET]193.175.73.200:1194
Wed Mar 22 23:24:44 2017 Socket Buffers: R=[212992->212992] S=[212992->212992]
Wed Mar 22 23:24:44 2017 UDP link local: (not bound)
Wed Mar 22 23:24:44 2017 UDP link remote: [AF_INET]193.175.73.200:1194
Wed Mar 22 23:24:44 2017 TLS: Initial packet from [AF_INET]193.175.73.200:1194, sid=78890186 f522bfd8
Wed Mar 22 23:24:44 2017 VERIFY OK: depth=1, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=Charite-VPN CA, name=EasyRSA, emailAddress=vpn@…
Wed Mar 22 23:24:44 2017 VERIFY OK: nsCertType=SERVER
Wed Mar 22 23:24:44 2017 Validating certificate extended key usage
Wed Mar 22 23:24:44 2017 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Wed Mar 22 23:24:44 2017 VERIFY EKU OK
Wed Mar 22 23:24:44 2017 VERIFY X509NAME OK: C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=openvpn.charite.de, emailAddress=vpn@…
Wed Mar 22 23:24:44 2017 VERIFY OK: depth=0, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=openvpn.charite.de, emailAddress=vpn@…
Wed Mar 22 23:24:44 2017 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Wed Mar 22 23:24:44 2017 [openvpn.charite.de] Peer Connection Initiated with [AF_INET]193.175.73.200:1194
Wed Mar 22 23:24:45 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:24:50 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:24:55 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:00 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:05 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:10 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:15 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:20 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:25 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:30 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:35 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:41 2017 SENT CONTROL [openvpn.charite.de]: 'PUSH_REQUEST' (status=1)
Wed Mar 22 23:25:46 2017 No reply from server after sending 12 push requests
Wed Mar 22 23:25:46 2017 SIGUSR1[soft,no-push-reply] received, process restarting
Wed Mar 22 23:25:46 2017 Restart pause, 5 second(s)

So I checked the server's log to see WTF happened:

Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 TLS: Initial packet from [AF_INET6]::ffff:91.65.62.252:33631, sid=ef5e9f5d 3f4217f3
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 VERIFY OK: depth=1, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=Charite-VPN CA, name=EasyRSA, emailAddress=vpn@…
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 Validating certificate extended key usage
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 ++ Certificate has EKU (str) TLS Web Client Authentication, expects TLS Web Client Authentication
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 VERIFY EKU OK
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 VERIFY OK: depth=0, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=hildeb, emailAddress=vpn@…
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_VER=2.4.0
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_PLAT=linux
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_PROTO=2
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_NCP=2
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_LZ4=1
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_LZ4v2=1
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_LZO=1
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_COMP_STUB=1
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_COMP_STUBv2=1
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 peer info: IV_TCPNL=1
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 TLS: Username/Password? authentication succeeded for username 'hildeb'
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Mar 22 23:24:44 openvpn udp[976]: 91.65.62.252 [hildeb] Peer Connection Initiated with [AF_INET6]::ffff:91.65.62.252:33631
Mar 22 23:24:44 openvpn udp[976]: hildeb/91.65.62.252 MULTI_sva: pool returned IPv4=172.29.0.32, IPv6=(Not enabled)
Mar 22 23:24:45 openvpn udp[976]: hildeb/91.65.62.252 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_9da7b1784f5db98918a667bf378a62a6.tmp
Mar 22 23:24:45 openvpn udp[976]: hildeb/91.65.62.252 MULTI: Learn: 172.29.0.32 -> hildeb/91.65.62.252
Mar 22 23:24:45 openvpn udp[976]: hildeb/91.65.62.252 MULTI: primary virtual IP for hildeb/91.65.62.252: 172.29.0.32
Mar 22 23:24:45 openvpn udp[976]: Key [AF_INET6]::ffff:91.65.62.252:33631 [0] not initialized (yet), dropping packet.
Mar 22 23:24:46 openvpn udp[976]: hildeb/87.142.97.40 Key [AF_INET6]::ffff:87.142.97.40:63480 [0] not initialized (yet), dropping packet.
Mar 22 23:25:05 openvpn udp[976]: message repeated 23 times: [ hildeb/87.142.97.40 Key [AF_INET6]::ffff:87.142.97.40:63480 [0] not initialized (yet), dropping packet.]

Not initialized yet? And what is that 87.142.97.40 IP? That's not my IP!

So I checked the server's log for 87.142.97.40:

Mar 22 23:22:18 openvpn udp[976]: 87.142.97.40 TLS: Initial packet from [AF_INET6]::ffff:87.142.97.40:63547, sid=601039fc 1ad49b35
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 VERIFY OK: depth=1, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=Charite-VPN CA, name=
EasyRSA, emailAddress=vpn@…
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 Validating certificate extended key usage
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 ++ Certificate has EKU (str) TLS Web Client Authentication, expects TLS Web Client Authenticatio
n
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 VERIFY EKU OK
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 VERIFY OK: depth=0, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=talthoff, emailAddres
s=vpn@…
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 peer info: IV_VER=2.3.6
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 peer info: IV_PLAT=mac
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 peer info: IV_PROTO=2
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 TLS: Username/Password? authentication succeeded for username 'talthoff'
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 Data Channel Encrypt: Using 256 bit message hash 'SHA256' for HMAC authentication
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 Data Channel Decrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 Data Channel Decrypt: Using 256 bit message hash 'SHA256' for HMAC authentication
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 Control Channel: TLSv1, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-SHA, 2048 bit RSA
Mar 22 23:22:19 openvpn udp[976]: 87.142.97.40 [talthoff] Peer Connection Initiated with [AF_INET6]::ffff:87.142.97.40:63547
Mar 22 23:22:20 openvpn udp[976]: MULTI: Learn: 172.29.4.212 -> talthoff/87.142.97.40
Mar 22 23:22:20 openvpn udp[976]: MULTI: primary virtual IP for talthoff/87.142.97.40: 172.29.4.212
Mar 22 23:22:21 openvpn udp[976]: talthoff/87.142.97.40 PUSH: Received control message: 'PUSH_REQUEST'
Mar 22 23:22:21 openvpn udp[976]: talthoff/87.142.97.40 SENT CONTROL [talthoff]: 'PUSH_REPLY,dhcp-option DNS 141.42.1.1,dhcp-option DOMAIN charite.de,register-dns,block-outside-dns,sndbuf 393216,rcvbuf 393216,route-gateway 172.29.0.1,topology subnet,ping 10,ping-restart 30,redirect-gateway def1,ifconfig 172.29.4.212 255.255.192.0,peer-id 18' (status=1)
Mar 22 23:24:21 openvpn udp[976]: 87.142.97.40 TLS: Initial packet from [AF_INET6]::ffff:87.142.97.40:63480, sid=26e85a98 04474672
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 VERIFY OK: depth=1, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=Charite-VPN CA, name=EasyRSA, emailAddress=vpn@…
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 Validating certificate extended key usage
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 ++ Certificate has EKU (str) TLS Web Client Authentication, expects TLS Web Client Authentication
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 VERIFY EKU OK
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 VERIFY OK: depth=0, C=DE, ST=Berlin, L=Berlin, O=Charite-VPN, OU=GB-IT, CN=talthoff, emailAddress=vpn@…
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 peer info: IV_VER=2.3.6
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 peer info: IV_PLAT=mac
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 peer info: IV_PROTO=2
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 TLS: Username/Password? authentication succeeded for username 'talthoff'
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 Data Channel Encrypt: Cipher 'AES-256-CBC' initialized with 256 bit key
Mar 22 23:24:22 openvpn udp[976]: 87.142.97.40 Data Channel Encrypt: Using 256 bit message hash 'SHA256' for HMAC authentication

So it seems there was a mixup between my connection (hildeb, 91.65.62.252) and talthoff (87.142.97.40)

[tct]

What is the openvpn server version ?
Also config files and possible CCD files please.

[Gert Döring]

@syzzer: do you have any idea what could have happened here?

@tincantech: this is 2.4.0 (which is clear from the log messages), and CCD plays no role at this point. Please do not add noise to trac tickets.

[Gert Döring]

@hildeb: is it possible that 87.142.97.40 is an external NAT IP that your connection ended up using before that, and the server didn't realize you had disconnected? Or, worse, a NAT that moved your OpenVPN connection to a new external IP before it fully completed?

It *should* still not mix this up (because ports are different, and even if ports are the same, peer-id should have caught it.

It's doubly strange, though, as the "key not initialized" message is for incoming DATA CHANNEL packets (which indeed only works after push request / push reply are done), but the PUSH_REQUEST packet would be coming in via control channel.

The more I think about it, the more the "a NAT that lost state and gave you a new external IP, right in the middle of the initial handshake" would perfectly explain what you observed - but it doesn't make sense either, because that would imply a very much overloaded NAT box...

[Steffan Karger]

This indeed looks like OpenVPN somehow lost track during the connection setup. I think cron2 is on the right track. Could it be that your client somehow roamed between access points, or between wired/wireless, or between wifi/cellular during the connection setup? That will indeed cause OpenVPN to lose track, because it can only code with roaming *after* connection setup has succeeded.

To be perfectly clear: OpenVPN is not confusing your connection (which it thinks is coming from 87.142.97.40:63480) with that of talthoff (which is shows is coming from 87.142.97.40:63547).

[hildeb]

What is the openvpn server version ?

2.4.0 (until now, now it's 2.4.1)

Also config files and possible CCD files please.

port 1194
proto udp6
dev tun

mssfix 1350

# drop privileges
user openvpn
group openvpn

ca /opt/openvpn/ca/keys/ca.crt
key /opt/openvpn/ca/keys/openvpn.charite.de.key # This file should be
kept secret
cert /opt/openvpn/ca/keys/openvpn.charite.de.crt
crl-verify /opt/openvpn/ca/keys/crl.pem
dh /opt/openvpn/ca/keys/dh2048.pem
tls-auth /opt/openvpn/ca/keys/ta.key 0
remote-cert-eku "TLS Web Client Authentication"

cipher AES-256-CBC
auth SHA256

server 172.29.0.0 255.255.192.0
topology subnet

auth-user-pass-verify /opt/openvpn/scripts/openVPN-authenticate.pl
via-env
client-connect /opt/openvpn/scripts/openVPN-clientConnect.pl
learn-address /opt/openvpn/scripts/openVPN-learnAddress.pl

#anycast dns
push "dhcp-option DNS 141.42.1.1"
push "dhcp-option DOMAIN charite.de"
push "register-dns"
push "block-outside-dns"

keepalive 10 30
comp-lzo
persist-key
persist-tun
status /var/log/openvpn-udp-status.log
verb 3
management 127.0.0.1 7505
reneg-sec 36000

script-security 3
mute-replay-warnings
fast-io

# Neu RHI 19.05.2016
#
​http://winaero.com/blog/speed-up-openvpn-and-get-faster-speed-over-its-channel/
sndbuf 393216
rcvbuf 393216
push "sndbuf 393216"
push "rcvbuf 393216"

[hildeb]

@hildeb: is it possible that 87.142.97.40 is an external NAT IP that your
connection ended up using before that, and the server didn't realize you
had disconnected?

No, they're from totally different ISPs!

Or, worse, a NAT that moved your OpenVPN connection to a new external
IP before it fully completed?

No.

It *should* still not mix this up (because ports are different, and even
if ports are the same, peer-id should have caught it.

It's doubly strange, though, as the "key not initialized" message is for
incoming DATA CHANNEL packets (which indeed only works after push request
/ push reply are done), but the PUSH_REQUEST packet would be coming in via
control channel.

See, that's why I reported this :)

[Antonio Quartulli]

@hildeb is this still a problem? If so, can you reproduce it somewhat easily?

[jmarshall]

Did anyone ever get to the bottom of this? I've got some users reporting an issue with a very similar set of symptoms (confused IP addresses in server logs, hanging PUSH_REQUESTS on clients).

Currently using openvpn community edition 2.4.7 from EPEL on Centos 7 on the server side; clients are a mixture, but the most recent report was from a user running OpenVPN 2.4.4 on an unknown version of Linux).

I'd be happy to get whatever details will help debug if someone has the time and interest to resume investigations.