Posted: Mon Jan 10, 2022 13:39 Post subject: OpenVPN client disconnects following Inactivity Timeout
I am currently running firmware v3.0-r47942 on Linksys WRT3200ACM. The issue I'm encountering has occurred on earlier builds I have tried as well.
Issue: From the config you'll see that I am running a split VPN (NordVPN). VPN connection for those systems is successful for hours, sometimes days until log shows an "Inactivity Timeout" occurring. I can then see via whatismyipaddress.com that my IP address drops back from VPN to ISP. OpenVPN status starts and remains at CONNECTED SUCCESSFUL even post the Inactivity Timeout. I had a Killswitch in the Administration Firewall but have since removed until this issue is resolved. That Killswitch worked and would drop activity since IP would drop back to ISP.
Here is how my log looks after connection when everything is fine. This can go on for hours, days.
https://ibb.co/209fZ9M
This is how the log ends with no activity thereafter. I suspect the iptables message is a big clue but I don't know how fix this.
https://ibb.co/L95dCMV
My config looks like this. I did have inbound firewall on TUN checked and unchecked it as a test which ultimately made no difference.
https://ibb.co/mbFxVxr
This is my first post while I have researched and learned quite a bit on this forum over the last few years.
Last edited by deedeedoubleyourt on Mon Jan 10, 2022 14:27; edited 3 times in total
Joined: 18 Mar 2014 Posts: 12922 Location: Netherlands
Posted: Mon Jan 10, 2022 16:13 Post subject:
I will move your post to the Advanced Networking forum as it is of interest to us all (and @eibgrad might have a look at it over there)
The "iptables: No chain ...." are from the deleting of the split DNS and are harmless.
You see it because you did not use the best settings as described in the docs (see the OpenVPN client setup guide, link in my signature at the bottom, there is a paragraph about NordVPN and also some things you can do to mitigate)
That said I will have a stern word with the developer, although the notification is harmless, it should not be there.
This is just sloppy programming
The real cause is not always apparent and even with keepalive set these things happen and sometimes you have to run a watchdog script to restart the tunnel.
I see nothing in the logs that's abnormal. Inactivity timesout occur from time to time for various reasons (e.g., temporary loss of communications between client and server). But it will always attempt to reconnect as quickly as possible. And as long as you have the kill switch enabled, there will be NO access to the WAN while it's attempting to reconnect.
Most of what I'm seeing in the log are the hourly change in the session key, which is done for the purposes of perfect forward secrecy. This too is completely normal. The default is every 3600 secs (1 hr), but you can change it to whatever you want using the reneg-sec directive (or even disable it w/ reneg-sec=0).
Each time this happens I have to go in and Apply Settings in VPN admin page to reconnect. Nothing looking odd in the logs goes in sync with the OpenVPN Status (as previously stated) which remains at CONNECTED SUCCESSFUL. So if there's nothing abnormal and the connection is indeed SUCCESSFUL pre and post Inactivity Timeout then the routing is breaking for devices listed in PBR.
Here's another session which starts with a new connection by Applying Settings in VPN tab. It ends again with a drop post Inactivity Timeout @ 12:10:05 .
Quote:
2022-01-10 11:00:11 us=370416 event_wait : Interrupted system call (code=4)
2022-01-10 11:00:11 us=370453 SIGTERM received, sending exit notification to peer
2022-01-10 11:00:12 us=524913 TCP/UDP: Closing socket
2022-01-10 11:00:12 us=525018 /tmp/openvpncl/route-down.sh tun1 1500 1584 10.8.3.4 255.255.255.0 init
ip: RTNETLINK answers: No such file or directory
2022-01-10 11:00:12 us=633823 net_route_v4_del: 185.202.220.118/32 via 24.89.4.1 dev [NULL] table 0 metric -1
2022-01-10 11:00:12 us=633914 Closing TUN/TAP interface
2022-01-10 11:00:12 us=633935 net_addr_v4_del: 10.8.3.4 dev tun1
2022-01-10 11:00:12 us=673526 SIGTERM[soft,exit-with-notification] received, process exiting
2022-01-10 11:00:12 us=751986 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752022 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752038 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752053 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752067 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752081 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752094 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752108 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752122 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752135 WARNING: Using --management on a TCP port WITHOUT passwords is STRONGLY discouraged and considered insecure
2022-01-10 11:00:12 us=752160 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752178 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752194 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752210 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752226 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752249 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752265 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752286 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752302 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752318 WARNING: file '/tmp/openvpncl/ta.key' is group or others accessible
2022-01-10 11:00:12 us=752335 WARNING: file '/tmp/openvpncl/credentials' is group or others accessible
2022-01-10 11:00:12 us=752364 Current Parameter Settings:
2022-01-10 11:00:12 us=752377 config = '/tmp/openvpncl/openvpn.conf'
2022-01-10 11:00:12 us=752389 mode = 0
2022-01-10 11:00:12 us=752450 NOTE: --mute triggered...
2022-01-10 11:00:12 us=752485 518 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 11:00:12 us=752499 OpenVPN 2.5.5 arm-unknown-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Dec 30 2021
2022-01-10 11:00:12 us=752513 library versions: OpenSSL 1.1.1l 24 Aug 2021, LZO 2.09
2022-01-10 11:00:12 us=753169 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:16
2022-01-10 11:00:12 us=754269 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2022-01-10 11:00:12 us=755534 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2022-01-10 11:00:12 us=755565 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2022-01-10 11:00:12 us=755712 Control Channel MTU parms [ L:1653 D:1140 EF:110 EB:0 ET:0 EL:3 ]
2022-01-10 11:00:12 us=777093 Data Channel MTU parms [ L:1653 D:1450 EF:121 EB:411 ET:32 EL:3 ]
2022-01-10 11:00:12 us=777174 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1633,tun-mtu 1532,proto UDPv4,keydir 1,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-client'
2022-01-10 11:00:12 us=777192 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1633,tun-mtu 1532,proto UDPv4,keydir 0,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-server'
2022-01-10 11:00:12 us=777222 TCP/UDP: Preserving recently used remote address: [AF_INET]217.138.208.155:1194
2022-01-10 11:00:12 us=777248 Socket Buffers: R=[180224->180224] S=[180224->180224]
2022-01-10 11:00:12 us=777265 UDPv4 link local: (not bound)
2022-01-10 11:00:12 us=777284 UDPv4 link remote: [AF_INET]217.138.208.155:1194
2022-01-10 11:00:12 us=793173 TLS: Initial packet from [AF_INET]217.138.208.155:1194, sid=c75b6037 ededebf6
2022-01-10 11:00:12 us=836581 VERIFY OK: depth=2, C=PA, O=NordVPN, CN=NordVPN Root CA
2022-01-10 11:00:12 us=838182 VERIFY OK: depth=1, C=PA, O=NordVPN, CN=NordVPN CA6
2022-01-10 11:00:12 us=839768 NOTE: --mute triggered...
2022-01-10 11:00:13 us=57144 5 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 11:00:13 us=57179 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1633', remote='link-mtu 1634'
2022-01-10 11:00:13 us=57317 WARNING: 'comp-lzo' is present in remote config but missing in local config, remote='comp-lzo'
2022-01-10 11:00:13 us=57434 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 4096 bit RSA, signature: RSA-SHA512
2022-01-10 11:00:13 us=57480 [us9327.nordvpn.com] Peer Connection Initiated with [AF_INET]217.138.208.155:1194
2022-01-10 11:00:14 us=134642 SENT CONTROL [us9327.nordvpn.com]: 'PUSH_REQUEST' (status=1)
2022-01-10 11:00:14 us=150919 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 103.86.96.100,dhcp-option DNS 103.86.99.100,sndbuf 524288,rcvbuf 524288,explicit-exit-notify,comp-lzo no,route-gateway 10.8.1.1,topology subnet,ping 60,ping-restart 180,ifconfig 10.8.1.5 255.255.255.0,peer-id 3,cipher AES-256-GCM'
2022-01-10 11:00:14 us=150959 Pushed option removed by filter: 'redirect-gateway def1'
2022-01-10 11:00:14 us=151118 NOTE: --mute triggered...
2022-01-10 11:00:14 us=151142 4 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 11:00:14 us=151158 Socket Buffers: R=[180224->360448] S=[180224->360448]
2022-01-10 11:00:14 us=151171 OPTIONS IMPORT: --ifconfig/up options modified
2022-01-10 11:00:14 us=151189 OPTIONS IMPORT: route-related options modified
2022-01-10 11:00:14 us=151203 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
2022-01-10 11:00:14 us=151215 NOTE: --mute triggered...
2022-01-10 11:00:14 us=151230 3 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 11:00:14 us=151243 Data Channel: using negotiated cipher 'AES-256-GCM'
2022-01-10 11:00:14 us=151275 Data Channel MTU parms [ L:1584 D:1450 EF:52 EB:411 ET:32 EL:3 ]
2022-01-10 11:00:14 us=151463 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2022-01-10 11:00:14 us=151486 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2022-01-10 11:00:14 us=151536 net_route_v4_best_gw query: dst 0.0.0.0
2022-01-10 11:00:14 us=151636 net_route_v4_best_gw result: via 24.89.4.1 dev eth0
2022-01-10 11:00:14 us=152105 TUN/TAP device tun1 opened
2022-01-10 11:00:14 us=152131 do_ifconfig, ipv4=1, ipv6=0
2022-01-10 11:00:14 us=152160 net_iface_mtu_set: mtu 1500 for tun1
2022-01-10 11:00:14 us=152216 net_iface_up: set tun1 up
2022-01-10 11:00:14 us=152506 net_addr_v4_add: 10.8.1.5/24 dev tun1
2022-01-10 11:00:14 us=152706 net_route_v4_add: 217.138.208.155/32 via 24.89.4.1 dev [NULL] table 0 metric -1
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
2022-01-10 11:00:14 us=334168 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
2022-01-10 11:00:14 us=334195 Initialization Sequence Completed
2022-01-10 12:00:12 us=663906 VERIFY OK: depth=2, C=PA, O=NordVPN, CN=NordVPN Root CA
2022-01-10 12:00:12 us=665165 VERIFY OK: depth=1, C=PA, O=NordVPN, CN=NordVPN CA6
2022-01-10 12:00:12 us=666753 VERIFY KU OK
2022-01-10 12:00:12 us=666774 NOTE: --mute triggered...
2022-01-10 12:00:14 us=688999 4 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 12:00:14 us=689037 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1633', remote='link-mtu 1634'
2022-01-10 12:00:14 us=689174 WARNING: 'comp-lzo' is present in remote config but missing in local config, remote='comp-lzo'
2022-01-10 12:00:14 us=689419 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2022-01-10 12:00:14 us=689444 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2022-01-10 12:00:14 us=689508 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, peer certificate: 4096 bit RSA, signature: RSA-SHA512
2022-01-10 12:10:05 us=199818 [us9327.nordvpn.com] Inactivity timeout (--ping-restart), restarting
2022-01-10 12:10:05 us=200196 TCP/UDP: Closing socket
2022-01-10 12:10:05 us=200285 /tmp/openvpncl/route-down.sh tun1 1500 1584 10.8.1.5 255.255.255.0 init
ip: RTNETLINK answers: No such file or directory
2022-01-10 12:10:05 us=308111 net_route_v4_del: 217.138.208.155/32 via 24.89.4.1 dev [NULL] table 0 metric -1
2022-01-10 12:10:05 us=308197 Closing TUN/TAP interface
2022-01-10 12:10:05 us=308221 net_addr_v4_del: 10.8.1.5 dev tun1
2022-01-10 12:10:05 us=358638 SIGUSR1[soft,ping-restart] received, process restarting
2022-01-10 12:10:05 us=358763 Restart pause, 5 second(s)
2022-01-10 12:10:10 us=363570 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2022-01-10 12:10:10 us=364385 Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2022-01-10 12:10:10 us=364416 Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2022-01-10 12:10:10 us=364536 Control Channel MTU parms [ L:1654 D:1140 EF:110 EB:0 ET:0 EL:3 ]
2022-01-10 12:10:10 us=364572 Data Channel MTU parms [ L:1654 D:1450 EF:122 EB:411 ET:32 EL:3 ]
2022-01-10 12:10:10 us=364649 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1634,tun-mtu 1532,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-client'
2022-01-10 12:10:10 us=364666 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1634,tun-mtu 1532,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-server'
2022-01-10 12:10:10 us=364689 TCP/UDP: Preserving recently used remote address: [AF_INET]217.138.208.155:1194
2022-01-10 12:10:10 us=364723 Socket Buffers: R=[180224->360448] S=[180224->360448]
2022-01-10 12:10:10 us=364741 UDPv4 link local: (not bound)
2022-01-10 12:10:10 us=364761 UDPv4 link remote: [AF_INET]217.138.208.155:1194
2022-01-10 12:10:10 us=395091 TLS: Initial packet from [AF_INET]217.138.208.155:1194, sid=444b5e23 cd214655
2022-01-10 12:10:10 us=465385 VERIFY OK: depth=2, C=PA, O=NordVPN, CN=NordVPN Root CA
2022-01-10 12:10:10 us=467018 VERIFY OK: depth=1, C=PA, O=NordVPN, CN=NordVPN CA6
2022-01-10 12:10:10 us=468639 NOTE: --mute triggered...
2022-01-10 12:10:10 us=758516 6 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 12:10:10 us=758547 [us9327.nordvpn.com] Peer Connection Initiated with [AF_INET]217.138.208.155:1194
2022-01-10 12:10:11 us=897775 SENT CONTROL [us9327.nordvpn.com]: 'PUSH_REQUEST' (status=1)
2022-01-10 12:10:11 us=919623 PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 103.86.96.100,dhcp-option DNS 103.86.99.100,sndbuf 524288,rcvbuf 524288,explicit-exit-notify,comp-lzo no,route-gateway 10.8.0.1,topology subnet,ping 60,ping-restart 180,ifconfig 10.8.0.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
2022-01-10 12:10:11 us=919664 Pushed option removed by filter: 'redirect-gateway def1'
2022-01-10 12:10:11 us=919826 NOTE: --mute triggered...
2022-01-10 12:10:11 us=919850 4 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 12:10:11 us=919867 Socket Buffers: R=[360448->360448] S=[360448->360448]
2022-01-10 12:10:11 us=919880 OPTIONS IMPORT: --ifconfig/up options modified
2022-01-10 12:10:11 us=919893 OPTIONS IMPORT: route-related options modified
2022-01-10 12:10:11 us=919906 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
2022-01-10 12:10:11 us=919918 NOTE: --mute triggered...
2022-01-10 12:10:11 us=919933 3 variation(s) on previous 3 message(s) suppressed by --mute
2022-01-10 12:10:11 us=919946 Data Channel: using negotiated cipher 'AES-256-GCM'
2022-01-10 12:10:11 us=919981 Data Channel MTU parms [ L:1585 D:1450 EF:53 EB:411 ET:32 EL:3 ]
2022-01-10 12:10:11 us=920168 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2022-01-10 12:10:11 us=920190 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2022-01-10 12:10:11 us=920240 net_route_v4_best_gw query: dst 0.0.0.0
2022-01-10 12:10:11 us=920335 net_route_v4_best_gw result: via 24.89.4.1 dev eth0
2022-01-10 12:10:11 us=920837 TUN/TAP device tun1 opened
2022-01-10 12:10:11 us=920864 do_ifconfig, ipv4=1, ipv6=0
2022-01-10 12:10:11 us=920893 net_iface_mtu_set: mtu 1500 for tun1
2022-01-10 12:10:11 us=920948 net_iface_up: set tun1 up
2022-01-10 12:10:11 us=921235 net_addr_v4_add: 10.8.0.2/24 dev tun1
2022-01-10 12:10:11 us=921575 net_route_v4_add: 217.138.208.155/32 via 24.89.4.1 dev [NULL] table 0 metric -1
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
iptables: No chain/target/match by that name.
2022-01-10 12:10:12 us=106754 Initialization Sequence Completed
Joined: 18 Mar 2014 Posts: 12922 Location: Netherlands
Posted: Mon Jan 10, 2022 18:59 Post subject:
No those are harmless.
It is the delete rule of the split dns which precedes the insert rule and I did not add '>/dev/null'
(but have added in upcoming builds the notifications are gone then)
BTW, let's get a dump of the ip rules and routing tables once the connection is established and working normally, then immediately after the reconnection completes from the inactivity timeout, but BEFORE the op hits Apply. Let's see if there's a difference (beyond just a change in the VPN ip).
Code:
ip route show table main
ip route show table 10
ip rule show
BTW, let's get a dump of the ip rules and routing tables once the connection is established and working normally, then immediately after the reconnection completes from the inactivity timeout, but BEFORE the op hits Apply. Let's see if there's a difference (beyond just a change in the VPN ip).
Code:
ip route show table main
ip route show table 10
ip rule show
Affirmative - I've grabbed this information after an established connection and will do so again post inactivity timeout, prior to any Apply. Not sure how long before it hits that wall again. I would prefer to PM that info to you once I have it if that's ok.