Opened 2 months ago

Last modified 2 months ago

#1316 new Bug / Defect

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

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

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 (2)

server-1316.txt (44.7 KB) - added by tincantech 2 months ago.
client-1316.txt (52.9 KB) - added by tincantech 2 months ago.

Download all attachments as: .zip

Change History (11)

comment:1 Changed 2 months ago by tincantech

Cc: tincantech added

comment:2 Changed 2 months ago by tincantech

Cc: Steffan Karger plaisthos Gert Döring Antonio added

comment:3 Changed 2 months ago by plaisthos

Can you add OpenVPN logs for both client and server?

Last edited 2 months ago by plaisthos (previous) (diff)

comment:4 Changed 2 months ago by tincantech

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 2 months ago by tincantech

Attachment: server-1316.txt added

Changed 2 months ago by tincantech

Attachment: client-1316.txt added

comment:5 Changed 2 months ago by tincantech

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 2 months ago by tincantech

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 2 months ago by tincantech

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 2 months ago by tincantech

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 2 months ago by tincantech

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.

Note: See TracTickets for help on using tickets.