Inactivity timeout (--ping-restart), restarting

chrisalau32

I would like to apologize in advance because I am very new to OpenVPN and I inherited a setup at my job. All of our clients are experiencing connection issues and it is related to this timeout error.

Inactivity timeout (--ping-restart), restarting

I am using the OpenVPN interface through pfSense and have been making changes to the keepalive configuration, but I have failed to solve the issue. I know you are likely going to need more information from me and I am willing and ready to provide it. Let me know what you need to help me solve this issue. The timeout is rather random. Sometimes our clients can stay connected for 45 minutes and sometimes we get this timeout error in 5 minutes.

Any ideas?

TinCanTech

Please see:
HOWTO: Request Help !

please read that carefully ..

chrisalau32

I don't know where to find my full server configuration file. Can it be accessed through pfsense?

TinCanTech

Just do what you can ..

chrisalau32

Hello. I posted earlier, but I realized that I was not posting enough information for anyone to be able to help me. I have followed the HOWTO and I am going to try this again. I am working on getting the client log file from one of our users, but I am sure it is very similar to the error you see in the server log file. Users are getting booted for inactivity and I am not sure why. Any help would be greatly appreciated.

Operating System

FreeBSD pfSense.consultpss.com 11.1-RELEASE-p7 FreeBSD 11.1-RELEASE-p7 #10 r313908+986837ba7e9 ( RELENG_2_4 ) : Mon Mar 26 18:08:25 CDT 2018 root@buildbot2.

Server Configuration File

dev ovpns1
verb 1
dev-type tun
dev-node /dev/tun1
writepid /var/run/openvpn_server1.pid
#user nobody
#group nobody
script-security 3
daemon
keepalive 10 60
ping-timer-rem
persist-tun
persist-key
proto udp4
cipher AES-256-CBC
auth SHA1
up /usr/local/sbin/ovpn-linkup
down /usr/local/sbin/ovpn-linkdown
client-connect /usr/local/sbin/openvpn.attributes.sh
client-disconnect /usr/local/sbin/openvpn.attributes.sh
local (*Public IP Removed*)
tls-server
server 10.8.0.0 255.255.255.0
client-config-dir /var/etc/openvpn-csc/server1
username-as-common-name
auth-user-pass-verify "/usr/local/sbin/ovpn_auth_verify user TG9jYWwgRGF0YWJhc2U= false server1 1194" via-env
tls-verify "/usr/local/sbin/ovpn_auth_verify tls 'VPN+-+CA' 1"
lport 1194
management /var/etc/openvpn/server1.sock unix
push "route 192.168.237.0 255.255.255.0"
push "dhcp-option DOMAIN (*DOMAIN REMOVED*)"
push "dhcp-option DNS 192.168.237.5"
push "dhcp-option DNS 192.168.237.10"
duplicate-cn
ca /var/etc/openvpn/server1.ca
cert /var/etc/openvpn/server1.cert
key /var/etc/openvpn/server1.key
dh /etc/dh-parameters.2048
tls-auth /var/etc/openvpn/server1.tls-auth 0
ncp-ciphers AES-256-GCM:AES-128-GCM
persist-remote-ip
float
topology subnet

Server Log

0.234.154:60550 peer info: IV_COMP_STUBv2=1
Aug 23 11:53:58 pfSense openvpn[22915]: 75.150.234.154:60550 peer info: IV_TCPNL=1
Aug 23 11:53:58 pfSense openvpn[22915]: 75.150.234.154:60550 peer info: IV_GUI_VER=OpenVPN_GUI_11
Aug 23 11:53:58 pfSense openvpn: user 'dsugg' authenticated
Aug 23 11:53:58 pfSense openvpn[22915]: 75.150.234.154:60550 [dsugg] Peer Connection Initiated with [AF_INET]75.150.234.154:60550
Aug 23 11:53:58 pfSense openvpn[22915]: dsugg/75.150.234.154:60550 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=(Not enabled)
Aug 23 12:01:49 pfSense openvpn[22915]: dsugg/75.150.234.154:60550 [dsugg] Inactivity timeout (--ping-restart), restarting
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_VER=2.4.4
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_PLAT=win
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_PROTO=2
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_NCP=2
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_LZ4=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_LZ4v2=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_LZO=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_COMP_STUB=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_COMP_STUBv2=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_TCPNL=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_GUI_VER=OpenVPN_GUI_11
Aug 23 12:02:47 pfSense openvpn: user 'dsugg' authenticated
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 [dsugg] Peer Connection Initiated with [AF_INET]75.150.234.154:55090
Aug 23 12:02:47 pfSense openvpn[22915]: dsugg/75.150.234.154:55090 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=(Not enabled)
Aug 23 12:23:09 pfSense openvpn[22915]: dsugg/75.150.234.154:55090 [dsugg] Inactivity timeout (--ping-restart), restarting
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_VER=2.4.4
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_PLAT=win
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_PROTO=2
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_NCP=2
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_LZ4=1
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_LZ4v2=1
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_LZO=1
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_COMP_STUB=1
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_COMP_STUBv2=1
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_TCPNL=1
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 peer info: IV_GUI_VER=OpenVPN_GUI_11
Aug 23 12:24:08 pfSense openvpn: user 'dsugg' authenticated
Aug 23 12:24:08 pfSense openvpn[22915]: 75.150.234.154:54477 [dsugg] Peer Connection Initiated with [AF_INET]75.150.234.154:54477
Aug 23 12:24:08 pfSense openvpn[22915]: dsugg/75.150.234.154:54477 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=(Not enabled)
Aug 23 13:13:15 pfSense openvpn[22915]: dsugg/75.150.234.154:54477 [dsugg] Inactivity timeout (--ping-restart), restarting
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_VER=2.4.4
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_PLAT=win
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_PROTO=2
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_NCP=2
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_LZ4=1
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_LZ4v2=1
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_LZO=1
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_COMP_STUB=1
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_COMP_STUBv2=1
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_TCPNL=1
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 peer info: IV_GUI_VER=OpenVPN_GUI_11
Aug 23 13:14:12 pfSense openvpn: user 'dsugg' authenticated
Aug 23 13:14:12 pfSense openvpn[22915]: 75.150.234.154:51307 [dsugg] Peer Connection Initiated with [AF_INET]75.150.234.154:51307
Aug 23 13:14:12 pfSense openvpn[22915]: dsugg/75.150.234.154:51307 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=(Not enabled)
Aug 23 13:25:18 pfSense openvpn[22915]: dsugg/75.150.234.154:51307 [dsugg] Inactivity timeout (--ping-restart), restarting
Aug 23 13:26:12 pfSense openvpn[22915]: 75.150.234.154:50629 peer info: IV_VER=2.4.4

Client Config File

dev tun
persist-tun
persist-key
cipher AES-256-CBC
ncp-ciphers AES-256-GCM:AES-128-GCM
auth SHA1
tls-client
client
resolv-retry infinite
remote vpn.(*DOMAIN HIDDEN*) 1194 udp
lport 0
verify-x509-name "VPN - CA" name
auth-user-pass
pkcs12 pfSense-UDP4-1194-dsugg.p12
tls-auth pfSense-UDP4-1194-dsugg-tls.key 1
remote-cert-tls server

TinCanTech

And your client log file please at --verb 4

chrisalau32

For some reason, it won't let me post it here.

Client Log File

https://pastebin.com/JSveMxS6

TinCanTech

--verb 4 please

You need to look for what is pushed and what is received ..

The reason your post gets rejected is because you do not sanitize your log file.

chrisalau32

I would also like to add that we see multiple users dropping connection at the same time with this inactivity timeout error.

chrisalau32

Here is the new log file at verb 4. Sorry for the misunderstanding.

https://pastebin.com/DePNdMTz

TinCanTech

From your log (sanitized):

Thu Aug 30 10:19:58 2018 us=204586 SENT CONTROL [VPN - CA]: 'PUSH_REQUEST' (status=1)
Thu Aug 30 10:19:58 2018 us=289249 PUSH: Received control message: 'PUSH_REPLY,route 192.168.237.0 255.255.255.0,dhcp-option DOMAIN [redacted].com,dhcp-option DNS 192.168.237.5,dhcp-option DNS 192.168.237.10,route-gateway 10.8.0.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.8.0.4 255.255.255.0,peer-id 2,cipher AES-256-GCM'
Thu Aug 30 10:19:58 2018 us=289249 OPTIONS IMPORT: timers and/or timeouts modified
Thu Aug 30 10:19:58 2018 us=289249 OPTIONS IMPORT: --ifconfig/up options modified
Thu Aug 30 10:19:58 2018 us=289249 OPTIONS IMPORT: route options modified
Thu Aug 30 10:19:58 2018 us=289249 OPTIONS IMPORT: route-related options modified
Thu Aug 30 10:19:58 2018 us=290291 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Thu Aug 30 10:19:58 2018 us=290291 OPTIONS IMPORT: peer-id set
Thu Aug 30 10:19:58 2018 us=290291 OPTIONS IMPORT: adjusting link_mtu to 1624
Thu Aug 30 10:19:58 2018 us=290291 OPTIONS IMPORT: data channel crypto options modified
Thu Aug 30 10:19:58 2018 us=290291 Data Channel: using negotiated cipher 'AES-256-GCM'
Thu Aug 30 10:19:58 2018 us=290291 Data Channel MTU parms [ L:1552 D:1450 EF:52 EB:406 ET:0 EL:3 ]
Thu Aug 30 10:19:58 2018 us=290291 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Aug 30 10:19:58 2018 us=290291 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Thu Aug 30 10:19:58 2018 us=290291 interactive service msg_channel=816
Thu Aug 30 10:19:58 2018 us=304261 ROUTE_GATEWAY 10.0.1.1/255.255.0.0 I=17 HWADDR=5c:ea:1d:60:56:1f
Thu Aug 30 10:19:58 2018 us=306258 open_tun
Thu Aug 30 10:19:58 2018 us=309237 TAP-WIN32 device [Ethernet 2] opened: \\.\Global\{D234EF63-6783-4CAA-B149-E86F4E399ACF}.tap
Thu Aug 30 10:19:58 2018 us=309237 TAP-Windows Driver Version 9.21
Thu Aug 30 10:19:58 2018 us=309237 TAP-Windows MTU=1500
Thu Aug 30 10:19:58 2018 us=314230 Set TAP-Windows TUN subnet mode network/local/netmask = 10.8.0.0/10.8.0.4/255.255.255.0 [SUCCEEDED]
Thu Aug 30 10:19:58 2018 us=314230 Notified TAP-Windows driver to set a DHCP IP/netmask of 10.8.0.4/255.255.255.0 on interface {D234EF63-6783-4CAA-B149-E86F4E399ACF} [DHCP-serv: 10.8.0.254, lease-time: 31536000]
Thu Aug 30 10:19:58 2018 us=314230 DHCP option string: 0f0e636f 6e73756c 74707373 2e636f6d 0608c0a8 ed05c0a8 ed0a
Thu Aug 30 10:19:58 2018 us=316175 Successful ARP Flush on interface [55] {D234EF63-6783-4CAA-B149-E86F4E399ACF}
Thu Aug 30 10:19:58 2018 us=327144 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Thu Aug 30 10:19:58 2018 us=327144 MANAGEMENT: >STATE:1535649598,ASSIGN_IP,,10.8.0.4,,,,
Thu Aug 30 10:20:03 2018 us=731777 TEST ROUTES: 1/1 succeeded len=1 ret=1 a=0 u/d=up
Thu Aug 30 10:20:03 2018 us=731777 MANAGEMENT: >STATE:1535649603,ADD_ROUTES,,,,,,
Thu Aug 30 10:20:03 2018 us=731777 C:\WINDOWS\system32\route.exe ADD 192.168.237.0 MASK 255.255.255.0 10.8.0.1
Thu Aug 30 10:20:03 2018 us=733775 Route addition via service succeeded
Thu Aug 30 10:20:03 2018 us=733775 Initialization Sequence Completed
Thu Aug 30 10:20:03 2018 us=733775 MANAGEMENT: >STATE:1535649603,CONNECTED,SUCCESS,10.8.0.4,#.#.#.#,1194,,
Thu Aug 30 10:21:27 2018 us=336202 [VPN - CA] Inactivity timeout (--ping-restart), restarting
Thu Aug 30 10:21:27 2018 us=337086 TCP/UDP: Closing socket
Thu Aug 30 10:21:27 2018 us=337086 SIGUSR1[soft,ping-restart] received, process restarting
Thu Aug 30 10:21:27 2018 us=337086 MANAGEMENT: >STATE:1535649687,RECONNECTING,ping-restart,,,,,
Thu Aug 30 10:21:27 2018 us=337086 Restart pause, 5 second(s)
Thu

No errors here ..

The only useful information in your server log:

12:01:49 pfSense openvpn[22915]: dsugg/#.#.#.#:60550 [dsugg] Inactivity timeout (--ping-restart), restarting
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_VER=2.4.4
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_PLAT=win
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_PROTO=2
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_NCP=2
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_LZ4=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_LZ4v2=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_LZO=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_COMP_STUB=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_COMP_STUBv2=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_TCPNL=1
Aug 23 12:02:47 pfSense openvpn[22915]: 75.150.234.154:55090 peer info: IV_GUI_VER=OpenVPN_GUI_11
Aug 23 12:02:47 pfSense openvpn: user 'dsugg' authenticated
Aug 23 12:02:47 pfSense openvpn[22915]: #.#.#.#:55090 [dsugg] Peer Connection Initiated with [AF_INET]75.150.234.154:55090
Aug 23 12:02:47 pfSense openvpn[22915]: dsugg/#.#.#.#:55090 MULTI_sva: pool returned IPv4=10.8.0.2, IPv6=(Not enabled)
Aug 23 12:23:09 pfSense openvpn[22915]: dsugg/#.#.#.#:55090 [dsugg] Inactivity timeout (--ping-restart), restarting
Aug 23 [/b]A

Inactivity timeout .. so --keepalive 's are not working ?

Your Server Config:

verb 1

chrisalau32

Yes it appears that the keepalive is not working, but I have added keepalive 10 60 to both the server and the client configuration. What would be causing it to fail?

TinCanTech

Server log at --verb 4 please.