"Inactivity timeout (--ping-restart), restarting" each 120 secs

[StEwert]

Hello,

I have here an OpenVPN Server with exactly one openVPN client. Each (little bit more as) 120secs the client disconnects because of "Inactivity timeout (--ping-restart), restarting". Seems that the client don't receive any ping messages from the server ("keepalive 10 120"). But why that?

My Server configuration:

View OriginalServer Config

port 1194
proto udp
dev tun

ca /etc/ssl/certs/ca_bis31.11.pem
cert /etc/ssl/certs/openvpn_bis31.04.pem
key /etc/ssl/private/openvpn_bis31.04.pem

dh /etc/openvpn/server/dh4096.pem

server 10.254.254.0 255.255.255.0

ifconfig-pool-persist /var/log/openvpn/ipp.txt

client-config-dir /etc/openvpn/ccd
client-to-client

keepalive 10 120

cipher AES-256-CBC

user openvpn
group openvpn

persist-key
persist-tun

status /var/log/openvpn/openvpn-status.log

log-append /var/log/openvpn/openvpn.log

verb 4

The client configuration is:

View OriginalClient Config

client
dev tun
proto udp
remote myServer.address.de

resolv-retry infinite
nobind

user openvpn
group openvpn

persist-key
persist-tun

ca /etc/ssl/certs/ca_bis31.11.pem
cert /etc/ssl/certs/openvpnExtern_bis3104.pem
key /etc/ssl/private/openvpnExtern_bis3104.pem

cipher AES-256-CBC

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

tun-mtu 1500

Server log (form 17:21:00 until 17:24:00):

View OriginalServer

Thu Apr 15 17:21:28 2021 us=7146 MULTI: multi_create_instance called
Thu Apr 15 17:21:28 2021 us=7185 89.182.31.XXX:51526 Re-using SSL/TLS context
Thu Apr 15 17:21:28 2021 us=7253 89.182.31.XXX:51526 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Apr 15 17:21:28 2021 us=7265 89.182.31.XXX:51526 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Thu Apr 15 17:21:28 2021 us=7299 89.182.31.XXX:51526 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Thu Apr 15 17:21:28 2021 us=7307 89.182.31.XXX:51526 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Thu Apr 15 17:21:28 2021 us=7333 89.182.31.XXX:51526 TLS: Initial packet from [AF_INET]89.182.31.XXX:51526, sid=d0331498 2c8bc2d2
Thu Apr 15 17:21:28 2021 us=177158 89.182.31.XXX:51526 VERIFY OK: depth=1, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin\1B[3~, CN=XXXX, emailAddress=XXXX@XXXX.de
Thu Apr 15 17:21:28 2021 us=177460 89.182.31.XXX:51526 VERIFY OK: depth=0, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin, CN=SerInt1, emailAddress=hostmaster@XXXX.de
Thu Apr 15 17:21:28 2021 us=181565 89.182.31.XXX:51526 peer info: IV_VER=2.4.7
Thu Apr 15 17:21:28 2021 us=181591 89.182.31.XXX:51526 peer info: IV_PLAT=linux
Thu Apr 15 17:21:28 2021 us=181601 89.182.31.XXX:51526 peer info: IV_PROTO=2
Thu Apr 15 17:21:28 2021 us=181610 89.182.31.XXX:51526 peer info: IV_NCP=2
Thu Apr 15 17:21:28 2021 us=181618 89.182.31.XXX:51526 peer info: IV_LZ4=1
Thu Apr 15 17:21:28 2021 us=181626 89.182.31.XXX:51526 peer info: IV_LZ4v2=1
Thu Apr 15 17:21:28 2021 us=181634 89.182.31.XXX:51526 peer info: IV_LZO=1
Thu Apr 15 17:21:28 2021 us=181642 89.182.31.XXX:51526 peer info: IV_COMP_STUB=1
Thu Apr 15 17:21:28 2021 us=181650 89.182.31.XXX:51526 peer info: IV_COMP_STUBv2=1
Thu Apr 15 17:21:28 2021 us=181658 89.182.31.XXX:51526 peer info: IV_TCPNL=1
Thu Apr 15 17:21:28 2021 us=227775 89.182.31.XXX:51526 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 4096 bit RSA
Thu Apr 15 17:21:28 2021 us=227810 89.182.31.XXX:51526 [SerInt1] Peer Connection Initiated with [AF_INET]89.182.31.XXX:51526
Thu Apr 15 17:21:28 2021 us=227911 MULTI: new connection by client 'SerInt1' will cause previous active sessions by this client to be dropped. Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
Thu Apr 15 17:21:28 2021 us=227937 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/ccd/SerInt1
Thu Apr 15 17:21:28 2021 us=228000 MULTI: Learn: 10.254.254.201 -> SerInt1/89.182.31.XXX:51526
Thu Apr 15 17:21:28 2021 us=228012 MULTI: primary virtual IP for SerInt1/89.182.31.XXX:51526: 10.254.254.201
Thu Apr 15 17:21:29 2021 us=409969 SerInt1/89.182.31.XXX:51526 PUSH: Received control message: 'PUSH_REQUEST'
Thu Apr 15 17:21:29 2021 us=410044 SerInt1/89.182.31.XXX:51526 SENT CONTROL [SerInt1]: 'PUSH_REPLY,route 10.254.254.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.254.254.201 255.255.255.255,peer-id 0,cipher AES-256-GCM' (status=1)
Thu Apr 15 17:21:29 2021 us=410057 SerInt1/89.182.31.XXX:51526 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Apr 15 17:21:29 2021 us=410076 SerInt1/89.182.31.XXX:51526 Data Channel MTU parms [ L:1549 D:1450 EF:49 EB:406 ET:0 EL:3 ]
Thu Apr 15 17:21:29 2021 us=410182 SerInt1/89.182.31.XXX:51526 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Apr 15 17:21:29 2021 us=410195 SerInt1/89.182.31.XXX:51526 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Apr 15 17:23:29 2021 us=728985 MULTI: multi_create_instance called
Thu Apr 15 17:23:29 2021 us=729063 89.182.31.XXX:55822 Re-using SSL/TLS context
Thu Apr 15 17:23:29 2021 us=729137 89.182.31.XXX:55822 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Thu Apr 15 17:23:29 2021 us=729149 89.182.31.XXX:55822 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Thu Apr 15 17:23:29 2021 us=729186 89.182.31.XXX:55822 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Thu Apr 15 17:23:29 2021 us=729196 89.182.31.XXX:55822 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Thu Apr 15 17:23:29 2021 us=729220 89.182.31.XXX:55822 TLS: Initial packet from [AF_INET]89.182.31.XXX:55822, sid=f5135abb d928ca8b
Thu Apr 15 17:23:29 2021 us=900350 89.182.31.XXX:55822 VERIFY OK: depth=1, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin\1B[3~, CN=XXXX, emailAddress=XXXX@XXXX.de
Thu Apr 15 17:23:29 2021 us=900672 89.182.31.XXX:55822 VERIFY OK: depth=0, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin, CN=SerInt1, emailAddress=hostmaster@XXXX.de
Thu Apr 15 17:23:29 2021 us=904696 89.182.31.XXX:55822 peer info: IV_VER=2.4.7
Thu Apr 15 17:23:29 2021 us=904722 89.182.31.XXX:55822 peer info: IV_PLAT=linux
Thu Apr 15 17:23:29 2021 us=904732 89.182.31.XXX:55822 peer info: IV_PROTO=2
Thu Apr 15 17:23:29 2021 us=904741 89.182.31.XXX:55822 peer info: IV_NCP=2
Thu Apr 15 17:23:29 2021 us=904749 89.182.31.XXX:55822 peer info: IV_LZ4=1
Thu Apr 15 17:23:29 2021 us=904757 89.182.31.XXX:55822 peer info: IV_LZ4v2=1
Thu Apr 15 17:23:29 2021 us=904765 89.182.31.XXX:55822 peer info: IV_LZO=1
Thu Apr 15 17:23:29 2021 us=904773 89.182.31.XXX:55822 peer info: IV_COMP_STUB=1
Thu Apr 15 17:23:29 2021 us=904781 89.182.31.XXX:55822 peer info: IV_COMP_STUBv2=1
Thu Apr 15 17:23:29 2021 us=904789 89.182.31.XXX:55822 peer info: IV_TCPNL=1
Thu Apr 15 17:23:29 2021 us=951162 89.182.31.XXX:55822 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 4096 bit RSA
Thu Apr 15 17:23:29 2021 us=951199 89.182.31.XXX:55822 [SerInt1] Peer Connection Initiated with [AF_INET]89.182.31.XXX:55822
Thu Apr 15 17:23:29 2021 us=951308 MULTI: new connection by client 'SerInt1' will cause previous active sessions by this client to be dropped. Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
Thu Apr 15 17:23:29 2021 us=951336 OPTIONS IMPORT: reading client specific options from: /etc/openvpn/ccd/SerInt1
Thu Apr 15 17:23:29 2021 us=951400 MULTI: Learn: 10.254.254.201 -> SerInt1/89.182.31.XXX:55822
Thu Apr 15 17:23:29 2021 us=951412 MULTI: primary virtual IP for SerInt1/89.182.31.XXX:55822: 10.254.254.201
Thu Apr 15 17:23:30 2021 us=752560 SerInt1/89.182.31.XXX:55822 PUSH: Received control message: 'PUSH_REQUEST'
Thu Apr 15 17:23:30 2021 us=752607 SerInt1/89.182.31.XXX:55822 SENT CONTROL [SerInt1]: 'PUSH_REPLY,route 10.254.254.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.254.254.201 255.255.255.255,peer-id 1,cipher AES-256-GCM' (status=1)
Thu Apr 15 17:23:30 2021 us=752632 SerInt1/89.182.31.XXX:55822 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Apr 15 17:23:30 2021 us=752650 SerInt1/89.182.31.XXX:55822 Data Channel MTU parms [ L:1549 D:1450 EF:49 EB:406 ET:0 EL:3 ]
Thu Apr 15 17:23:30 2021 us=752737 SerInt1/89.182.31.XXX:55822 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Apr 15 17:23:30 2021 us=752748 SerInt1/89.182.31.XXX:55822 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key

Client log file (form 17:21:00 until 17:24:00):

View OriginalClient

[XXXX.de] Inactivity timeout (--ping-restart), restarting
TCP/UDP: Closing socket
SIGUSR1[soft,ping-restart] received, process restarting
Restart pause, 5 second(s)
WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Re-using SSL/TLS context
Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
TCP/UDP: Preserving recently used remote address: [AF_INET]193.111.199.XXX:1194
Socket Buffers: R=[163840->163840] S=[163840->163840]
UDP link local: (not bound)
UDP link remote: [AF_INET]193.111.199.XXX:1194
TLS: Initial packet from [AF_INET]193.111.199.XXX:1194, sid=e1ed0275 d1e01b55
VERIFY OK: depth=1, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin\1B[3~, CN=XXXX, emailAddress=XXXX@XXXX.de
VERIFY OK: depth=0, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin, CN=XXXX.de, emailAddress=hostmaster@XXXX.de
Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 4096 bit RSA
[XXXX.de] Peer Connection Initiated with [AF_INET]193.111.199.XXX:1194
SENT CONTROL [XXXX.de]: 'PUSH_REQUEST' (status=1)
PUSH: Received control message: 'PUSH_REPLY,route 10.254.254.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.254.254.201 255.255.255.255,peer-id 0,cipher AES-256-GCM'
OPTIONS IMPORT: timers and/or timeouts modified
OPTIONS IMPORT: --ifconfig/up options modified
OPTIONS IMPORT: route options modified
OPTIONS IMPORT: peer-id set
OPTIONS IMPORT: adjusting link_mtu to 1624
OPTIONS IMPORT: data channel crypto options modified
Data Channel: using negotiated cipher 'AES-256-GCM'
Data Channel MTU parms [ L:1552 D:1450 EF:52 EB:406 ET:0 EL:3 ]
Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Preserving previous TUN/TAP instance: tun0
Initialization Sequence Completed
Thu Apr 15 17:23:24 2021 [XXXX.de] Inactivity timeout (--ping-restart), restarting
Thu Apr 15 17:23:24 2021 SIGUSR1[soft,ping-restart] received, process restarting
Thu Apr 15 17:23:24 2021 Restart pause, 5 second(s)
Thu Apr 15 17:23:29 2021 WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Thu Apr 15 17:23:29 2021 TCP/UDP: Preserving recently used remote address: [AF_INET]193.111.199.XXX:1194
Thu Apr 15 17:23:29 2021 Socket Buffers: R=[163840->163840] S=[163840->163840]
Thu Apr 15 17:23:29 2021 UDP link local: (not bound)
Thu Apr 15 17:23:29 2021 UDP link remote: [AF_INET]193.111.199.XXX:1194
Thu Apr 15 17:23:29 2021 TLS: Initial packet from [AF_INET]193.111.199.XXX:1194, sid=0c02947a 8b6c78bc
Thu Apr 15 17:23:29 2021 VERIFY OK: depth=1, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin\1B[3~, CN=XXXX, emailAddress=XXXX@XXXX.de
Thu Apr 15 17:23:29 2021 VERIFY OK: depth=0, C=DE, ST=Niedersachsen, L=XXXX, O=XXXX, OU=Admin, CN=XXXX.de, emailAddress=hostmaster@XXXX.de
Thu Apr 15 17:23:29 2021 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 4096 bit RSA
Thu Apr 15 17:23:29 2021 [XXXX.de] Peer Connection Initiated with [AF_INET]193.111.199.XXX:1194
Thu Apr 15 17:23:30 2021 SENT CONTROL [XXXX.de]: 'PUSH_REQUEST' (status=1)
Thu Apr 15 17:23:30 2021 PUSH: Received control message: 'PUSH_REPLY,route 10.254.254.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 10.254.254.201 255.255.255.255,peer-id 1,cipher AES-256-GCM'
Thu Apr 15 17:23:30 2021 OPTIONS IMPORT: timers and/or timeouts modified
Thu Apr 15 17:23:30 2021 OPTIONS IMPORT: --ifconfig/up options modified
Thu Apr 15 17:23:30 2021 OPTIONS IMPORT: route options modified
Thu Apr 15 17:23:30 2021 OPTIONS IMPORT: peer-id set
Thu Apr 15 17:23:30 2021 OPTIONS IMPORT: adjusting link_mtu to 1624
Thu Apr 15 17:23:30 2021 OPTIONS IMPORT: data channel crypto options modified
Thu Apr 15 17:23:30 2021 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Apr 15 17:23:30 2021 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Apr 15 17:23:30 2021 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Apr 15 17:23:30 2021 Preserving previous TUN/TAP instance: tun1
Thu Apr 15 17:23:30 2021 Initialization Sequence Completed

By the way, this means that I always have a connection between client and server for about 2 minutes (ping from the command line is possible in both directions). The connection is then interrupted for approx. two minutes. Then it goes again for two minutes and so on ...

Where is my mistake?

[TinCanTech]

From your server log:

Thu Apr 15 17:21:28 2021 us=227911 MULTI: new connection by client 'SerInt1' will cause previous active sessions by this client to be dropped. Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.

[StEwert]

Thanks for your reply. But as you can see in my post I have only ONE openVPN client. So I don't know, why this should be a behaviour with the "--duplicate-cn" option.

Strange is, that I get this morning (with the same configuration files like yesterday) two more log output lines on the client side (the both "PID_ERR" lines after "Initialization Sequence Completed"):

View OriginalClient

...
Preserving previous TUN/TAP instance: tun0
Initialization Sequence Completed
PID_ERR replay-window backtrack occurred [1] [SSL-0] [0_0000000000000000000000000000000111] 0:36 0:35 t=1618556753[0] r=[-1,64,15,1,1] sl=[28,36,64,272]
PID_ERR replay-window backtrack occurred [2] [SSL-0] [0__00000001111111111111111111111111111111111111222] 0:50 0:48 t=1618556754[0] r=[-2,64,15,2,1] sl=[14,50,64,272]

If I enable "duplicate-cn" on the server side, then I get on server tons of following outputs:

View OriginalServer

Fri Apr 16 09:16:45 2021 us=238342 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:45 2021 us=614419 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:45 2021 us=615536 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:47 2021 us=246377 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:47 2021 us=254773 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:47 2021 us=408687 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:47 2021 us=662399 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:47 2021 us=664037 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped
Fri Apr 16 09:16:48 2021 us=254849 SerInt1/89.182.146.0:56621 MULTI: bad source address from client [10.254.254.201], packet dropped

In the ccd directory /etc/openvpn/ccd/ I have put the file "SerInt1" with following contents:

View OriginalSerInt1

ifconfig-push 10.254.254.201 255.255.255.255

[StEwert]

May be also interesting the content of "openvpn-status.log":

View Originalopenvpn-status.log

OpenVPN CLIENT LIST
Updated,Fri Apr 16 09:40:02 2021
Common Name,Real Address,Bytes Received,Bytes Sent,Connected Since
SerInt1,89.182.146.0:33204,11093,101984,Fri Apr 16 09:15:07 2021
SerInt1,89.182.146.0:56621,1249417,898709,Fri Apr 16 09:14:10 2021
ROUTING TABLE
Virtual Address,Common Name,Real Address,Last Ref
10.254.254.201,SerInt1,89.182.146.0:33204,Fri Apr 16 09:40:01 2021
GLOBAL STATS
Max bcast/mcast queue length,3
END

[StEwert]

F***ing hell! Found it! The openvpn software was running twice on client side!

As I have installed the client I have create and enable a systemd services so the openvpn client will be start automatically. What I was not known, that this job will be done already by debian ...

Now, after disabling one of the openvpn client services, it works like expected!

Thanks!

[TinCanTech]

Thanks for posting your solution