Opened 4 years ago

Closed 4 years ago

#1259 closed Bug / Defect (fixed)

--enable-async-push is broken when NCP is used

Reported by: stipa Owned by:
Priority: major Milestone: release 2.4.10
Component: Generic / unclassified Version: OpenVPN 2.4.7 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc:

Description

When server is configured with --enable-async-push, uses sample "defer" plugin and NCP, VPN connection is broken:

Mar 13 11:05:59 stipakov openvpn[9061]: client40/x.x.x.x:1194 Key [AF_INET]x.x.x.x:1194 [0] not initialized (yet), dropping packet.

Server config:

auth-user-pass-optional
setenv test_deferred_auth 3
plugin simple.so

Bug doesn't occur when server config has "ncp-disable".

Change History (16)

comment:1 Changed 4 years ago by stipa

One workaround is to have

ncp-disable
ciipher AES-256-GCM

in server config and

cipher AES-256-GCM

in client config. This disables NCP and ensures that proper cipher is used.

comment:3 Changed 4 years ago by stipa

Original mail from Spencer Maxfield <smaxfield@…>:

Hi,

I'm a software engineer at Duo Security (part of Cisco). We have an OpenVPN plugin that adds Duo 2FA and have recently been receiving reports that our plugin is causing the VPN to break. After investigating, I've determined that things only break with our plugin if OpenVPN was built with --enable-async-push. I've tried to figure out why our plugin isn't playing nicely with this feature but haven't had any luck. In fact, replacing our plugin with the sample "defer" plugin in the OpenVPN repo (openvpn/sample/sample-plugins/defer/) results in the same broken behavior. I was hoping the sample plugin would work and I could use it for guidance on how to correct ours, but since that wasn't the case I'm hoping to get some guidance here.

Before I jump into the technical bits, a couple of questions I have are:

1) Is there more documentation about the --enable-async-push feature other than what's in Changes.rst that explain more about the feature and any of its pre-requisites if there are any? (e.g. "both the client and server OpenVPN must be built with --enable-async-push for the feature to work")

2) Other than the plugin examples in the OpenVPN repo, are there any guides on how to write an OpenVPN plugin that could be followed to ensure best practices are used?
Those questions aside, I've done quite a bit of debugging so I'll include what I've figured out so far below. Since I was able to reproduce the behavior with the sample plugin, I'm only going to include logs from when that was used instead of when Duo's plugin was used, just to keep things simple. But for the curious, Duo's plugin can be found here:

https://github.com/duosecurity/duo_openvpn.

The below "what I know so far" is based on using Tunnelblick 3.8.1 with OpenVPN 2.4.7 (OpenSSL 1.0.2t). I also set Tunnelblick to use OpenVPN 2.4.7 with OpenSSL 1.1.1d and got the same behavior. Here's some snippets from some server logs with verb set to 9 related to what I believe to be the cause of the problem:

Tue Mar 10 13:25:46 2020 us=895490 spencer/10.50.0.1:55726 TLS Warning: no data channel send key available: [key#0 state=S_ACTIVE id=0 sid=9ded1ffe 73d59daf] [key#1 state=S_UNDEF id=0 sid=00000000 00000000] [key#2 state=S_UNDEF id=0 sid=00000000 00000000]
Tue Mar 10 13:25:49 2020 us=755749 spencer/10.50.0.1:55726 Key [AF_INET]10.50.0.1:55726 [0] not initialized (yet), dropping packet.

What I know so far:

1) From the client side of things, the connection appears to be completely initialized, but on the server side it can be seen that this is not the case and all packets are dropped.

2) Packets are dropped because the data channel does not have a send key available. Specifically this is because the key context on the crypto options has not been initialized. After the auth has completed, the state of the key within function tls_pre_encrypt in ssl.c is:

ks->state: Active
ks->authenticated: True
ks->crypto_options.key_ctx_bi.initialized: False this is what's causing the key to not be selected for the data channel
ks->auth_deferred: False

3) I've confirmed that the auth control file is being written to, has a value of 1 for success, and that value of 1 is being properly read in function key_state_test_auth_control_file.

4) I see that tls_session_generate_data_channel_keys is the function called to set the crypto initialization to true and get the data channel set up, but it's not being called and it's unclear to me what should be calling it in the case --enable-async-push is on. It seems like the call to multi_connection_established should eventually lead to a call to tls_session_generate_data_channel_keys, but I'm not sure.

Attached are my client and server configurations, information about my environment and OpenVPN build, and the client and server logs when reproducing this issue at both verb 5 and verb 9 logging verbosities. Let me know if there's anything else needed from me. I'm happy to help in any way I can to figure this out.

Thanks! (edited)

comment:4 Changed 4 years ago by stipa

Feedback on a fix:

Thanks for the fix and workaround. I’ve just tested with OpenVPN running on Centos 8 with –enable-async-push using Tunnelblick as the client from a Mac. I tried the workaround provided here https://community.openvpn.net/openvpn/ticket/1259 (adding ncp-disable to the server config) and that worked. I also pulled down your patch with a fix, rebuilt OpenVPN, removed ncp-disable from my server config, and confirmed that everything working in that case as well. So everything looks good to me!

I’ll provide the workaround to the users of Duo’s OpenVPN plugin that have reported issues and keep an eye out for an official release that contains your commit.

comment:5 Changed 4 years ago by szatam

Hello!

Thanks for your work on this, this issue had been plaguing me for a long time.
I've tried the new fix but it led to some strange behavior for me.
Let's take the following server config:
cipher AES-256-CBC
ncp-ciphers 'AES-256-GCM:AES-128-GCM'

This makes sure that our legacy (pre 2.4) clients can connect with AES-256-CBC and 2.4 clients can upgrade to GCM. This works perfectly without async push enabled.

However, after enabling async push, the cipher setting (AES-256-CBC) seems to override the pushed ncp options, so the effective cipher with 2.4+ clients will be AES-256-CBC as well.
Clients who specify ncp-disable and cipher AES-256-GCM or AES-128-GCM are not able to connect

Server log:

Fri Apr 17 21:30:41 2020 us=905500 szatam/xxx:45170 Using peer cipher 'AES-128-GCM'
Fri Apr 17 21:30:41 2020 us=905528 szatam/xxx:45170 SENT CONTROL [szatam]: 'PUSH_REPLY,ping 10,ping-restart 60,persist-key,redirect-gateway def1,explicit-exit-notify 2,route-gateway 10.128.0.1,topology subnet,compress,ifconfig xxx.xxx.xxx.xxx  255.255.0.0,peer-id 0' (status=1)
Fri Apr 17 21:30:41 2020 us=943105 szatam/xxx:45170 Authenticate/Decrypt packet error: packet HMAC authentication failed

Client log:

Fri Apr 17 21:31:52 2020 us=977361 Outgoing Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
Fri Apr 17 21:31:52 2020 us=977423 Incoming Data Channel: Cipher 'AES-128-GCM' initialized with 128 bit key
Fri Apr 17 21:31:52 2020 us=978475 TUN/TAP device tun5 opened
Fri Apr 17 21:31:52 2020 us=978664 TUN/TAP TX queue length set to 100
Fri Apr 17 21:31:52 2020 us=978842 do_ifconfig, tt->did_ifconfig_ipv6_setup=1
Fri Apr 17 21:31:52 2020 us=978950 /sbin/ip link set dev tun5 up mtu 1500
Fri Apr 17 21:31:52 2020 us=981024 /sbin/ip addr add dev tun5 xxx broadcast xxx
Fri Apr 17 21:31:52 2020 us=983827 Initialization Sequence Completed
Fri Apr 17 21:32:02 2020 us=137449 AEAD Decrypt error: cipher final failed
Last edited 4 years ago by szatam (previous) (diff)

comment:6 Changed 4 years ago by stipa

Hi,

Unfortunately I am not able to reproduce those issues with 2.4.9 client and server. Here is what I tried:

Scenario 1

Async-push enabled, sample plugin used which defers authentication. Server config:

    auth-user-pass-optional
    setenv test_deferred_auth 3
    plugin /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so
    cipher AES-256-CBC
    ncp-ciphers 'AES-256-GCM:AES-128-GCM'

Client config doesn't contain any crypto-specific options.

Server log:

Apr 18 17:38:45 stipakov openvpn[2109]: MULTI: multi_create_instance called
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 Re-using SSL/TLS context
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tl
s-server'
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-m
ethod 2,tls-client'
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 TLS: Initial packet from [AF_INET]81.175.xxx.yyy:52207, sid=6ecf7173 d4ccf295
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_TLS_VERIFY status=0
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 VERIFY PLUGIN OK: depth=1, CN=LeeviCA5
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 VERIFY OK: depth=1, CN=LeeviCA5
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_TLS_VERIFY status=0
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 VERIFY PLUGIN OK: depth=0, CN=client42
Apr 18 17:38:45 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 VERIFY OK: depth=0, CN=client42
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 peer info: IV_VER=2.4.9
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 peer info: IV_PLAT=linux
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 peer info: IV_PROTO=2
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 peer info: IV_NCP=2
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 TLS: Username/Password authentication deferred for username ''
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1557', remote='link-mtu 1541'
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-CBC', remote='cipher BF-CBC'
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 WARNING: 'keysize' is used inconsistently, local='keysize 256', remote='keysize 128'
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_TLS_FINAL status=0
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 [client42] Peer Connection Initiated with [AF_INET]81.175.xxx.yyy:52207
Apr 18 17:38:46 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_IPCHANGE status=0
Apr 18 17:38:47 stipakov openvpn[2109]: 81.175.xxx.yyy:52207 PUSH: Received control message: 'PUSH_REQUEST'
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=2001:db8:0:123::1000
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_CLIENT_CONNECT status=0
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_LEARN_ADDRESS status=0
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 MULTI: Learn: 10.8.0.2 -> client42/81.175.xxx.yyy:52207
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 MULTI: primary virtual IP for client42/81.175.xxx.yyy:52207: 10.8.0.2
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_LEARN_ADDRESS status=0
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 MULTI: Learn: 2001:db8:0:123::1000 -> client42/81.175.xxx.yyy:52207
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 MULTI: primary virtual IPv6 for client42/81.175.xxx.yyy:52207: 2001:db8:0:123::1000
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 SENT CONTROL [client42]: 'PUSH_REPLY,dhcp-option DNS 2001:4860:4860::8888,dhcp-option DNS 10.8.0.1,route 10.66.0.0 255.255.255.0,tun-ipv6,route-gateway 10.8.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:123::1000/64 2001:db8:0:123::1,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 Data Channel: using negotiated cipher 'AES-256-GCM'
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 Data Channel MTU parms [ L:1549 D:1450 EF:49 EB:406 ET:0 EL:3 ]
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Apr 18 17:38:49 stipakov openvpn[2109]: client42/81.175.xxx.yyy:52207 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key

Client log:

Sat Apr 18 17:38:45 2020 us=846620 OpenVPN 2.4.9 [git:HEAD/9b0dafca6c50b8bb] x86_64-pc-linux-gnu [SSL (OpenSSL)] [EPOLL] [MH/PKTINFO] [AEAD] built on Apr 18 2020
Sat Apr 18 17:38:45 2020 us=846630 library versions: OpenSSL 1.0.2g  1 Mar 2016
Sat Apr 18 17:38:45 2020 us=846670 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Sat Apr 18 17:38:45 2020 us=847009 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Sat Apr 18 17:38:45 2020 us=847464 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:4 ET:0 EL:3 ]
Sat Apr 18 17:38:45 2020 us=847788 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Sat Apr 18 17:38:45 2020 us=847965 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1541,tun-mtu 1500,proto UDPv4,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Sat Apr 18 17:38:45 2020 us=848386 TCP/UDP: Preserving recently used remote address: [AF_INET]128.199.aaa.bbb:1194
Sat Apr 18 17:38:45 2020 us=848632 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sat Apr 18 17:38:45 2020 us=849003 UDP link local (bound): [AF_INET][undef]:1194
Sat Apr 18 17:38:45 2020 us=849300 UDP link remote: [AF_INET]128.199.aaa.bbb:1194
Sat Apr 18 17:38:45 2020 us=897962 TLS: Initial packet from [AF_INET]128.199.aaa.bbb:1194, sid=34aba01d 93a60180
Sat Apr 18 17:38:45 2020 us=952719 VERIFY OK: depth=1, CN=LeeviCA5
Sat Apr 18 17:38:45 2020 us=953585 VERIFY OK: depth=0, CN=server.fi
Sat Apr 18 17:38:46 2020 us=62984 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1541', remote='link-mtu 1557'
Sat Apr 18 17:38:46 2020 us=63255 WARNING: 'cipher' is used inconsistently, local='cipher BF-CBC', remote='cipher AES-256-CBC'
Sat Apr 18 17:38:46 2020 us=64273 WARNING: 'keysize' is used inconsistently, local='keysize 128', remote='keysize 256'
Sat Apr 18 17:38:46 2020 us=65734 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Apr 18 17:38:46 2020 us=65845 [server.fi] Peer Connection Initiated with [AF_INET]128.199.aaa.bbb:1194
Sat Apr 18 17:38:47 2020 us=98157 SENT CONTROL [server.fi]: 'PUSH_REQUEST' (status=1)
Sat Apr 18 17:38:49 2020 us=153053 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 2001:4860:4860::8888,dhcp-option DNS 10.8.0.1,route 10.66.0.0 255.255.255.0,tun-ipv6,route-gateway 10.8.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:123::1000/64 2001:db8:0:123::1,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Sat Apr 18 17:38:49 2020 us=154156 OPTIONS IMPORT: timers and/or timeouts modified
Sat Apr 18 17:38:49 2020 us=155004 OPTIONS IMPORT: --ifconfig/up options modified
Sat Apr 18 17:38:49 2020 us=155354 OPTIONS IMPORT: route options modified
Sat Apr 18 17:38:49 2020 us=155807 OPTIONS IMPORT: route-related options modified
Sat Apr 18 17:38:49 2020 us=156268 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sat Apr 18 17:38:49 2020 us=156603 OPTIONS IMPORT: peer-id set
Sat Apr 18 17:38:49 2020 us=156950 OPTIONS IMPORT: adjusting link_mtu to 1624
Sat Apr 18 17:38:49 2020 us=157277 OPTIONS IMPORT: data channel crypto options modified
Sat Apr 18 17:38:49 2020 us=157700 Data Channel: using negotiated cipher 'AES-256-GCM'
Sat Apr 18 17:38:49 2020 us=157775 Data Channel MTU parms [ L:1552 D:1450 EF:52 EB:4 ET:0 EL:3 ]
Sat Apr 18 17:38:49 2020 us=158390 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Apr 18 17:38:49 2020 us=158468 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Apr 18 17:38:49 2020 us=159152 ROUTE_GATEWAY 10.0.2.2/255.255.255.0 IFACE=enp0s3 HWADDR=08:00:27:6c:08:1e
Sat Apr 18 17:38:49 2020 us=160531 TUN/TAP device tun0 opened
Sat Apr 18 17:38:49 2020 us=160635 TUN/TAP TX queue length set to 100
Sat Apr 18 17:38:49 2020 us=161037 do_ifconfig, tt->did_ifconfig_ipv6_setup=1
Sat Apr 18 17:38:49 2020 us=161303 /sbin/ifconfig tun0 10.8.0.2 netmask 255.255.255.0 mtu 1500 broadcast 10.8.0.255
Sat Apr 18 17:38:49 2020 us=163456 /sbin/ifconfig tun0 add 2001:db8:0:123::1000/64
Sat Apr 18 17:38:49 2020 us=164739 /sbin/route add -net 10.66.0.0 netmask 255.255.255.0 gw 10.8.0.1
Sat Apr 18 17:38:49 2020 us=165941 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Sat Apr 18 17:38:49 2020 us=171521 Initialization Sequence Completed

As you may see, server and client negotiated AES-256-GCM.

Scenario 2

Server config is the same as above. Client config:

ncp-disable
cipher AES-256-GCM

Server log:

Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 Re-using SSL/TLS context
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 TLS: Initial packet from [AF_INET]81.175.xxx.yyy:52207, sid=0bdaac1b bde4752d
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_TLS_VERIFY status=0
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 VERIFY PLUGIN OK: depth=1, CN=LeeviCA5
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 VERIFY OK: depth=1, CN=LeeviCA5
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_TLS_VERIFY status=0
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 VERIFY PLUGIN OK: depth=0, CN=client42
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 VERIFY OK: depth=0, CN=client42
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 peer info: IV_VER=2.4.9
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 peer info: IV_PLAT=linux
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 peer info: IV_PROTO=2
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 TLS: Username/Password authentication deferred for username ''
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1557', remote='link-mtu 1549'
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-CBC', remote='cipher AES-256-GCM'
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 WARNING: 'auth' is used inconsistently, local='auth SHA1', remote='auth [null-digest]'
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_TLS_FINAL status=0
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 [client42] Peer Connection Initiated with [AF_INET]81.175.xxx.yyy:52207
Apr 18 17:55:47 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_IPCHANGE status=0
Apr 18 17:55:48 stipakov openvpn[2409]: 81.175.xxx.yyy:52207 PUSH: Received control message: 'PUSH_REQUEST'
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=2001:db8:0:123::1000
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_CLIENT_CONNECT status=0
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_LEARN_ADDRESS status=0
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 MULTI: Learn: 10.8.0.2 -> client42/81.175.xxx.yyy:52207
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 MULTI: primary virtual IP for client42/81.175.xxx.yyy:52207: 10.8.0.2
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 PLUGIN_CALL: POST /home/lev/Projects/openvpn/sample/sample-plugins/defer/simple.so/PLUGIN_LEARN_ADDRESS status=0
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 MULTI: Learn: 2001:db8:0:123::1000 -> client42/81.175.xxx.yyy:52207
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 MULTI: primary virtual IPv6 for client42/81.175.xxx.yyy:52207: 2001:db8:0:123::1000
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 Using peer cipher 'AES-256-GCM'
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 SENT CONTROL [client42]: 'PUSH_REPLY,dhcp-option DNS 2001:4860:4860::8888,dhcp-option DNS 10.8.0.1,route 10.66.0.0 255.255.255.0,tun-ipv6,route-gateway 10.8.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:123::1000/64 2001:db8:0:123::1,ifconfig 10.8.0.2 255.255.255.0,peer-id 0' (status=1)
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 Data Channel: using negotiated cipher 'AES-256-GCM'
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 Data Channel MTU parms [ L:1549 D:1450 EF:49 EB:406 ET:0 EL:3 ]
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Apr 18 17:55:50 stipakov openvpn[2409]: client42/81.175.xxx.yyy:52207 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key

Client log:

Sat Apr 18 17:55:47 2020 us=31196 OpenVPN 2.4.9 [git:HEAD/9b0dafca6c50b8bb] x86_64-pc-linux-gnu [SSL (OpenSSL)] [EPOLL] [MH/PKTINFO] [AEAD] built on Apr 18 2020
Sat Apr 18 17:55:47 2020 us=31208 library versions: OpenSSL 1.0.2g  1 Mar 2016
Sat Apr 18 17:55:47 2020 us=31301 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Sat Apr 18 17:55:47 2020 us=31968 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Sat Apr 18 17:55:47 2020 us=32089 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:4 ET:0 EL:3 ]
Sat Apr 18 17:55:47 2020 us=32111 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
Sat Apr 18 17:55:47 2020 us=32120 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
Sat Apr 18 17:55:47 2020 us=32131 TCP/UDP: Preserving recently used remote address: [AF_INET]128.199.xxx.yyy:1194
Sat Apr 18 17:55:47 2020 us=32146 Socket Buffers: R=[212992->212992] S=[212992->212992]
Sat Apr 18 17:55:47 2020 us=32157 UDP link local (bound): [AF_INET][undef]:1194
Sat Apr 18 17:55:47 2020 us=32165 UDP link remote: [AF_INET]128.199.xxx.yyy:1194
Sat Apr 18 17:55:47 2020 us=83650 TLS: Initial packet from [AF_INET]128.199.xxx.yyy:1194, sid=e5cbd65a d0fd1fee
Sat Apr 18 17:55:47 2020 us=138222 VERIFY OK: depth=1, CN=LeeviCA5
Sat Apr 18 17:55:47 2020 us=139235 VERIFY OK: depth=0, CN=server.fi
Sat Apr 18 17:55:47 2020 us=245312 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1549', remote='link-mtu 1557'
Sat Apr 18 17:55:47 2020 us=245625 WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher AES-256-CBC'
Sat Apr 18 17:55:47 2020 us=247213 WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1'
Sat Apr 18 17:55:47 2020 us=248429 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Sat Apr 18 17:55:47 2020 us=248872 [server.fi] Peer Connection Initiated with [AF_INET]128.199.xxx.yyy:1194
Sat Apr 18 17:55:48 2020 us=496886 SENT CONTROL [server.fi]: 'PUSH_REQUEST' (status=1)
Sat Apr 18 17:55:50 2020 us=291692 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 2001:4860:4860::8888,dhcp-option DNS 10.8.0.1,route 10.66.0.0 255.255.255.0,tun-ipv6,route-gateway 10.8.0.1,topology subnet,ping 30,ping-restart 180,ifconfig-ipv6 2001:db8:0:123::1000/64 2001:db8:0:123::1,ifconfig 10.8.0.2 255.255.255.0,peer-id 0'
Sat Apr 18 17:55:50 2020 us=292440 OPTIONS IMPORT: timers and/or timeouts modified
Sat Apr 18 17:55:50 2020 us=292712 OPTIONS IMPORT: --ifconfig/up options modified
Sat Apr 18 17:55:50 2020 us=293046 OPTIONS IMPORT: route options modified
Sat Apr 18 17:55:50 2020 us=293690 OPTIONS IMPORT: route-related options modified
Sat Apr 18 17:55:50 2020 us=294035 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Sat Apr 18 17:55:50 2020 us=294755 OPTIONS IMPORT: peer-id set
Sat Apr 18 17:55:50 2020 us=295136 OPTIONS IMPORT: adjusting link_mtu to 1624
Sat Apr 18 17:55:50 2020 us=295497 Data Channel MTU parms [ L:1552 D:1450 EF:52 EB:4 ET:0 EL:3 ]
Sat Apr 18 17:55:50 2020 us=296072 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Apr 18 17:55:50 2020 us=296178 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Sat Apr 18 17:55:50 2020 us=297143 ROUTE_GATEWAY 10.0.2.2/255.255.255.0 IFACE=enp0s3 HWADDR=08:00:27:6c:08:1e
Sat Apr 18 17:55:50 2020 us=298706 TUN/TAP device tun0 opened
Sat Apr 18 17:55:50 2020 us=299062 TUN/TAP TX queue length set to 100
Sat Apr 18 17:55:50 2020 us=299405 do_ifconfig, tt->did_ifconfig_ipv6_setup=1
Sat Apr 18 17:55:50 2020 us=300151 /sbin/ifconfig tun0 10.8.0.2 netmask 255.255.255.0 mtu 1500 broadcast 10.8.0.255
Sat Apr 18 17:55:50 2020 us=301759 /sbin/ifconfig tun0 add 2001:db8:0:123::1000/64
Sat Apr 18 17:55:50 2020 us=302938 /sbin/route add -net 10.66.0.0 netmask 255.255.255.0 gw 10.8.0.1
Sat Apr 18 17:55:50 2020 us=304641 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Sat Apr 18 17:55:50 2020 us=311078 Initialization Sequence Completed

Again, client and server agreed on AES-256-GCM. This line in server log

Using peer cipher 'AES-256-GCM'

indicates that server used so called "poor man's NCP".

comment:7 Changed 4 years ago by stipa

I tested that if client config contains only

cipher AES-256-CBC

then 2.3.10 connects with AES-256-CBC and 2.4.9 with AES-256-GCM. Async-push is enabled on server (2.4.9) side.

comment:8 Changed 4 years ago by szatam

Hi Lev!
Thanks for testing. I've debugged the issue further.
I'm using a plugin for the authentication stage to generate client connect temporary files with dynamic values. It intercepts the PLUGIN_AUTH_USER_PASS_VERIFY stage.

Connection between 2.4.9 versions -
It seems the wrong cipher is appended to the server's push_reply (value of 'cipher' and not any of the ciphers from ncp_ciphers)
When disabling the plugin the correct cipher is pushed (based on ncp negotiation or poor man's ncp).

Last edited 4 years ago by szatam (previous) (diff)

comment:9 Changed 4 years ago by szatam

The generated tempfile looks something like this:

push "persist-key"
push "redirect-gateway def1"
push "explicit-exit-notify 2"
push "route-gateway xxx"
push "topology subnet"
push "compress"
compress
ifconfig-push xxx yyy
push "tun-ipv6"
ifconfig-ipv6-push xxx/xx xxx
push "route-ipv6 2000::/3"
push "dhcp-option yyy"
push "dhcp-option xxx"

comment:10 Changed 4 years ago by szatam

This is the part where it fails using the plugin:

Sat Apr 18 20:45:38 2020 us=931797 xxx PUSH: client wants to negotiate cipher (NCP), but server has already generated data channel keys, re-sending previously negotiated cipher 'AES-256-CBC'

comment:11 Changed 4 years ago by szatam

If I append a short sleep cycle (500 msec) to the script called by the auth-user-verify plugin, the correct cipher gets appended to the push_reply

Version 2, edited 4 years ago by szatam (previous) (next) (diff)

comment:12 Changed 4 years ago by stipa

The sample plugin I've tried also intercepts PLUGIN_AUTH_USER_PASS_VERIFY.

Could you post server log with verb 7 (which displays inotify events) ?

comment:13 in reply to:  11 Changed 4 years ago by ss-17

Replying to szatam:

If I append a short sleep cycle (1000 msec) to the script called by the auth-user-verify plugin, the correct cipher gets appended to the push_reply

I am also experiencing similar behavior with async push feature. Used "cipher AES-128-CBC" on server (1.2.3.4) and "cipher AES-256-CBC" on client (5.6.7.8) so that they mismatch and then something has to picked from the default negotiated ciphers list. It doesn't work if I don't induce a artificial 2 second delay in the deferred authentication script. With the delay in place, client & server negotiate a cipher and connect successfully. Here are the Verb 7 logs of both scenarios:

Server log w/o induced delay in deferred auth script: https://dpaste.org/wY4s/slim
Client log w/o induced delay in deferred auth script: https://dpaste.org/vUG1/slim

Server log with 2s delay induced in deferred auth script: https://dpaste.org/kGEo/slim
Client log with 2s delay induced in deferred auth script: https://dpaste.org/QT1g/slim

comment:14 Changed 4 years ago by Gert Döring

Milestone: release 2.4release 2.4.10

I am fairly confident that this is fixed for good in 2.5 (@szatam: please test and report!) - the server side got real thorough testing with async-auth-pam and/or async-client-connect, with and without --enable-async-push.

For 2.4, not sure what to do next. Maybe stall until we have 2.5.0 released and then see how / if we can fix it for 2.4? @stipa, what do you think?

comment:16 Changed 4 years ago by Gert Döring

Resolution: fixed
Status: newclosed

Thanks. Indeed :-) - so we can close this.

Note: See TracTickets for help on using tickets.