VPN Open RoadWarrior - Inactivity timeout (--ping-restart), restarting

ertank · June 24, 2022, 5:31pm

NethServer Version: 7.9.2009
Module: OpenVPN Road Warrior

My internet service provider changed its own internet provider recently. Might be just a coincidence but currently I am blaming them. as after that, I started to have intermittent disconnections to NethServer VPN. Crop log file is as following.

Fri Jun 24 20:05:01 2022 Restart pause, 5 second(s)
Fri Jun 24 20:05:06 2022 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Fri Jun 24 20:05:06 2022 TCP/UDP: Preserving recently used remote address: [AF_INET]x.x.x.x:1194
Fri Jun 24 20:05:06 2022 Socket Buffers: R=[65536->65536] S=[65536->65536]
Fri Jun 24 20:05:06 2022 UDP link local: (not bound)
Fri Jun 24 20:05:06 2022 UDP link remote: [AF_INET]x.x.x.x:1194
Fri Jun 24 20:05:06 2022 MANAGEMENT: >STATE:1656090306,WAIT,,,,,,
Fri Jun 24 20:05:07 2022 MANAGEMENT: >STATE:1656090307,AUTH,,,,,,
Fri Jun 24 20:05:07 2022 TLS: Initial packet from [AF_INET]x.x.x.x:1194, sid=20d2b1fb c6ab967a
Fri Jun 24 20:05:07 2022 VERIFY OK: depth=0, CN=NethServer, O=Example Org, ST=SomeState, OU=Main, emailAddress=root@localhost.localdomain, C=--, L=Hometown
Fri Jun 24 20:05:09 2022 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
Fri Jun 24 20:05:09 2022 [NethServer] Peer Connection Initiated with [AF_INET]x.x.x.x:1194
Fri Jun 24 20:05:10 2022 MANAGEMENT: >STATE:1656090310,GET_CONFIG,,,,,,
Fri Jun 24 20:05:10 2022 SENT CONTROL [NethServer]: 'PUSH_REQUEST' (status=1)
Fri Jun 24 20:05:10 2022 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DOMAIN x.com,dhcp-option DNS 10.11.0.1,dhcp-option WINS 10.11.0.1,dhcp-option NBDD 10.11.0.1,dhcp-option NBT 2,route 192.168.1.0 255.255.255.0,route 10.11.0.1,topology net30,ping 20,ping-restart 120,ifconfig 10.11.0.6 10.11.0.5,peer-id 1,cipher AES-256-GCM'
Fri Jun 24 20:05:10 2022 OPTIONS IMPORT: timers and/or timeouts modified
Fri Jun 24 20:05:10 2022 OPTIONS IMPORT: --ifconfig/up options modified
Fri Jun 24 20:05:10 2022 OPTIONS IMPORT: route options modified
Fri Jun 24 20:05:10 2022 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Fri Jun 24 20:05:10 2022 OPTIONS IMPORT: peer-id set
Fri Jun 24 20:05:10 2022 OPTIONS IMPORT: adjusting link_mtu to 1624
Fri Jun 24 20:05:10 2022 OPTIONS IMPORT: data channel crypto options modified
Fri Jun 24 20:05:10 2022 Data Channel: using negotiated cipher 'AES-256-GCM'
Fri Jun 24 20:05:10 2022 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Fri Jun 24 20:05:10 2022 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Fri Jun 24 20:05:10 2022 Preserving previous TUN/TAP instance: Local Area Connection 3
Fri Jun 24 20:05:10 2022 Initialization Sequence Completed
Fri Jun 24 20:05:10 2022 MANAGEMENT: >STATE:1656090310,CONNECTED,SUCCESS,10.11.0.6,x.x.x.x,1194,,
Fri Jun 24 20:09:16 2022 [NethServer] Inactivity timeout (--ping-restart), restarting
Fri Jun 24 20:09:16 2022 SIGUSR1[soft,ping-restart] received, process restarting
Fri Jun 24 20:09:16 2022 MANAGEMENT: >STATE:1656090556,RECONNECTING,ping-restart,,,,,
Fri Jun 24 20:09:16 2022 Restart pause, 5 second(s)
Fri Jun 24 20:09:21 2022 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Fri Jun 24 20:09:21 2022 TCP/UDP: Preserving recently used remote address: [AF_INET]x.x.x.x:1194
Fri Jun 24 20:09:21 2022 Socket Buffers: R=[65536->65536] S=[65536->65536]
Fri Jun 24 20:09:21 2022 UDP link local: (not bound)
Fri Jun 24 20:09:21 2022 UDP link remote: [AF_INET]x.x.x.x:1194
Fri Jun 24 20:09:21 2022 MANAGEMENT: >STATE:1656090561,WAIT,,,,,,
Fri Jun 24 20:09:21 2022 MANAGEMENT: >STATE:1656090561,AUTH,,,,,,
Fri Jun 24 20:09:21 2022 TLS: Initial packet from [AF_INET]x.x.x.x:1194, sid=a02ee110 774ae084
Fri Jun 24 20:09:21 2022 VERIFY OK: depth=0, CN=NethServer, O=Example Org, ST=SomeState, OU=Main, emailAddress=root@localhost.localdomain, C=--, L=Hometown
Fri Jun 24 20:09:21 2022 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
Fri Jun 24 20:09:21 2022 [NethServer] Peer Connection Initiated with [AF_INET]x.x.x.x:1194
Fri Jun 24 20:09:22 2022 MANAGEMENT: >STATE:1656090562,GET_CONFIG,,,,,,
Fri Jun 24 20:09:22 2022 SENT CONTROL [NethServer]: 'PUSH_REQUEST' (status=1)
Fri Jun 24 20:09:23 2022 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DOMAIN x.com,dhcp-option DNS 10.11.0.1,dhcp-option WINS 10.11.0.1,dhcp-option NBDD 10.11.0.1,dhcp-option NBT 2,route 192.168.1.0 255.255.255.0,route 10.11.0.1,topology net30,ping 20,ping-restart 120,ifconfig 10.11.0.6 10.11.0.5,peer-id 1,cipher AES-256-GCM'
Fri Jun 24 20:09:23 2022 OPTIONS IMPORT: timers and/or timeouts modified
Fri Jun 24 20:09:23 2022 OPTIONS IMPORT: --ifconfig/up options modified
Fri Jun 24 20:09:23 2022 OPTIONS IMPORT: route options modified
Fri Jun 24 20:09:23 2022 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Fri Jun 24 20:09:23 2022 OPTIONS IMPORT: peer-id set
Fri Jun 24 20:09:23 2022 OPTIONS IMPORT: adjusting link_mtu to 1624
Fri Jun 24 20:09:23 2022 OPTIONS IMPORT: data channel crypto options modified
Fri Jun 24 20:09:23 2022 Data Channel: using negotiated cipher 'AES-256-GCM'
Fri Jun 24 20:09:23 2022 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Fri Jun 24 20:09:23 2022 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Fri Jun 24 20:09:23 2022 Preserving previous TUN/TAP instance: Local Area Connection 3
Fri Jun 24 20:09:23 2022 Initialization Sequence Completed
Fri Jun 24 20:09:23 2022 MANAGEMENT: >STATE:1656090563,CONNECTED,SUCCESS,10.11.0.6,x.x.x.x,1194,,
Fri Jun 24 20:13:03 2022 [NethServer] Inactivity timeout (--ping-restart), restarting
Fri Jun 24 20:13:03 2022 SIGUSR1[soft,ping-restart] received, process restarting
Fri Jun 24 20:13:03 2022 MANAGEMENT: >STATE:1656090783,RECONNECTING,ping-restart,,,,,
Fri Jun 24 20:13:03 2022 Restart pause, 5 second(s)
Fri Jun 24 20:13:08 2022 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Fri Jun 24 20:13:08 2022 TCP/UDP: Preserving recently used remote address: [AF_INET]x.x.x.x:1194
Fri Jun 24 20:13:08 2022 Socket Buffers: R=[65536->65536] S=[65536->65536]
Fri Jun 24 20:13:08 2022 UDP link local: (not bound)
Fri Jun 24 20:13:08 2022 UDP link remote: [AF_INET]x.x.x.x:1194
Fri Jun 24 20:13:08 2022 MANAGEMENT: >STATE:1656090788,WAIT,,,,,,
Fri Jun 24 20:13:08 2022 MANAGEMENT: >STATE:1656090788,AUTH,,,,,,
Fri Jun 24 20:13:08 2022 TLS: Initial packet from [AF_INET]x.x.x.x:1194, sid=02a31df9 b5dc30ab
Fri Jun 24 20:13:08 2022 VERIFY OK: depth=0, CN=NethServer, O=Example Org, ST=SomeState, OU=Main, emailAddress=root@localhost.localdomain, C=--, L=Hometown
Fri Jun 24 20:13:09 2022 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
Fri Jun 24 20:13:09 2022 [NethServer] Peer Connection Initiated with [AF_INET]x.x.x.x:1194
Fri Jun 24 20:13:10 2022 MANAGEMENT: >STATE:1656090790,GET_CONFIG,,,,,,
Fri Jun 24 20:13:10 2022 SENT CONTROL [NethServer]: 'PUSH_REQUEST' (status=1)
Fri Jun 24 20:13:10 2022 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DOMAIN x.com,dhcp-option DNS 10.11.0.1,dhcp-option WINS 10.11.0.1,dhcp-option NBDD 10.11.0.1,dhcp-option NBT 2,route 192.168.1.0 255.255.255.0,route 10.11.0.1,topology net30,ping 20,ping-restart 120,ifconfig 10.11.0.6 10.11.0.5,peer-id 1,cipher AES-256-GCM'
Fri Jun 24 20:13:10 2022 OPTIONS IMPORT: timers and/or timeouts modified
Fri Jun 24 20:13:10 2022 OPTIONS IMPORT: --ifconfig/up options modified
Fri Jun 24 20:13:10 2022 OPTIONS IMPORT: route options modified
Fri Jun 24 20:13:10 2022 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Fri Jun 24 20:13:10 2022 OPTIONS IMPORT: peer-id set
Fri Jun 24 20:13:10 2022 OPTIONS IMPORT: adjusting link_mtu to 1624
Fri Jun 24 20:13:10 2022 OPTIONS IMPORT: data channel crypto options modified
Fri Jun 24 20:13:10 2022 Data Channel: using negotiated cipher 'AES-256-GCM'
Fri Jun 24 20:13:10 2022 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Fri Jun 24 20:13:10 2022 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Fri Jun 24 20:13:10 2022 Preserving previous TUN/TAP instance: Local Area Connection 3
Fri Jun 24 20:13:10 2022 Initialization Sequence Completed
Fri Jun 24 20:13:10 2022 MANAGEMENT: >STATE:1656090790,CONNECTED,SUCCESS,10.11.0.6,x.x.x.x,1194,,

I count 16 disconnects in one hour only.

Searching the forum for Inactivity timeout did not provide any meaningful solution. Restart of the system did not help.

Any help is appreciated.

dnutan · June 24, 2022, 6:04pm

If it is of help here is a list with the possible causes of the error (like having two openvpn clients trying to connect with same account, etc.):
https://www.sparklabs.com/support/kb/article/error-inactivity-timeout-ping-restart/

ertank · June 24, 2022, 6:47pm

It turned out that my laptop is using same VPN configuration and it was open after I returned from a business trip. Lucky me, its charge was still fine and it didn’t went to sleep even its setup to hibernate after closing of a lid.

In short, it was my laptop and my desktop racing to get connected to the VPN.

Sorry for the noise.

Thanks for the help.

Regards,
Ertan

Andy_Wismer · June 24, 2022, 6:49pm

Hi

Classic “race condition”…

My 2 cents
Andy

pike · June 24, 2022, 9:25pm

This is why often i go for a “par device” configuration than “par user”.
I have to delete only one user/VPN CFG if something goes wrong.