Opened 4 years ago

Closed 3 years ago

#1316 closed Bug / Defect (fixed)

Server Key [AF_INET]foo:bar [0] not initialized (yet) does not recover - Client without --nobind

Reported by: tct Owned by: Gert Döring
Priority: major Milestone: release 2.5.2
Component: Generic / unclassified Version: OpenVPN 2.5.1 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc: tct, Steffan Karger, plaisthos, Gert Döring, Antonio Quartulli

Description

Standard server 2.6 using --persist-key
Standard client 2.6

When the keys de-sync then the server does not recover.

How to reproduce:

My server is a VM, all I need to do is save-state the VM.
Then sometime later (~2mins or 20mins eg. After the client times out) restore the VM.

The server is still running the same instance and the client has been doing normal reconnect attempts during the downtime.

Now the client appears to connect ok, although it is not, and the server has this in the logs:

2020-08-17 12:58:08 us=883493 tct-c01/foo:bar Key [AF_INET]foo:bar [0] not initialized (yet), dropping packet.

The server never recovers from this. I even waited for server --reneg-sec to roll over but that had no effect either.

Attachments (3)

server-1316.txt (44.7 KB) - added by tct 4 years ago.
client-1316.txt (52.9 KB) - added by tct 4 years ago.
t.t (19.3 KB) - added by tct 3 years ago.

Download all attachments as: .zip

Change History (22)

comment:1 Changed 4 years ago by tct

Cc: tct added

comment:2 Changed 4 years ago by tct

Cc: Steffan Karger plaisthos Gert Döring Antonio Quartulli added

comment:3 Changed 4 years ago by plaisthos

Can you add OpenVPN logs for both client ander server?

Version 0, edited 4 years ago by plaisthos (next)

comment:4 Changed 4 years ago by tct

Attaching logs.

Notes: The client has multiple <connection> blocks and --nobind is used after them, so the client did bind to 1194. However the intervening router uses SNAT on egress, so in the server log the client port is 4024. Also, all the <connection> blocks --remote resolve to the same IP and the client log shows no further resolving, it shows preserving recently used remote address

Changed 4 years ago by tct

Attachment: server-1316.txt added

Changed 4 years ago by tct

Attachment: client-1316.txt added

comment:5 Changed 4 years ago by tct

In the server log the server VM was saved/restored here:

2020-08-17 17:04:25 us=347255 tct.ccc.c01/79.71.aaa.bbb:4024 SENT CONTROL [tct.ccc.c01]: 'PUSH_REPLY,topology subnet,explicit-exit-notify 3,comp-lzo no,tun-ipv6,route-gateway 10.55.111.1,topology subnet,ping 10,ping-restart 30,route 10.7.39.137,ifconfig-ipv6 12fc:1918::10:55:111:2/112 12fc:1918::10:55:111:1,ifconfig 10.55.111.101 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)	
2020-08-17 17:05:34 us=431217 tct.ccc.c01/79.71.aaa.bbb:4024 TLS: new session incoming connection from [AF_INET]79.71.aaa.bbb:4024

About 10 seconds after the client first connection.

comment:6 Changed 4 years ago by tct

I tried this again with the same server/client but this time the client is correctly using --nobind (And connecting to a local IP address). The server immediately resolved the new connection with:

2020-08-17 22:18:00 us=676165 10.10.101.101:36295 TLS: Initial packet from [AF_INET]10.10.101.101:36295, sid=b98338f2 5040cad3

The original connection being from port 47197. So this is not an issue in this case.

So i tried again without --nobind and bingo! Server key not initialised.

Log snippets of the event:

SERVER:

2020-08-17 22:25:32 us=63160 tct.aaa.c01/10.10.101.101:1194 SENT CONTROL [tct.aaa.c01]: 'PUSH_REPLY,topology subnet,explicit-exit-notify 3,comp-lzo no,tun-ipv6,route-gateway 10.55.111.1,topology subnet,ping 10,ping-restart 60,route 10.7.39.137,ifconfig-ipv6 12fc:1918::10:55:111:2/112 12fc:1918::10:55:111:1,ifconfig 10.55.111.101 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
2020-08-17 22:27:10 us=949820 tct.aaa.c01/10.10.101.101:1194 TLS: new session incoming connection from [AF_INET]10.10.101.101:1194
2020-08-17 22:27:10 us=983040 tct.aaa.c01/10.10.101.101:1194 VERIFY OK: depth=1, C=00, ST=tct, L=home, O=tctnet, OU=tctnet-secp384r1, CN=CA tct-secp384r1, emailAddress=me@home.org
2020-08-17 22:27:10 us=985036 tct.aaa.c01/10.10.101.101:1194 VERIFY KU OK
2020-08-17 22:27:10 us=985072 tct.aaa.c01/10.10.101.101:1194 Validating certificate extended key usage
2020-08-17 22:27:10 us=985094 tct.aaa.c01/10.10.101.101:1194 ++ Certificate has EKU (str) TLS Web Client Authentication, expects TLS Web Client Authentication
2020-08-17 22:27:10 us=985112 tct.aaa.c01/10.10.101.101:1194 VERIFY EKU OK
2020-08-17 22:27:10 us=985130 tct.aaa.c01/10.10.101.101:1194 VERIFY OK: depth=0, C=00, ST=tct, L=home, O=tctnet, OU=tctnet-secp384r1, CN=tct.aaa.c01, emailAddress=me@home.org
2020-08-17 22:27:10 us=992844 tct.aaa.c01/10.10.101.101:1194 peer info: IV_VER=2.6_git
2020-08-17 22:27:10 us=992901 tct.aaa.c01/10.10.101.101:1194 peer info: IV_PLAT=linux
2020-08-17 22:27:10 us=992924 tct.aaa.c01/10.10.101.101:1194 peer info: IV_PROTO=6
2020-08-17 22:27:10 us=992944 tct.aaa.c01/10.10.101.101:1194 peer info: IV_NCP=2
2020-08-17 22:27:10 us=992964 tct.aaa.c01/10.10.101.101:1194 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
2020-08-17 22:27:10 us=992984 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZ4=1
2020-08-17 22:27:10 us=993026 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZ4v2=1
2020-08-17 22:27:10 us=993047 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZO=1
2020-08-17 22:27:10 us=993067 tct.aaa.c01/10.10.101.101:1194 peer info: IV_COMP_STUB=1
2020-08-17 22:27:10 us=993086 tct.aaa.c01/10.10.101.101:1194 peer info: IV_COMP_STUBv2=1
2020-08-17 22:27:10 us=993105 tct.aaa.c01/10.10.101.101:1194 peer info: IV_TCPNL=1
2020-08-17 22:27:10 us=993125 tct.aaa.c01/10.10.101.101:1194 peer info: IV_HWADDR=24:b6:fd:31:bc:ca
2020-08-17 22:27:10 us=993145 tct.aaa.c01/10.10.101.101:1194 peer info: IV_SSL=OpenSSL_1.1.1__11_Sep_2018
2020-08-17 22:27:10 us=993165 tct.aaa.c01/10.10.101.101:1194 peer info: UV_INFO=v3.rsa.ossl11.cli01.mint
2020-08-17 22:27:10 us=993184 tct.aaa.c01/10.10.101.101:1194 peer info: UV_PING=10
2020-08-17 22:27:10 us=993203 tct.aaa.c01/10.10.101.101:1194 peer info: UV_PINGR=60
2020-08-17 22:27:10 us=993307 tct.aaa.c01/10.10.101.101:1194 TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
2020-08-17 22:27:10 us=993436 tct.aaa.c01/10.10.101.101:1194 TLS: tls_multi_process: untrusted session promoted to semi-trusted
2020-08-17 22:27:10 us=995063 tct.aaa.c01/10.10.101.101:1194 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-ECDSA-AES256-GCM-SHA384, 384 bit EC, curve: secp384r1
2020-08-17 22:27:12 us=111671 tct.aaa.c01/10.10.101.101:1194 PUSH: Received control message: 'PUSH_REQUEST'
2020-08-17 22:27:12 us=111881 tct.aaa.c01/10.10.101.101:1194 SENT CONTROL [tct.aaa.c01]: 'PUSH_REPLY,topology subnet,explicit-exit-notify 3,comp-lzo no,tun-ipv6,route-gateway 10.55.111.1,topology subnet,ping 10,ping-restart 60,route 10.7.39.137,ifconfig-ipv6 12fc:1918::10:55:111:2/112 12fc:1918::10:55:111:1,ifconfig 10.55.111.101 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
2020-08-17 22:27:22 us=550378 tct.aaa.c01/10.10.101.101:1194 Key [AF_INET]10.10.101.101:1194 [0] not initialized (yet), dropping packet.

CLIENT:

2020-08-17 22:25:32 us=119851 Initialization Sequence Completed
2020-08-17 22:26:40 us=11617 [tct.bbb.s01] Inactivity timeout (--ping-restart), restarting
2020-08-17 22:26:40 us=11802 TCP/UDP: Closing socket
2020-08-17 22:26:40 us=11862 SIGUSR1[soft,ping-restart] received, process restarting
2020-08-17 22:26:40 us=11885 Restart pause, 10 second(s)
2020-08-17 22:26:50 us=12020 Re-using SSL/TLS context
2020-08-17 22:26:50 us=12281 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2020-08-17 22:26:50 us=12329 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2020-08-17 22:26:50 us=12442 Control Channel MTU parms [ L:1626 D:1184 EF:66 EB:0 ET:0 EL:3 ]
2020-08-17 22:26:50 us=12535 Data Channel MTU parms [ L:1626 D:1300 EF:126 EB:407 ET:0 EL:3 ]
2020-08-17 22:26:50 us=12560 Fragmentation MTU parms [ L:1626 D:1300 EF:125 EB:407 ET:1 EL:3 ]
2020-08-17 22:26:50 us=12619 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1554,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,keydir 1,ciph
er AES-256-GCM,auth [null-digest],keysize 256,tls-auth,key-method 2,tls-client'
2020-08-17 22:26:50 us=12639 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1554,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,key
dir 0,cipher AES-256-GCM,auth [null-digest],keysize 256,tls-auth,key-method 2,tls-server'
2020-08-17 22:26:50 us=12668 TCP/UDP: Preserving recently used remote address: [AF_INET]10.10.201.226:55111
2020-08-17 22:26:50 us=12722 Socket Buffers: R=[212992->212992] S=[212992->212992]
2020-08-17 22:26:50 us=12757 UDPv4 link local (bound): [AF_INET][undef]:1194
2020-08-17 22:26:50 us=12778 UDPv4 link remote: [AF_INET]10.10.201.226:55111
2020-08-17 22:27:01 us=420757 TLS Error: local/remote TLS keys are out of sync: [AF_INET]10.10.201.226:55111 [0]

It is not hard to replicate, just use a nice --ping-restart period for the server and you have time, i used --keepalive 10 60

FTR: I Let this run for some time, server is still lost:

2020-08-17 22:41:08 us=20902 tct.aaa.c01/10.10.101.101:1194 Key [AF_INET]10.10.101.101:1194 [0] not initialized (yet), dropping packet.
2020-08-17 22:41:26 us=606230 tct.aaa.c01/10.10.101.101:1194 TLS: new session incoming connection from [AF_INET]10.10.101.101:1194
2020-08-17 22:41:26 us=637380 tct.aaa.c01/10.10.101.101:1194 VERIFY OK: depth=1, C=00, ST=tct, L=home, O=tctnet, OU=tctnet-secp384r1, CN=CA tct-secp384r1, emailAddress=me@home.org
2020-08-17 22:41:26 us=641265 tct.aaa.c01/10.10.101.101:1194 VERIFY KU OK
2020-08-17 22:41:26 us=641334 tct.aaa.c01/10.10.101.101:1194 Validating certificate extended key usage
2020-08-17 22:41:26 us=641356 tct.aaa.c01/10.10.101.101:1194 ++ Certificate has EKU (str) TLS Web Client Authentication, expects TLS Web Client Authentication
2020-08-17 22:41:26 us=641379 tct.aaa.c01/10.10.101.101:1194 VERIFY EKU OK
2020-08-17 22:41:26 us=641397 tct.aaa.c01/10.10.101.101:1194 VERIFY OK: depth=0, C=00, ST=tct, L=home, O=tctnet, OU=tctnet-secp384r1, CN=tct.aaa.c01, emailAddress=me@home.org
2020-08-17 22:41:26 us=650269 tct.aaa.c01/10.10.101.101:1194 peer info: IV_VER=2.6_git
2020-08-17 22:41:26 us=650361 tct.aaa.c01/10.10.101.101:1194 peer info: IV_PLAT=linux
2020-08-17 22:41:26 us=650394 tct.aaa.c01/10.10.101.101:1194 peer info: IV_PROTO=6
2020-08-17 22:41:26 us=650424 tct.aaa.c01/10.10.101.101:1194 peer info: IV_NCP=2
2020-08-17 22:41:26 us=650453 tct.aaa.c01/10.10.101.101:1194 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
2020-08-17 22:41:26 us=650483 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZ4=1
2020-08-17 22:41:26 us=650512 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZ4v2=1
2020-08-17 22:41:26 us=650541 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZO=1
2020-08-17 22:41:26 us=650570 tct.aaa.c01/10.10.101.101:1194 peer info: IV_COMP_STUB=1
2020-08-17 22:41:26 us=650600 tct.aaa.c01/10.10.101.101:1194 peer info: IV_COMP_STUBv2=1
2020-08-17 22:41:26 us=650629 tct.aaa.c01/10.10.101.101:1194 peer info: IV_TCPNL=1
2020-08-17 22:41:26 us=650693 tct.aaa.c01/10.10.101.101:1194 peer info: IV_HWADDR=24:b6:fd:31:bc:ca
2020-08-17 22:41:26 us=650725 tct.aaa.c01/10.10.101.101:1194 peer info: IV_SSL=OpenSSL_1.1.1__11_Sep_2018
2020-08-17 22:41:26 us=650755 tct.aaa.c01/10.10.101.101:1194 peer info: UV_INFO=v3.rsa.ossl11.cli01.mint
2020-08-17 22:41:26 us=650784 tct.aaa.c01/10.10.101.101:1194 peer info: UV_PING=10
2020-08-17 22:41:26 us=650813 tct.aaa.c01/10.10.101.101:1194 peer info: UV_PINGR=60
2020-08-17 22:41:26 us=650959 tct.aaa.c01/10.10.101.101:1194 TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
2020-08-17 22:41:26 us=651135 tct.aaa.c01/10.10.101.101:1194 TLS: tls_multi_process: untrusted session promoted to semi-trusted
2020-08-17 22:41:26 us=652818 tct.aaa.c01/10.10.101.101:1194 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-ECDSA-AES256-GCM-SHA384, 384 bit EC, curve: secp384r1
2020-08-17 22:41:27 us=671244 tct.aaa.c01/10.10.101.101:1194 PUSH: Received control message: 'PUSH_REQUEST'
2020-08-17 22:41:27 us=671327 tct.aaa.c01/10.10.101.101:1194 SENT CONTROL [tct.aaa.c01]: 'PUSH_REPLY,topology subnet,explicit-exit-notify 3,comp-lzo no,tun-ipv6,route-gateway 10.55.111.1,topology subnet,ping 10,ping-restart 60,route 10.7.39.137,ifconfig-ipv6 12fc:1918::10:55:111:2/112 12fc:1918::10:55:111:1,ifconfig 10.55.111.101 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
2020-08-17 22:41:37 us=855554 tct.aaa.c01/10.10.101.101:1194 Key [AF_INET]10.10.101.101:1194 [0] not initialized (yet), dropping packet.

comment:7 Changed 4 years ago by tct

Summary: Key [AF_INET]foo:bar [0] not initialized (yet) does not recover with --persist-keyServer Key [AF_INET]foo:bar [0] not initialized (yet) does not recover - Client without --nobind

comment:8 Changed 4 years ago by tct

I forgot this was running:

2020-08-18 08:15:26 us=94514 tct.aaa.c01/10.10.101.101:1194 TLS: new session incoming connection from [AF_INET]10.10.101.101:1194
2020-08-18 08:15:26 us=125348 tct.aaa.c01/10.10.101.101:1194 VERIFY OK: depth=1, C=00, ST=tct, L=home, O=tctnet, OU=tctnet-secp384r1, CN=CA tct-secp384r1, emailAddress=me@home.org
2020-08-18 08:15:26 us=128675 tct.aaa.c01/10.10.101.101:1194 VERIFY KU OK
2020-08-18 08:15:26 us=128755 tct.aaa.c01/10.10.101.101:1194 Validating certificate extended key usage
2020-08-18 08:15:26 us=128797 tct.aaa.c01/10.10.101.101:1194 ++ Certificate has EKU (str) TLS Web Client Authentication, expects TLS Web Client Authentication
2020-08-18 08:15:26 us=128841 tct.aaa.c01/10.10.101.101:1194 VERIFY EKU OK
2020-08-18 08:15:26 us=128871 tct.aaa.c01/10.10.101.101:1194 VERIFY OK: depth=0, C=00, ST=tct, L=home, O=tctnet, OU=tctnet-secp384r1, CN=tct.aaa.c01, emailAddress=me@home.org
2020-08-18 08:15:26 us=138214 tct.aaa.c01/10.10.101.101:1194 peer info: IV_VER=2.6_git
2020-08-18 08:15:26 us=138305 tct.aaa.c01/10.10.101.101:1194 peer info: IV_PLAT=linux
2020-08-18 08:15:26 us=138382 tct.aaa.c01/10.10.101.101:1194 peer info: IV_PROTO=6
2020-08-18 08:15:26 us=138417 tct.aaa.c01/10.10.101.101:1194 peer info: IV_NCP=2
2020-08-18 08:15:26 us=138450 tct.aaa.c01/10.10.101.101:1194 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
2020-08-18 08:15:26 us=138483 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZ4=1
2020-08-18 08:15:26 us=138515 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZ4v2=1
2020-08-18 08:15:26 us=138547 tct.aaa.c01/10.10.101.101:1194 peer info: IV_LZO=1
2020-08-18 08:15:26 us=138579 tct.aaa.c01/10.10.101.101:1194 peer info: IV_COMP_STUB=1
2020-08-18 08:15:26 us=138611 tct.aaa.c01/10.10.101.101:1194 peer info: IV_COMP_STUBv2=1
2020-08-18 08:15:26 us=138643 tct.aaa.c01/10.10.101.101:1194 peer info: IV_TCPNL=1
2020-08-18 08:15:26 us=138675 tct.aaa.c01/10.10.101.101:1194 peer info: IV_HWADDR=24:b6:fd:31:bc:ca
2020-08-18 08:15:26 us=138707 tct.aaa.c01/10.10.101.101:1194 peer info: IV_SSL=OpenSSL_1.1.1__11_Sep_2018
2020-08-18 08:15:26 us=138739 tct.aaa.c01/10.10.101.101:1194 peer info: UV_INFO=v3.rsa.ossl11.cli01.mint
2020-08-18 08:15:26 us=138770 tct.aaa.c01/10.10.101.101:1194 peer info: UV_PING=10
2020-08-18 08:15:26 us=138801 tct.aaa.c01/10.10.101.101:1194 peer info: UV_PINGR=60
2020-08-18 08:15:26 us=138982 tct.aaa.c01/10.10.101.101:1194 TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
2020-08-18 08:15:26 us=139243 tct.aaa.c01/10.10.101.101:1194 TLS: tls_multi_process: untrusted session promoted to semi-trusted
2020-08-18 08:15:26 us=141094 tct.aaa.c01/10.10.101.101:1194 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-ECDSA-AES256-GCM-SHA384, 384 bit EC, curve: secp384r1
2020-08-18 08:15:27 us=303864 tct.aaa.c01/10.10.101.101:1194 PUSH: Received control message: 'PUSH_REQUEST'
2020-08-18 08:15:27 us=304005 tct.aaa.c01/10.10.101.101:1194 SENT CONTROL [tct.aaa.c01]: 'PUSH_REPLY,topology subnet,explicit-exit-notify 3,comp-lzo no,tun-ipv6,route-gateway 10.55.111.1,topology subnet,ping 10,ping-restart 60,route 10.7.39.137,ifconfig-ipv6 12fc:1918::10:55:111:2/112 12fc:1918::10:55:111:1,ifconfig 10.55.111.101 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
2020-08-18 08:15:37 us=725386 tct.aaa.c01/10.10.101.101:1194 Key [AF_INET]10.10.101.101:1194 [0] not initialized (yet), dropping packet.

comment:9 Changed 4 years ago by tct

I restarted the client using systemctl stop/start openvpn-client@foo and the server key is still not initialised.

I restarted the server using systemctl restart openvpn-server@foo and obviously the tunnel was finally established.

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

not using nobind on the client is arguably a bad idea, but the server should handle this better.

Please try against a current master (as of "last week"). I merged a heap of patches from arne that deauth a client that is zombified - the intent was something else, but it might help in this case as well.

comment:11 Changed 3 years ago by tct

First, I successfully reproduced the problem.

Server: commit 99d217b20064e7fef90dfa49bdcbab23ea7fbcb3
Client: OpenVPN 2.5.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Oct 28 2020

Then cloned git/master to a new folder and did the thang..

The same error occurred in exactly the same way. I was very careful to ensure I used the correct binary.

Server log --verb 6 added -- shows key not initialised three times.

Last edited 3 years ago by tct (previous) (diff)

Changed 3 years ago by tct

Attachment: t.t added

comment:12 Changed 3 years ago by plaisthos

The problem is that our NCP code has an assumption that key_id == 0 is a first connect and key generation is done in the first time setup of a client. For some reason with a client without nobind we can end up with a continuing of a tls multi session that at the same has the key_id=0, so we never generated the key material as it somehow is a new session but also isn't. I need to look into and understand how we get into this strange state.

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

commit a005044be9ca77ee8a47cb65a603d0b1c41b99f4 (master)
commit 227fbc117d58a87465804f7b2a5cd95ef1b94da6 (release/2.5)
Author: Arne Schwabe
Date: Sun Mar 28 14:02:41 2021 +0200

Fix condition to generate session keys

and it needs this patch to be able to access "context_auth now called multi_state" in the right place

commit 0767d5b447044e4cdcfd198058aef1f85f63bbe6 (master)
commit 145110101b70599cb9adcf4ed071856daac9c8af (release/2.5)
Author: Arne Schwabe
Date: Sun Apr 18 18:01:11 2021 +0200

Move context_auth from context_2 to tls_multi and name it multi_state

I think this also needs fixing for 2.4, but I will make this a separate patch because it needs an extra 4-eyes-check.

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

@tincantech: with master or release/2.5, it should now do what you want it to :-)

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

Milestone: release 2.5.2
Owner: set to Gert Döring
Status: newaccepted
Version: OpenVPN 2.5.1 (Community Ed)

Okay, I tested against a release/2.4 git server, and I could not reproduce the problematic behaviour. As in: I connected, renegotiated, aborted, reconnected from the same port, and I had no "keys out of sync" issues. So it seems the problematic "in-between and keys not done" behaviour got added on the way to 2.5, not "already in 2.4" (I suspected it might have come in with NCP v1).

@tincantech: can you reproduce this with a 2.4 server?

comment:16 Changed 3 years ago by plaisthos

I think this was a result of the openvpn connect refactoring. Before that we did generate the session keys on a PULL_REQUEST and now we generate it as soon as the client is fully authenticated.

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

@tincantech: waiting for your test results - and then we can close this, I think.

comment:18 Changed 3 years ago by tct

A brief rerun of the test as follows:

Server log after resume from sleep, shows new TLS session being handled correctly:

2021-06-15 12:51:47 us=295959 deb10/10.10.201.210:1194 SENT CONTROL [deb10]: 'PUSH_REPLY,route-gateway 10.13.16.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.13.16.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,key-derivation tls-ekm' (status=1)
2021-06-15 12:52:01 us=497217 deb10/10.10.201.210:1194 TLS: new session incoming connection from [AF_INET]10.10.201.210:1194
2021-06-15 12:52:01 us=512489 deb10/10.10.201.210:1194 VERIFY OK: depth=1, CN=EasyTLS-v22-wiscii-CA
2021-06-15 12:52:01 us=513027 deb10/10.10.201.210:1194 VERIFY OK: depth=0, CN=deb10
2021-06-15 12:52:01 us=513882 deb10/10.10.201.210:1194 peer info: IV_VER=2.6_git
2021-06-15 12:52:01 us=514234 deb10/10.10.201.210:1194 peer info: IV_PLAT=linux
2021-06-15 12:52:01 us=514919 deb10/10.10.201.210:1194 peer info: IV_NCP=2
2021-06-15 12:52:01 us=515430 deb10/10.10.201.210:1194 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM
2021-06-15 12:52:01 us=515748 deb10/10.10.201.210:1194 peer info: IV_PROTO=30
2021-06-15 12:52:01 us=516467 deb10/10.10.201.210:1194 peer info: IV_LZ4=1
2021-06-15 12:52:01 us=516818 deb10/10.10.201.210:1194 peer info: IV_LZ4v2=1
2021-06-15 12:52:01 us=517088 deb10/10.10.201.210:1194 peer info: IV_LZO=1
2021-06-15 12:52:01 us=517507 deb10/10.10.201.210:1194 peer info: IV_COMP_STUB=1
2021-06-15 12:52:01 us=517898 deb10/10.10.201.210:1194 peer info: IV_COMP_STUBv2=1
2021-06-15 12:52:01 us=518234 deb10/10.10.201.210:1194 peer info: IV_TCPNL=1
2021-06-15 12:52:01 us=518709 deb10/10.10.201.210:1194 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-06-15 12:52:01 us=519071 deb10/10.10.201.210:1194 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-06-15 12:52:01 us=519339 deb10/10.10.201.210:1194 TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
2021-06-15 12:52:01 us=520310 deb10/10.10.201.210:1194 TLS: tls_multi_process: untrusted session promoted to trusted
2021-06-15 12:52:01 us=521699 deb10/10.10.201.210:1194 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
2021-06-15 12:52:02 us=551518 deb10/10.10.201.210:1194 PUSH: Received control message: 'PUSH_REQUEST'
2021-06-15 12:52:07 us=588009 deb10/10.10.201.210:1194 PUSH: Received control message: 'PUSH_REQUEST'
2021-06-15 12:52:12 us=621897 deb10/10.10.201.210:1194 PUSH: Received control message: 'PUSH_REQUEST'
2021-06-15 12:52:18 us=274134 deb10/10.10.201.210:1194 PUSH: Received control message: 'PUSH_REQUEST'
2021-06-15 12:52:18 us=274295 deb10/10.10.201.210:1194 SENT CONTROL [deb10]: 'PUSH_REPLY,route-gateway 10.13.16.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.13.16.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,key-derivation tls-ekm' (status=1)

Client log after server resumes from sleep, shows TLS keys not initialized and subsequent recovery:

2021-06-15 13:59:53 us=933920 Restart pause, 5 second(s)
2021-06-15 13:59:58 us=934326 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2021-06-15 13:59:58 us=935000 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
2021-06-15 13:59:58 us=935176 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 AF:14/121 ]
2021-06-15 13:59:58 us=935225 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,auth SHA1,keysize 128,key-method 2,tls-client'
2021-06-15 13:59:58 us=935241 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,auth SHA1,keysize 128,key-method 2,tls-server'
2021-06-15 13:59:58 us=935297 TCP/UDP: Preserving recently used remote address: [AF_INET]10.10.201.186:1194
2021-06-15 13:59:58 us=935326 Socket Buffers: R=[212992->212992] S=[212992->212992]
2021-06-15 13:59:58 us=935346 UDP link local (bound): [AF_INET][undef]:1194
2021-06-15 13:59:58 us=935360 UDP link remote: [AF_INET]10.10.201.186:1194
2021-06-15 14:00:28 us=222096 TLS: Initial packet from [AF_INET]10.10.201.186:1194, sid=361cf3d7 76a65c5a
2021-06-15 14:00:28 us=228777 VERIFY OK: depth=1, CN=EasyTLS-v22-wiscii-CA
2021-06-15 14:00:28 us=229436 VERIFY OK: depth=0, CN=wiscii
2021-06-15 14:00:28 us=244892 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
2021-06-15 14:00:28 us=245154 [wiscii] Peer Connection Initiated with [AF_INET]10.10.201.186:1194
2021-06-15 14:00:29 us=272211 SENT CONTROL [wiscii]: 'PUSH_REQUEST' (status=1)
2021-06-15 14:00:34 us=307787 SENT CONTROL [wiscii]: 'PUSH_REQUEST' (status=1)
2021-06-15 14:00:39 us=338058 SENT CONTROL [wiscii]: 'PUSH_REQUEST' (status=1)
2021-06-15 14:00:39 us=726689 Key [AF_INET]10.10.201.186:1194 [0] not initialized (yet), dropping packet.
2021-06-15 14:00:44 us=987892 SENT CONTROL [wiscii]: 'PUSH_REQUEST' (status=1)
2021-06-15 14:00:44 us=990798 PUSH: Received control message: 'PUSH_REPLY,route-gateway 10.13.16.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.13.16.2 255.255.255.0,peer-id 0,cipher AES-256-GCM,key-derivation tls-ekm'
2021-06-15 14:00:44 us=991140 OPTIONS IMPORT: timers and/or timeouts modified
2021-06-15 14:00:44 us=991259 OPTIONS IMPORT: --ifconfig/up options modified
2021-06-15 14:00:44 us=991291 OPTIONS IMPORT: route-related options modified
2021-06-15 14:00:44 us=991314 OPTIONS IMPORT: peer-id set
2021-06-15 14:00:44 us=991338 OPTIONS IMPORT: adjusting link_mtu to 1624
2021-06-15 14:00:44 us=991361 OPTIONS IMPORT: data channel crypto options modified
2021-06-15 14:00:44 us=991389 Data Channel: using negotiated cipher 'AES-256-GCM'
2021-06-15 14:00:44 us=991436 Data Channel MTU parms [ L:1552 D:1450 EF:52 EB:406 ET:0 EL:3 AF:14/121 ]
2021-06-15 14:00:44 us=991589 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-06-15 14:00:44 us=991647 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-06-15 14:00:44 us=995501 TUN/TAP device tun0 opened
2021-06-15 14:00:44 us=995846 do_ifconfig, ipv4=1, ipv6=0
2021-06-15 14:00:44 us=996599 /usr/bin/ip link set dev tun0 up mtu 1500
2021-06-15 14:00:45 us=4102 /usr/bin/ip link set dev tun0 up
2021-06-15 14:00:45 us=8434 /usr/bin/ip addr add dev tun0 10.13.16.2/24
2021-06-15 14:00:45 us=12289 Initialization Sequence Completed

comment:19 Changed 3 years ago by tct

Resolution: fixed
Status: acceptedclosed

I believe I have completely replicated this initial setup (Except for <connection> blocks in the client conf, which don't seem to be relevant here) and the logs show that the problem was instantly resolved by both server and client with minimal noise. I consider this to be fixed, thanks!

Note: See TracTickets for help on using tickets.