Two issues when reconnecting with 2.4.1

[sbehrens]

Theses two issues happen only sometimes. The full server log is attached. Both issues might be related?

Issue # 1:
extra_frame is -72 larger after each connection attempt and after a few times packets are discarded with "TCP/UDP packet too large on write".

Some of the lines of the server log file:

MULTI: multi_create_instance called
Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
TLS: Username/Password authentication succeeded for username 'foo' [CN SET]
Data Channel MTU parms [ L:1549 D:1450 EF:49 EB:406 ET:0 EL:3 ]
TLS: Username/Password authentication succeeded for username 'foo' [CN SET]
Data Channel MTU parms [ L:1477 D:1450 EF:-23 EB:406 ET:0 EL:3 ]
TLS: Username/Password authentication succeeded for username 'foo' [CN SET]
Data Channel MTU parms [ L:1405 D:1405 EF:-95 EB:406 ET:0 EL:3 ]
TLS: Username/Password authentication succeeded for username 'foo' [CN SET]
Data Channel MTU parms [ L:1333 D:1333 EF:-167 EB:406 ET:0 EL:3 ]
TCP/UDP packet too large on write to [AF_INET]1.2.3.4:1194 (tried=1419,max=1333)

(A small ping still works.)

Issue # 2:
Sometimes the PUSH_REPLY does not include the "cipher AES-256-GCM" which would switch the client away from the default BF-CBC to AES-256-GCM. Client and server use mismatching ciphers afterwards.

When tls_session_generate_data_channel_keys() is called via tls_session_update_crypto_params() (which also adds the -72 bytes to extra_frame and dumps the "Data Channel MTU parms") the client and server both use the same cipher AES-256-GCM, but sometimes key_method_2_write() or key_method_2_read() seem to be the one who call tls_session_generate_data_channel_keys() and then the server uses AES-256-GCM but the client uses BF-CBC.

Example for when client + server both establish AES-256-GCM:

TLS: Username/Password authentication succeeded for username 'foo' [CN SET]
TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
TLS: tls_multi_process: untrusted session promoted to semi-trusted
Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
PUSH: Received control message: 'PUSH_REQUEST'
SENT CONTROL [foo]: 'PUSH_REPLY,ping 45,route 3.2.1.69,route 3.2.1.72,route 3.2.1.44,route 10.144.0.1,topology net30,ifconfig 10.144.0.6 10.144.0.5,peer-id 0,cipher AES-256-GCM' (status=1)
Data Channel MTU parms [ L:1333 D:1333 EF:-167 EB:406 ET:0 EL:3 ]
Data Channel Encrypt: Cipher 'AES-256-GCM' initialized with 256 bit key
Data Channel Decrypt: Cipher 'AES-256-GCM' initialized with 256 bit key

Example for when client uses BF-CBC but server uses AES-256-GCM:

TLS: Username/Password authentication succeeded for username 'foo' [CN SET]
Data Channel Encrypt: Cipher 'AES-256-GCM' initialized with 256 bit key
Data Channel Decrypt: Cipher 'AES-256-GCM' initialized with 256 bit key
TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
TLS: tls_multi_process: untrusted session promoted to semi-trusted
Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
PUSH: Received control message: 'PUSH_REQUEST'
PUSH: client wants to negotiate cipher (NCP), but server has already generated data channel keys, ignoring client request
SENT CONTROL [foo]: 'PUSH_REPLY,ping 45,route 3.2.1.69,route 3.2.1.72,route 3.2.1.44,route 10.144.0.1,topology net30,ifconfig 10.144.0.6 10.144.0.5,peer-id 0' (status=1)
AEAD Decrypt error: cipher final failed

[sbehrens]

server log, kill -USR2 output, OS and --version output

[Gert Döring]

@syzzer: this seems to be your ballpark...

@sbehrens: are you doing anything unusal on the server, like, any non-standard options, scripts, plugins?

[sbehrens]

A script to verify the user/password is allowed to log in. The config looks normal to me. This is the config (with some lines removed which shouldn't matter):
server 10.144.0.0 255.255.0.0
float
duplicate-cn
script-security 3
auth-user-pass-verify auth.pl via-env
up up.sh
verify-client-cert none
username-as-common-name
ca ca.drive....com.crt
cert server.crt
key server.key
dh dh2048.pem
tls-auth tls-auth.key

[sbehrens]

Sorry, after taking a closer look, these two things don't look related anymore. Shall I split this single ticket into two?

The "TCP/UDP packet too large on write" is reproducible just by reconnecting. extra_flags grows by -72 with each new connection and SMB fails to operate after three reconnects.

The second issue looks like being related to the "TLS: soft reset sec=0 bytes=23248/-1 pkts=237/0" thing, when the state is reset. I'm currently running the server with verb=9 and reneg-sec 180 and in fact after the reset, disconnect and reconnect the BF-CBC on the client happens.

[dbussink]

I have hit the same issue with the shrinking MTU sizes. I've sent a patch for it to the mailing list (available also at ​https://sourceforge.net/p/openvpn/mailman/message/35823479/) and also opened a pull request on GitHub? for discussion about the patch: ​https://github.com/OpenVPN/openvpn/pull/87

[Steffan Karger]

Thanks for the clear bug report and the suggested patch. And sorry for taking long to respond, life has been a bit busy...

The analysis makes sense, and logic-wise the resulting patch does too. I'll look into this further soon.

In the mean while, sbehrens, it would be great to hear from you if this patch works properly for you too.

[sbehrens]

This patch does work properly for me and fixes the 1st issue. The client is able to reconnect multiple times. Grepping for 'Data Channel MTU parms' on the server shows "[ L:1549 D:1450 EF:49 EB:406 ET:0 EL:3 ]" all the time. The extra_flags no longer change on a reconnect.

Thanks!

[Steffan Karger]

(Tuned the markup of the description a little.)