Random crashes of 2.5.1 server

This forum is for admins who are looking to build or expand their OpenVPN setup.

Moderators: TinCanTech, TinCanTech, TinCanTech, TinCanTech, TinCanTech, TinCanTech

Forum rules
Please use the [oconf] BB tag for openvpn Configurations. See viewtopic.php?f=30&t=21589 for an example.
Post Reply
richard52
OpenVpn Newbie
Posts: 6
Joined: Fri Apr 02, 2021 9:59 am

Random crashes of 2.5.1 server

Post by richard52 » Fri Apr 02, 2021 10:26 am

Hi all,

Im getting a random crashes of openvpn server 2.5.1, usually it crashes with "exited on signal 11" after "WARNING: Bad encapsulated packet length from peer (18245)"
Maybe these things are not related, but after this warning i'm getting "TCP: accept(10) failed: Software caused connection abort (errno=53)" in log and daemon crashes.
Maybe anybody can help me investigate this problem?


My server config and logs below:

/var/log/openvpn.log
2021-04-02 04:58:10 us=734354 MULTI: multi_create_instance called
2021-04-02 04:58:10 us=734404 Re-using SSL/TLS context
2021-04-02 04:58:10 us=734523 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:10 us=734541 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:10 us=734635 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-02 04:58:10 us=734659 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-02 04:58:10 us=734716 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-02 04:58:10 us=734730 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-02 04:58:10 us=734755 TCP connection established with [AF_INET]209.141.56.59:45822
2021-04-02 04:58:10 us=734770 TCPv4_SERVER link local: (not bound)
2021-04-02 04:58:10 us=734784 TCPv4_SERVER link remote: [AF_INET]209.141.56.59:45822
2021-04-02 04:58:10 us=734872 209.141.56.59:45822 WARNING: Bad encapsulated packet length from peer (18245), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...]
2021-04-02 04:58:10 us=734889 209.141.56.59:45822 Connection reset, restarting [0]
2021-04-02 04:58:10 us=734901 209.141.56.59:45822 SIGUSR1[soft,connection-reset] received, client-instance restarting
2021-04-02 04:58:10 us=734951 TCP/UDP: Closing socket
2021-04-02 04:58:11 us=93278 MULTI: multi_create_instance called
2021-04-02 04:58:11 us=93316 Re-using SSL/TLS context
2021-04-02 04:58:11 us=93421 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:11 us=93438 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:11 us=93492 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-02 04:58:11 us=93512 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-02 04:58:11 us=93560 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-02 04:58:11 us=93573 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-02 04:58:11 us=93635 TCP: accept(10) failed: Software caused connection abort (errno=53)
/var/log/messages
Apr 2 04:58:11 vpn-ext kernel: [15774] pid 46022 (openvpn), jid 0, uid 65534: exited on signal 11

openvpn --version
OpenVPN 2.5.1 amd64-portbld-freebsd12.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Feb 26 2021
library versions: OpenSSL 1.1.1h-freebsd 22 Sep 2020, LZO 2.10
Originally developed by James Yonan
Copyright (C) 2002-2018 OpenVPN Inc <sales@openvpn.net>
Compile time defines: enable_async_push=no enable_comp_stub=no enable_crypto_ofb_cfb=yes enable_debug=yes enable_def_auth=yes enable_dlopen=unknown enable_dlopen_self=unknown enable_dlopen_self_static=unknown enable_fast_install=needless enable_fragment=yes enable_iproute2=no enable_libtool_lock=yes enable_lz4=yes enable_lzo=yes enable_management=yes enable_multihome=yes enable_pam_dlopen=no enable_pedantic=no enable_pf=yes enable_pkcs11=no enable_plugin_auth_pam=yes enable_plugin_down_root=yes enable_plugins=yes enable_port_share=yes enable_selinux=no enable_shared=yes enable_shared_with_static_runtimes=no enable_silent_rules=no enable_small=no enable_static=yes enable_strict=yes enable_strict_options=no enable_systemd=no enable_werror=no enable_win32_dll=yes enable_x509_alt_username=no with_aix_soname=aix with_crypto_library=openssl with_gnu_ld=yes with_mem_check=no with_sysroot=no
Server config

management 127.0.0.1 5281
plugin /usr/local/lib/openvpn-auth-ldap.so "/usr/local/etc/openvpn/openvpn-auth-ldap.conf"
port 81
proto tcp4
hand-window 240
dev tun5
topology subnet
verify-client-cert none
ca /usr/local/etc/openvpn/keys/ca.crt
cert /usr/local/etc/openvpn/keys/server.crt
key /usr/local/etc/openvpn/keys/server.key
dh /usr/local/etc/openvpn/keys/dh2048.pem
server 172.16.1.0 255.255.255.0
push "route 192.168.91.0 255.255.255.0"
push "dhcp-option DNS 8.8.8.8"
username-as-common-name
client-config-dir /usr/local/etc/openvpn/rtkct
tls-auth /usr/local/etc/openvpn/keys/ta.key 0
auth SHA256
cipher AES-256-CBC
tcp-queue-limit 4096
bcast-buffers 4096
reneg-sec 36000
reneg-bytes 0
keepalive 10 120
allow-compression no
compress
comp-lzo no
push "comp-lzo no"
max-clients 100
user nobody
group nobody
persist-key
persist-tun
status /var/log/openvpn-status.log
status-version 3
log-append /var/log/openvpn.log
verb 4
script-security 3
sndbuf 512000
rcvbuf 512000
push "sndbuf 512000"
push "rcvbuf 512000"



verb 7 log

Code: Select all

2021-04-02 14:13:54 us=168300 TCP connection established with [AF_INET]209.141.58.91:36152
2021-04-02 14:13:54 us=168317 TCPv4_SERVER link local: (not bound)
2021-04-02 14:13:54 us=168330 TCPv4_SERVER link remote: [AF_INET]209.141.58.91:36152
2021-04-02 14:13:54 us=168353 209.141.58.91:36152 SENT PING
2021-04-02 14:13:54 us=168409 209.141.58.91:36152 MULTI TCP: instance added: 209.141.58.91:36152
2021-04-02 14:13:54 us=168425 209.141.58.91:36152 MULTI TCP: multi_tcp_action a=TA_INITIAL p=0
2021-04-02 14:13:54 us=168436 209.141.58.91:36152 MULTI TCP: multi_tcp_dispatch a=TA_INITIAL mi=0x801601000
2021-04-02 14:13:54 us=168455 209.141.58.91:36152 MULTI TCP: multi_tcp_post TA_INITIAL -> TA_UNDEF
2021-04-02 14:13:54 us=168477 209.141.58.91:36152 MULTI TCP: multi_tcp_action a=TA_SOCKET_READ p=0
2021-04-02 14:13:54 us=168489 209.141.58.91:36152 MULTI TCP: multi_tcp_dispatch a=TA_SOCKET_READ mi=0x801601000
2021-04-02 14:13:54 us=168507 209.141.58.91:36152 WARNING: Bad encapsulated packet length from peer (18245), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...]
2021-04-02 14:13:54 us=168524 209.141.58.91:36152 Connection reset, restarting [0]
2021-04-02 14:13:54 us=168536 209.141.58.91:36152 SIGUSR1[soft,connection-reset] received, client-instance restarting
2021-04-02 14:13:54 us=168547 MULTI: multi_close_instance called
2021-04-02 14:13:54 us=168562 PID packet_id_free
2021-04-02 14:13:54 us=168595 PID packet_id_free
2021-04-02 14:13:54 us=168608 PID packet_id_free
2021-04-02 14:13:54 us=168618 PID packet_id_free
2021-04-02 14:13:54 us=168638 PID packet_id_free
2021-04-02 14:13:54 us=168650 PID packet_id_free
2021-04-02 14:13:54 us=168661 PID packet_id_free
2021-04-02 14:13:54 us=168671 PID packet_id_free
2021-04-02 14:13:54 us=168686 TCP/UDP: Closing socket
2021-04-02 14:13:54 us=168719 PID packet_id_free
2021-04-02 14:13:54 us=168739 MULTI TCP: multi_tcp_post TA_SOCKET_READ -> TA_UNDEF
2021-04-02 14:13:54 us=365785 MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
2021-04-02 14:13:54 us=365806 MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
2021-04-02 14:13:54 us=365822 MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
2021-04-02 14:13:54 us=492710 MULTI TCP: multi_tcp_action a=TA_SOCKET_READ p=0
2021-04-02 14:13:54 us=492730 MULTI TCP: multi_tcp_dispatch a=TA_SOCKET_READ mi=0x8013c9400
2021-04-02 14:13:54 us=492754 av_andreev/37.145.211.176:25906 TCPv4_SERVER READ [77] from [AF_INET]37.145.211.176:25906: P_DATA_V2 kid=1 DATA len=76
2021-04-02 14:13:54 us=492769 av_andreev/37.145.211.176:25906 TLS: tls_pre_decrypt, key_id=1, IP=[AF_INET]37.145.211.176:25906
2021-04-02 14:13:54 us=492807 av_andreev/37.145.211.176:25906 PID_TEST [0] [SSL-1] [369>>>EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE] 0:3231 0:3232 t=1617362034[0] r=[-3,64,15,0,1] sl=[33,64,64,528]
2021-04-02 14:13:54 us=492828 av_andreev/37.145.211.176:25906 GET INST BY VIRT: 172.16.1.4 -> test_username/37.145.211.176:25906 via 172.16.1.4
2021-04-02 14:13:54 us=492842 MULTI TCP: multi_tcp_post TA_SOCKET_READ -> TA_TUN_WRITE
2021-04-02 14:13:54 us=492853 MULTI TCP: multi_tcp_action a=TA_TUN_WRITE p=1
2021-04-02 14:13:54 us=492864 MULTI TCP: multi_tcp_wait_lite a=TA_TUN_WRITE mi=0x8013c9400
2021-04-02 14:13:54 us=492880 MULTI TCP: multi_tcp_dispatch a=TA_TUN_WRITE mi=0x8013c9400
2021-04-02 14:13:54 us=492892 av_andreev/37.145.211.176:25906 TUN WRITE [52]
2021-04-02 14:13:54 us=492919 MULTI TCP: multi_tcp_post TA_TUN_WRITE -> TA_UNDEF
2021-04-02 14:13:54 us=536581 MULTI: multi_create_instance called
2021-04-02 14:13:54 us=536617 Re-using SSL/TLS context
2021-04-02 14:13:54 us=536722 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 14:13:54 us=536745 Outgoing Control Channel Authentication: HMAC KEY: d500140d c19a3615 e47d1de9 cba9620f 67661d23 e664754f 83dd742f b5fd7793
2021-04-02 14:13:54 us=536757 Outgoing Control Channel Authentication: HMAC size=32 block_size=32
2021-04-02 14:13:54 us=536772 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 14:13:54 us=536794 Incoming Control Channel Authentication: HMAC KEY: 2f846a76 7f8ef2b5 a5791ea5 1fbf687c 741b78d9 8fd03dc2 7a681db3 8b9650e9
2021-04-02 14:13:54 us=536805 Incoming Control Channel Authentication: HMAC size=32 block_size=32
2021-04-02 14:13:54 us=536820 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 40 bytes
2021-04-02 14:13:54 us=536836 PID packet_id_init seq_backtrack=64 time_backtrack=15
2021-04-02 14:13:54 us=536867 PID packet_id_init seq_backtrack=64 time_backtrack=15
2021-04-02 14:13:54 us=536883 PID packet_id_init seq_backtrack=64 time_backtrack=15
2021-04-02 14:13:54 us=536908 PID packet_id_init seq_backtrack=64 time_backtrack=15
2021-04-02 14:13:54 us=536924 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-02 14:13:54 us=536939 MTU DYNAMIC mtu=1450, flags=2, 1624 -> 1450
2021-04-02 14:13:54 us=536953 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-02 14:13:54 us=536974 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 68 bytes
2021-04-02 14:13:54 us=536985 calc_options_string_link_mtu: link-mtu 1624 -> 1572
2021-04-02 14:13:54 us=537017 crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 68 bytes
2021-04-02 14:13:54 us=537029 calc_options_string_link_mtu: link-mtu 1624 -> 1572
2021-04-02 14:13:54 us=537053 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-02 14:13:54 us=537066 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-02 14:13:54 us=537110 TCP: accept(7) failed: Software caused connection abort (errno=53)

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Fri Apr 02, 2021 12:35 pm

This is likely to be related to recent development concerning compression.

A new release 2.5.2 is scheduled for next week or so, so you can wait for that.

However, you must actually ensure that your client config file specifies --comp-lzo no as well ..
because pushing it only is simply not enough, currently.

richard52
OpenVpn Newbie
Posts: 6
Joined: Fri Apr 02, 2021 9:59 am

Re: Random crashes of 2.5.1 server

Post by richard52 » Mon Apr 05, 2021 11:22 am

Thank you for asnwer.
Is this problem exists on version 2.4.10?
I can not remove comp-lzo from all clients, im having too many clients.

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Mon Apr 05, 2021 2:44 pm

Please post the client config files as well.

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Mon Apr 05, 2021 9:19 pm

For help with your server crashing, please post a log at --verb 4 when the server crashes.

richard52
OpenVpn Newbie
Posts: 6
Joined: Fri Apr 02, 2021 9:59 am

Re: Random crashes of 2.5.1 server

Post by richard52 » Tue Apr 06, 2021 8:10 am

client
topology subnet
auth-user-pass
dev tun
proto tcp
remote vpn.somedomain.external
port 81
client
nobind
resolv-retry infinite
auth SHA256
cipher AES-256-CBC
remote-cert-tls server
comp-lzo
persist-key
persist-tun
verb 3
key-direction 1
<tls-auth>
-----BEGIN OpenVPN Static key V1-----
-----END OpenVPN Static key V1-----
</tls-auth>
<ca>
-----BEGIN CERTIFICATE-----
-----END CERTIFICATE-----
</ca>



Verb 4 log

Code: Select all

2021-04-02 04:58:10 us=734354 MULTI: multi_create_instance called
2021-04-02 04:58:10 us=734404 Re-using SSL/TLS context
2021-04-02 04:58:10 us=734523 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:10 us=734541 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:10 us=734635 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-02 04:58:10 us=734659 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-02 04:58:10 us=734716 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-02 04:58:10 us=734730 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-02 04:58:10 us=734755 TCP connection established with [AF_INET]209.141.56.59:45822
2021-04-02 04:58:10 us=734770 TCPv4_SERVER link local: (not bound)
2021-04-02 04:58:10 us=734784 TCPv4_SERVER link remote: [AF_INET]209.141.56.59:45822
2021-04-02 04:58:10 us=734872 209.141.56.59:45822 WARNING: Bad encapsulated packet length from peer (18245), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...]
2021-04-02 04:58:10 us=734889 209.141.56.59:45822 Connection reset, restarting [0]
2021-04-02 04:58:10 us=734901 209.141.56.59:45822 SIGUSR1[soft,connection-reset] received, client-instance restarting
2021-04-02 04:58:10 us=734951 TCP/UDP: Closing socket
2021-04-02 04:58:11 us=93278 MULTI: multi_create_instance called
2021-04-02 04:58:11 us=93316 Re-using SSL/TLS context
2021-04-02 04:58:11 us=93421 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:11 us=93438 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-02 04:58:11 us=93492 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-02 04:58:11 us=93512 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-02 04:58:11 us=93560 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-02 04:58:11 us=93573 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-02 04:58:11 us=93635 TCP: accept(10) failed: Software caused connection abort (errno=53)

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Tue Apr 06, 2021 1:31 pm

Because you have only posted a snippet of your log it is hard to say.
But that does not look like your server crashed, it simply dropped the connection.

richard52
OpenVpn Newbie
Posts: 6
Joined: Fri Apr 02, 2021 9:59 am

Re: Random crashes of 2.5.1 server

Post by richard52 » Wed Apr 07, 2021 12:59 pm

TinCanTech wrote:
Tue Apr 06, 2021 1:31 pm
Because you have only posted a snippet of your log it is hard to say.
But that does not look like your server crashed, it simply dropped the connection.
No, that not a snippet, that's end of the log. At same time i got at /var/log/messages that log message:

Code: Select all

Apr  7 15:08:16 vpn-ext kernel: [484379] pid 55980 (openvpn), jid 0, uid 65534: exited on signal 11
Apr  7 15:08:16 vpn-ext kernel: [484379] tun5: link state changed to DOWN
And this openvpn verb 4 log:

Code: Select all

2021-04-07 15:08:15 us=880177 MULTI: multi_create_instance called
2021-04-07 15:08:15 us=880227 Re-using SSL/TLS context
2021-04-07 15:08:15 us=880336 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-07 15:08:15 us=880355 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-07 15:08:15 us=880417 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-07 15:08:15 us=880439 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-07 15:08:15 us=880490 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-07 15:08:15 us=880504 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-07 15:08:15 us=880534 TCP connection established with [AF_INET]209.141.58.91:50552
2021-04-07 15:08:15 us=880557 TCPv4_SERVER link local: (not bound)
2021-04-07 15:08:15 us=880572 TCPv4_SERVER link remote: [AF_INET]209.141.58.91:50552
2021-04-07 15:08:15 us=880659 209.141.58.91:50552 WARNING: Bad encapsulated packet length from peer (18245), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...]
2021-04-07 15:08:15 us=880677 209.141.58.91:50552 Connection reset, restarting [0]
2021-04-07 15:08:15 us=880690 209.141.58.91:50552 SIGUSR1[soft,connection-reset] received, client-instance restarting
2021-04-07 15:08:15 us=880736 TCP/UDP: Closing socket
2021-04-07 15:08:16 us=238761 MULTI: multi_create_instance called
2021-04-07 15:08:16 us=238804 Re-using SSL/TLS context
2021-04-07 15:08:16 us=238910 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-07 15:08:16 us=238927 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-07 15:08:16 us=238980 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-07 15:08:16 us=239001 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-07 15:08:16 us=239051 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-07 15:08:16 us=239065 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-07 15:08:16 us=239119 TCP: accept(7) failed: Software caused connection abort (errno=53)

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Wed Apr 07, 2021 1:25 pm

richard52 wrote:
Fri Apr 02, 2021 10:26 am
OpenVPN 2.5.1 amd64-portbld-freebsd12.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Feb 26 2021
library versions: OpenSSL 1.1.1h-freebsd 22 Sep 2020, LZO 2.10
Is this an official version for FreeBSD12.2 or did you build it yourself ?

Also, please post your client log at --verb 4 at the time the server crashes.

cron2
Developer
Posts: 24
Joined: Tue Jan 12, 2010 8:08 pm

Re: Random crashes of 2.5.1 server

Post by cron2 » Wed Apr 07, 2021 4:09 pm

I do not think this is related to compression at all.

This looks like a timing issue with TCP connections being reset at an "untimely moment", as in "we're halfway through the TLS handshake, then the session is reset, and at cleanup, we try to clean up something that is not properly initialized yet" - or possibly something with "bad data is injected in the TCP stream", but OpenVPN is normally very careful about handling of network data.

If this can be reproduced more easily, it would be great to run openvpn in a debugger, as in

# gdb /usr/local/sbin/openvpn
(gdb) run --config /path/to/config.ovpn

and when it crashes, it will return to the GDB prompt. Then run

(gdb) where

and post the result.

Alternatively, if you can describe how to reproduce this at will, we can try to reproduce this on our FreeBSD systems.

(And no, there is nothing in 2.5.2 which would fix a SIGSEGV crash)

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Wed Apr 07, 2021 6:38 pm

I notice from your three server logs that there are only two unique client IP addresses.
Do you know which client causes the crash or is it also random clients ?

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Thu Apr 08, 2021 2:49 pm

You have this version:
  • OpenVPN 2.5.1 amd64-portbld-freebsd12.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Feb 26 2021
    library versions: OpenSSL 1.1.1h-freebsd 22 Sep 2020, LZO 2.10
I get this version from ports:
  • OpenVPN 2.5.1 amd64-portbld-freebsd12.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Mar 28 2021
    library versions: OpenSSL 1.1.1h-freebsd 22 Sep 2020, LZO 2.10
Try updating and let us know if the problem persists.

richard52
OpenVpn Newbie
Posts: 6
Joined: Fri Apr 02, 2021 9:59 am

Re: Random crashes of 2.5.1 server

Post by richard52 » Tue Apr 13, 2021 10:16 am

TinCanTech wrote:
Wed Apr 07, 2021 6:38 pm
I notice from your three server logs that there are only two unique client IP addresses.
Do you know which client causes the crash or is it also random clients ?
I think this not a clients, thats random connections, such as portscanners or something similar.

Normal user session looks like this:
2021-04-13 12:05:52 us=365085 46.xx.xx.90:55605 TLS: Initial packet from [AF_INET]46.xx.xx.90:55605, sid=166064ad 5d3793ac
2021-04-13 12:05:52 us=485545 46.xx.xx.90:55605 peer info: IV_VER=2.5_rc1
2021-04-13 12:05:52 us=485567 46.xx.xx.90:55605 peer info: IV_PLAT=win
2021-04-13 12:05:52 us=485581 46.xx.xx.90:55605 peer info: IV_PROTO=6
2021-04-13 12:05:52 us=485594 46.xx.xx.90:55605 peer info: IV_NCP=2
2021-04-13 12:05:52 us=485607 46.xx.xx.90:55605 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:AES-256-CBC
2021-04-13 12:05:52 us=485620 46.xx.xx.90:55605 peer info: IV_LZ4=1
2021-04-13 12:05:52 us=485633 46.xx.xx.90:55605 peer info: IV_LZ4v2=1
2021-04-13 12:05:52 us=485645 46.xx.xx.90:55605 peer info: IV_LZO=1
2021-04-13 12:05:52 us=485658 46.xx.xx.90:55605 peer info: IV_COMP_STUB=1
2021-04-13 12:05:52 us=485670 46.xx.xx.90:55605 peer info: IV_COMP_STUBv2=1
2021-04-13 12:05:52 us=485683 46.xx.xx.90:55605 peer info: IV_TCPNL=1
2021-04-13 12:05:52 us=485696 46.xx.xx.90:55605 peer info: IV_GUI_VER=OpenVPN_GUI_11
2021-04-13 12:05:52 us=511116 46.xx.xx.90:55605 PLUGIN_CALL: POST /usr/local/lib/openvpn-auth-ldap.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
2021-04-13 12:05:52 us=511185 46.xx.xx.90:55605 TLS: Username/Password authentication succeeded for username 'valid.user.name' [CN SET]
2021-04-13 12:05:52 us=567985 46.xx.xx.90:55605 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384
2021-04-13 12:05:52 us=568019 46.xx.xx.90:55605 [valid.user.name] Peer Connection Initiated with [AF_INET]46.xx.xx.90:55605
2021-04-13 12:05:52 us=568060 valid.user.name/46.xx.xx.90:55605 MULTI_sva: pool returned IPv4=172.16.1.2, IPv6=(Not enabled)
2021-04-13 12:05:52 us=568132 valid.user.name/46.xx.xx.90:55605 OPTIONS IMPORT: reading client specific options from: /usr/local/etc/openvpn/rtkct/valid.user.name
2021-04-13 12:05:52 us=586275 valid.user.name/46.xx.xx.90:55605 PLUGIN_CALL: POST /usr/local/lib/openvpn-auth-ldap.so/PLUGIN_CLIENT_CONNECT status=0
2021-04-13 12:05:52 us=586340 valid.user.name/46.xx.xx.90:55605 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_3398db5b1fb7956814534c2ea39ff84c.tmp
2021-04-13 12:05:52 us=678964 valid.user.name/46.xx.xx.90:55605 OPTIONS IMPORT: reading client specific options from: /tmp/openvpn_cc_165f8d8711b40ead7451be5f8bdda992.tmp
2021-04-13 12:05:52 us=679142 valid.user.name/46.xx.xx.90:55605 MULTI: Learn: 172.16.1.6 -> valid.user.name/46.xx.xx.90:55605
2021-04-13 12:05:52 us=679167 valid.user.name/46.xx.xx.90:55605 MULTI: primary virtual IP for valid.user.name/46.xx.xx.90:55605: 172.16.1.6
2021-04-13 12:05:52 us=679209 valid.user.name/46.xx.xx.90:55605 Data Channel: using negotiated cipher 'AES-256-GCM'
2021-04-13 12:05:52 us=679242 valid.user.name/46.xx.xx.90:55605 Data Channel MTU parms [ L:1552 D:1450 EF:52 EB:406 ET:0 EL:3 ]
2021-04-13 12:05:52 us=679396 valid.user.name/46.xx.xx.90:55605 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-04-13 12:05:52 us=679422 valid.user.name/46.xx.xx.90:55605 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-04-13 12:05:52 us=679532 valid.user.name/46.xx.xx.90:55605 SENT CONTROL [valid.user.name]: 'PUSH_REPLY,route 192.168.91.0 255.255.255.0,route 10.22.0.121 255.255.255.255,dhcp-option DNS 8.8.8.8,comp-lzo no,sndbuf 512000,rcvbuf 512000,route-gateway 172.16.1.1,topology subnet,ping 10,ping-restart 120,ifconfig 172.16.1.6 255.255.255.0,peer-id 0,cipher AES-256-GCM' (status=1)
2021-04-13 13:05:52 us=817918 valid.user.name/46.xx.xx.90:55605 peer info: IV_VER=2.5_rc1
2021-04-13 13:05:52 us=817944 valid.user.name/46.xx.xx.90:55605 peer info: IV_PLAT=win
2021-04-13 13:05:52 us=817958 valid.user.name/46.xx.xx.90:55605 peer info: IV_PROTO=6
2021-04-13 13:05:52 us=817972 valid.user.name/46.xx.xx.90:55605 peer info: IV_NCP=2
2021-04-13 13:05:52 us=817986 valid.user.name/46.xx.xx.90:55605 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:AES-256-CBC
2021-04-13 13:05:52 us=817999 valid.user.name/46.xx.xx.90:55605 peer info: IV_LZ4=1
2021-04-13 13:05:52 us=818012 valid.user.name/46.xx.xx.90:55605 peer info: IV_LZ4v2=1
2021-04-13 13:05:52 us=818025 valid.user.name/46.xx.xx.90:55605 peer info: IV_LZO=1
2021-04-13 13:05:52 us=818038 valid.user.name/46.xx.xx.90:55605 peer info: IV_COMP_STUB=1
2021-04-13 13:05:52 us=818051 valid.user.name/46.xx.xx.90:55605 peer info: IV_COMP_STUBv2=1
2021-04-13 13:05:52 us=818064 valid.user.name/46.xx.xx.90:55605 peer info: IV_TCPNL=1
2021-04-13 13:05:52 us=818078 valid.user.name/46.xx.xx.90:55605 peer info: IV_GUI_VER=OpenVPN_GUI_11
2021-04-13 13:05:52 us=858124 valid.user.name/46.xx.xx.90:55605 PLUGIN_CALL: POST /usr/local/lib/openvpn-auth-ldap.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
2021-04-13 13:05:52 us=858184 valid.user.name/46.xx.xx.90:55605 TLS: Username/Password authentication succeeded for username 'valid.user.name' [CN SET]
2021-04-13 13:05:52 us=858383 valid.user.name/46.xx.xx.90:55605 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-04-13 13:05:52 us=858409 valid.user.name/46.xx.xx.90:55605 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2021-04-13 13:05:52 us=879895 valid.user.name/46.xx.xx.90:55605 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384
Update to
  • OpenVPN 2.5.1 amd64-portbld-freebsd12.2 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Mar 28 2021
    library versions: OpenSSL 1.1.1h-freebsd 22 Sep 2020, LZO 2.10
same problem:

12:05:43 - server crashed
2021-04-13 12:05:42 us=982773 MULTI: multi_create_instance called
2021-04-13 12:05:42 us=982834 Re-using SSL/TLS context
2021-04-13 12:05:42 us=982955 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-13 12:05:42 us=982974 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-13 12:05:42 us=983064 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-13 12:05:42 us=983089 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-13 12:05:42 us=983149 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-13 12:05:42 us=983163 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-13 12:05:42 us=983197 TCP connection established with [AF_INET]209.141.49.19:44506
2021-04-13 12:05:42 us=983213 TCPv4_SERVER link local: (not bound)
2021-04-13 12:05:42 us=983228 TCPv4_SERVER link remote: [AF_INET]209.141.49.19:44506
2021-04-13 12:05:42 us=983316 209.141.49.19:44506 WARNING: Bad encapsulated packet length from peer (18245), which must be > 0 and <= 1627 -- please ensure that --tun-mtu or --link-mtu is equal on both peers -- this condition could also indicate a possible active attack on the TCP link -- [Attempting restart...]
2021-04-13 12:05:42 us=983333 209.141.49.19:44506 Connection reset, restarting [0]
2021-04-13 12:05:42 us=983346 209.141.49.19:44506 SIGUSR1[soft,connection-reset] received, client-instance restarting
2021-04-13 12:05:42 us=983396 TCP/UDP: Closing socket
2021-04-13 12:05:43 us=343818 MULTI: multi_create_instance called
2021-04-13 12:05:43 us=343860 Re-using SSL/TLS context
2021-04-13 12:05:43 us=343965 Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-13 12:05:43 us=343982 Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
2021-04-13 12:05:43 us=344036 Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]
2021-04-13 12:05:43 us=344057 Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
2021-04-13 12:05:43 us=344106 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-server'
2021-04-13 12:05:43 us=344119 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA256,keysize 256,tls-auth,key-method 2,tls-client'
2021-04-13 12:05:43 us=344181 TCP: accept(7) failed: Software caused connection abort (errno=53)
/var/log/messages
Apr 13 12:05:43 vpn-ext kernel: [991826] pid 90803 (openvpn), jid 0, uid 65534: exited on signal 11
Apr 13 12:05:43 vpn-ext kernel: [991826] tun5: link state changed to DOWN

Servers on UDP port with disabled compression works stable.

TinCanTech
OpenVPN Protagonist
Posts: 11137
Joined: Fri Jun 03, 2016 1:17 pm

Re: Random crashes of 2.5.1 server

Post by TinCanTech » Tue Apr 13, 2021 2:58 pm

richard52 wrote:
Tue Apr 13, 2021 10:16 am
12:05:43 - server crashed
cron2 wrote:
Wed Apr 07, 2021 4:09 pm
run openvpn in a debugger, as in

# gdb /usr/local/sbin/openvpn
(gdb) run --config /path/to/config.ovpn

and when it crashes, it will return to the GDB prompt. Then run

(gdb) where

and post the result.
We cannot replicate this so you'll have to do the steps above.

richard52
OpenVpn Newbie
Posts: 6
Joined: Fri Apr 02, 2021 9:59 am

Re: Random crashes of 2.5.1 server

Post by richard52 » Thu Apr 15, 2021 7:23 am

Thank you for your help, now i know where problem is.
I will write on github to author of openvpn-auth-ldap module or use previous version of module (not from freebsd packages)

Code: Select all

(gdb) run --config /usr/local/etc/openvpn/server.conf
Starting program: /usr/local/sbin/openvpn --config /usr/local/etc/openvpn/server.conf
[Detaching after fork from child process 51709]
[Detaching after fork from child process 52064]
[Detaching after fork from child process 57053]
[Detaching after fork from child process 57815]
[Detaching after fork from child process 80102]
[Detaching after fork from child process 80645]
[Detaching after fork from child process 81999]
[Detaching after fork from child process 46007]
[Detaching after fork from child process 51107]
[Detaching after fork from child process 77250]
[Detaching after fork from child process 78044]

Program received signal SIGSEGV, Segmentation fault.
0x000000080089da2f in strlen () from /lib/libc.so.7
(gdb) where
#0  0x000000080089da2f in strlen () from /lib/libc.so.7
#1  0x0000000801246114 in ?? () from /usr/local/lib/openvpn-auth-ldap.so
#2  0x000000080123806f in openvpn_plugin_func_v1 () from /usr/local/lib/openvpn-auth-ldap.so
#3  0x0000000000289812 in ?? ()
#4  0x0000000000266e1a in ?? ()
#5  0x0000000000266c6f in ?? ()
#6  0x0000000000267200 in ?? ()
#7  0x0000000000264793 in ?? ()
#8  0x000000000026f158 in ?? ()
#9  0x000000000023dee0 in ?? ()
#10 0x00000008002df000 in ?? ()
#11 0x0000000000000000 in ?? ()

Post Reply