Upgrade to 2.5 server - Key [AF_INET] [0] not initialized (yet), dropping packet

jstaubr

Hi,

I'm trying to upgrade our OVPN server from 2.3 to 2.5 mainly because I need to have independent ipv6 pool feature (We use ccd with ifconfig push for ipv4).
The thing is - first connection after the server is started is fine and then when I disconnect I just can't reconnect at least for a couple of minutes (seems like 5-10 but I can't be sure - might be inactivity timeout).
All I get in the server log is

2020-11-16 10:21:30 us=737169 jstaubr-7/x.x.x.x:1194 TLS: new session incoming connection from [AF_INET]x.x.x.x:1194
2020-11-16 10:21:30 us=746167 jstaubr-7/x.x.x.x:1194 VERIFY OK: depth=1, XXXXX
2020-11-16 10:21:30 us=746527 jstaubr-7/x.x.x.x:1194 VERIFY OK: depth=0, XXXXX, CN=jstaubr-7
2020-11-16 10:21:30 us=746988 jstaubr-7/x.x.x.x:1194 peer info: IV_VER=2.4.9
2020-11-16 10:21:30 us=747023 jstaubr-7/x.x.x.x:1194 peer info: IV_PLAT=mac
2020-11-16 10:21:30 us=747036 jstaubr-7/x.x.x.x:1194 peer info: IV_PROTO=2
2020-11-16 10:21:30 us=747083 jstaubr-7/x.x.x.x:1194 peer info: IV_NCP=2
2020-11-16 10:21:30 us=747094 jstaubr-7/x.x.x.x:1194 peer info: IV_LZ4=1
2020-11-16 10:21:30 us=747105 jstaubr-7/x.x.x.x:1194 peer info: IV_LZ4v2=1
2020-11-16 10:21:30 us=747122 jstaubr-7/x.x.x.x:1194 peer info: IV_LZO=1
2020-11-16 10:21:30 us=747133 jstaubr-7/x.x.x.x:1194 peer info: IV_COMP_STUB=1
2020-11-16 10:21:30 us=747144 jstaubr-7/x.x.x.x:1194 peer info: IV_COMP_STUBv2=1
2020-11-16 10:21:30 us=747155 jstaubr-7/x.x.x.x:1194 peer info: IV_TCPNL=1
2020-11-16 10:21:30 us=747166 jstaubr-7/x.x.x.x:1194 peer info: IV_GUI_VER=Viscosity_1.9_1556
2020-11-16 10:21:30 us=747219 jstaubr-7/x.x.x.x:1194 TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
2020-11-16 10:21:30 us=747352 jstaubr-7/x.x.x.x:1194 TLS: tls_multi_process: untrusted session promoted to semi-trusted
2020-11-16 10:21:30 us=747947 jstaubr-7/x.x.x.x:1194 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
2020-11-16 10:21:30 us=748126 jstaubr-7/x.x.x.x:1194 PUSH: Received control message: 'PUSH_REQUEST'
2020-11-16 10:21:46 us=359862 jstaubr-7/x.x.x.x:1194 PUSH: Received control message: 'PUSH_REQUEST'
2020-11-16 10:21:46 us=360070 jstaubr-7/x.x.x.x:1194 SENT CONTROL [jstaubr-7]: 'PUSH_REPLY,keysize 256,topology subnet,route-gateway 10.0.224.1,route 10.0.0.0 255.255.0.0,push-continuation 2' (status=1)
2020-11-16 10:21:46 us=360200 jstaubr-7/x.x.x.x:1194 SENT CONTROL [jstaubr-7]: 'PUSH_REPLY,ping 10,ping-restart 120,peer-id 0,cipher AES-256-GCM,push-continuation 1' (status=1)
2020-11-16 10:21:46 us=561728 jstaubr-7/x.x.x.x:1194 Key [AF_INET]x.x.x.x:1194 [0] not initialized (yet), dropping packet.
2020-11-16 10:21:46 us=562125 jstaubr-7/x.x.x.x:1194 Key [AF_INET]x.x.x.x:1194 [0] not initialized (yet), dropping packet.
2020-11-16 10:21:46 us=562189 jstaubr-7/x.x.x.x:1194 Key [AF_INET]x.x.x.x:1194 [0] not initialized (yet), dropping packet.

Client log is clean and thinks the tunnel is up.

Server version is OpenVPN 2.5.0 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Nov 13 2020
Client version is OpenVPN 2.4.9 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [MH/RECVDA] [AEAD] built on Nov 10 2020

dev tun1

local x.x.x.x
port 1193
proto udp

user nobody
group nogroup

topology subnet

client-config-dir /www/increment/www/vpn_sync/ccd

mode server
tls-server
client-to-client

tls-auth /etc/openvpn/new/ta.key

ca /etc/openvpn/new/cacert.pem
cert /etc/openvpn/new/vpn-kancelar-crt.pem
key /etc/openvpn/new/vpn-kancelar-key.pem
dh /etc/openvpn/new/dh2048.pem

tls-version-min 1.0

crl-verify /www/vpn_sync/cacrl.pem

data-ciphers AES-256-GCM:AES-256-CBC
ncp-ciphers AES-256-GCM:AES-256-CBC
data-ciphers-fallback AES-256-CBC

ifconfig 10.0.224.1 255.255.240.0

push "keysize 256"
push "topology subnet"

push "route-gateway 10.0.224.1"
push "route 10.0.0.0 255.255.0.0"

push "dhcp-option DNS 10.0.2.x"
push "dhcp-option DNS 10.0.2.x"
push "dhcp-option DOMAIN xxxx.com"

comp-lzo
persist-tun
persist-key

script-security 2
up "/etc/openvpn/ip-new.up"

status /var/log/openvpn/status-new.log
log-append /var/log/openvpn/openvpn-new.log
verb 4

management x.x.x.x 1184 /etc/openvpn/new/management.passwd

#-- Configuration Generated By Viscosity --#

#viscosity startonopen false
#viscosity protocol openvpn
#viscosity dns automatic
#viscosity usepeerdns true
#viscosity autoreconnect true
#viscosity name "Seznam.cz.dev backup"
#viscosity dhcp true
remote x.x.x.x 1193 udp
dev tun
compress lzo
pull
tls-client
ca ca.crt
cert cert.crt
key key.key
tls-auth ta.key
verb 5
float
tls-cipher TLS-DHE-RSA-WITH-AES-256-CBC-SHA
ns-cert-type server
cipher AES-256-CBC
topology subnet

Any help is appreciated

TinCanTech

Try using --explicit-exit-notify

jstaubr

TinCanTech wrote Try using --explicit-exit-notify

Thank you! That solves a scenario where a client does a deliberate disconnect which is nice.

The other case, where the client loses his network access and is trying to connect again ends in the behaviour described above - client thinks he's online and server just spams the log with "Key [AF_INET] [0] not initialized (yet), dropping packet".
In the latest testing it seems that and inactivity timeout is not applied while this happens.

So the user sees his client connected with nothing wrong in the log, server knows the session is not valid but also keeps the client online and doesn't kill it.

TinCanTech

Your configs do not specify --key-direction, which is required for --tls-auth.

WRT to key initialisation, I have also seen this and there are some outstanding bugs which seem to link to this issue.

jstaubr

TinCanTech wrote Your configs do not specify --key-direction, which is required for --tls-auth.

WRT to key initialisation, I have also seen this and there are some outstanding bugs which seem to link to this issue.

Tried key-direction but it didn't help in this case.
I downgraded to 2.4.7 and it is working now but I have to use a ifconfig-pool to an unused network subnet to enable ipv6.

Anyway thanks for the help!