pfSense English Support > OpenVPN

pfsense OpenVPN never seems to resonnect after Inactivity timeout, AUTH_FAILED

(1/2) > >>

rcmpayne:
I am using PIA OpenVPN on my pfsense router and every 4-5 days my internet stops. When I check pfsense GUI, I see OpenVPN adapter is down, and I have to manually start it. Doing so always starts up fine, and now I am good for another 4-5 days. Looking at the logs, I see two things.   

1. start getting "write UDPv4: Permission denied (code=13)"
2. after a few of these i see a restart due to timeout "Inactivity timeout (--ping-restart), restarting"
3. Upon restart i fail with "AUTH: Received control message: AUTH_FAILED"
4. Adapter stops.

I know I don't have any issues with the GUI saved password as I can login to pfsense and manually start the vpn again, and all is good. I can also restart the pfsense router hardware, and OpneVPN reconnects automatically.

I read another post where the guy had PIA support reset his password, so I did the same thing and updated it in pfsense. This seems to be ok until six days later where I hit the below again.
any ideas? 

I've bumped the OpenVPn to lev4 logging for the next occurrence in case its needed for this


[System Log]

--- Code: ---Oct 2 20:11:29 php-fpm 83575 /rc.newwanip: rc.newwanip: on (IP address: 10.7.10.6) (interface: VPN_INTERFACE[opt2]) (real interface: ovpnc1).
Oct 2 20:11:29 php-fpm 83575 /rc.newwanip: rc.newwanip: Info: starting on ovpnc1.
Oct 2 20:11:28 check_reload_status rc.newwanip starting ovpnc1
Oct 2 20:11:28 kernel ovpnc1: link state changed to UP
Oct 2 20:11:25 check_reload_status Reloading filter
Oct 2 20:11:25 php-fpm 37377 OpenVPN PID written: 81724
Oct 2 20:11:25 php-fpm 37377 OpenVPN terminate old pid: 37727
Oct 2 20:11:16 php-fpm 61477 /index.php: Successful login for user '**********' from: 1**>***>***>***
Oct 2 19:47:20 check_reload_status Reloading filter
Oct 2 19:47:20 kernel ovpnc1: link state changed to DOWN
--- End code ---

[OpenVPN Log]

--- Code: ---Oct 2 19:47:20 openvpn 37727 SIGTERM[soft,auth-failure] received, process exiting
Oct 2 19:47:20 openvpn 37727 /usr/local/sbin/ovpn-linkdown ovpnc1 1500 1558 10.49.10.6 10.49.10.5 init
Oct 2 19:47:20 openvpn 37727 AUTH: Received control message: AUTH_FAILED
Oct 2 19:47:18 openvpn 37727 [09d6f12104cd8a0039aa25571fd5ac0b] Peer Connection Initiated with [AF_INET]208.167.254.218:1198
Oct 2 19:47:18 openvpn 37727 WARNING: 'cipher' is used inconsistently, local='cipher AES-128-CBC', remote='cipher BF-CBC'
Oct 2 19:47:18 openvpn 37727 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1542'
Oct 2 19:47:18 openvpn 37727 UDPv4 link remote: [AF_INET]208.167.254.218:1198
Oct 2 19:47:18 openvpn 37727 UDPv4 link local (bound): [AF_INET]142.167.179.121
Oct 2 19:47:18 openvpn 37727 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Oct 2 19:47:16 openvpn 37727 SIGUSR1[soft,ping-restart] received, process restarting
Oct 2 19:47:16 openvpn 37727 [9b98010e67433cb752679cd25ef383a4] Inactivity timeout (--ping-restart), restarting
Oct 2 19:47:15 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:15 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:14 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:14 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:14 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:12 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:12 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:11 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:10 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:10 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:09 openvpn 37727 write UDPv4: Permission denied (code=13)
Oct 2 19:47:09 openvpn 37727 write UDPv4: Permission denied (code=13)

--- End code ---

rcmpayne:
Failed again


Debug 4 Logging as well as added auth-nocache as requested by PIA Support



--- Code: ---Oct 8 21:01:22 openvpn 15841 SIGTERM[soft,auth-failure] received, process exiting
Oct 8 21:01:22 openvpn 15841 /usr/local/sbin/ovpn-linkdown ovpnc1 1500 1558 10.40.10.6 10.40.10.5 init
Oct 8 21:01:22 openvpn 15841 Closing TUN/TAP interface
Oct 8 21:01:22 openvpn 15841 TCP/UDP: Closing socket
Oct 8 21:01:22 openvpn 15841 AUTH: Received control message: AUTH_FAILED
Oct 8 21:01:22 openvpn 15841 SENT CONTROL [5abc279e33ffb4796ab9c724b5b8515a]: 'PUSH_REQUEST' (status=1)
Oct 8 21:01:20 openvpn 15841 [5abc279e33ffb4796ab9c724b5b8515a] Peer Connection Initiated with [AF_INET]172.98.67.38:1198
Oct 8 21:01:20 openvpn 15841 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Oct 8 21:01:20 openvpn 15841 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Oct 8 21:01:20 openvpn 15841 Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
Oct 8 21:01:20 openvpn 15841 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Oct 8 21:01:20 openvpn 15841 Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
Oct 8 21:01:20 openvpn 15841 WARNING: 'cipher' is used inconsistently, local='cipher AES-128-CBC', remote='cipher BF-CBC'
Oct 8 21:01:20 openvpn 15841 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1542'
Oct 8 21:01:20 openvpn 15841 VERIFY OK: depth=0, C=US, ST=CA, L=LosAngeles, O=Private Internet Access, OU=Private Internet Access, CN=5abc279e33ffb4796ab9c724b5b8515a, name=5abc279e33ffb4796ab9c724b5b8515a
Oct 8 21:01:20 openvpn 15841 VERIFY EKU OK
Oct 8 21:01:20 openvpn 15841 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Oct 8 21:01:20 openvpn 15841 Validating certificate extended key usage
Oct 8 21:01:20 openvpn 15841 VERIFY KU OK
Oct 8 21:01:20 openvpn 15841 ++ Certificate has key usage 00a0, expects 00a0
Oct 8 21:01:20 openvpn 15841 Validating certificate key usage
Oct 8 21:01:20 openvpn 15841 VERIFY OK: depth=1, C=US, ST=CA, L=LosAngeles, O=Private Internet Access, OU=Private Internet Access, CN=Private Internet Access, name=Private Internet Access, emailAddress=secure@privateinternetaccess.com
Oct 8 21:01:20 openvpn 15841 TLS: Initial packet from [AF_INET]172.98.67.38:1198, sid=364b61a5 b5a1d7ea
Oct 8 21:01:20 openvpn 15841 UDPv4 link remote: [AF_INET]172.98.67.38:1198
Oct 8 21:01:20 openvpn 15841 UDPv4 link local (bound): [AF_INET]142.167.179.121
Oct 8 21:01:20 openvpn 15841 Expected Remote Options hash (VER=V4): '691e95c7'
Oct 8 21:01:20 openvpn 15841 Local Options hash (VER=V4): '66096c33'
Oct 8 21:01:20 openvpn 15841 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Oct 8 21:01:20 openvpn 15841 Local Options String: 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Oct 8 21:01:20 openvpn 15841 Data Channel MTU parms [ L:1558 D:1450 EF:58 EB:143 ET:0 EL:3 AF:3/1 ]
Oct 8 21:01:20 openvpn 15841 Socket Buffers: R=[42080->42080] S=[57344->57344]
Oct 8 21:01:20 openvpn 15841 Control Channel MTU parms [ L:1558 D:1212 EF:38 EB:0 ET:0 EL:3 ]
Oct 8 21:01:20 openvpn 15841 LZO compression initialized
Oct 8 21:01:20 openvpn 15841 Re-using SSL/TLS context
Oct 8 21:01:20 openvpn 15841 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Oct 8 21:01:18 openvpn 15841 Restart pause, 2 second(s)
Oct 8 21:01:18 openvpn 15841 SIGUSR1[soft,ping-restart] received, process restarting
Oct 8 21:01:18 openvpn 15841 TCP/UDP: Closing socket
Oct 8 21:01:18 openvpn 15841 [97a58cbbb1f29906dc6e44cb83dd7ce6] Inactivity timeout (--ping-restart), restarting
Oct 8 21:01:17 openvpn 15841 write UDPv4: Permission denied (code=13)
Oct 8 21:01:17 openvpn 15841 write UDPv4: Permission denied (code=13)
Oct 8 21:01:17 openvpn 15841 write UDPv4: Permission denied (code=13)
Oct 8 21:01:17 openvpn 15841 write UDPv4: Permission denied (code=13)
Oct 8 21:01:17 openvpn 15841 write UDPv4: Permission denied (code=13)
Oct 8 21:01:17 openvpn 15841 write UDPv4: Permission denied (code=13)
--- End code ---

Derelict:
AUTH_FAILED is, by default, a hard error to OpenVPN and it dies. The real issue there is PIA returning that.

Try adding:

   auth-retry nointeract;

to the custom options in the OpenVPN client configuration.

rcmpayne:
OK the Issue is now fixed after working with PIA support a few times. The new configs for those with this sort of issue

OpenVPN client configuration:

persist-key
remote-cert-tls server
reneg-sec 0
auth-nocache


Essentially, we added "auth-nocache" and removed "persist-tun". Doing so should cause OpenVPN to opt for a full restart instead of trying to resume the previous session, which tends to fail due to your router likely connecting to a different server.

Derelict:
Cool. Good info. Thanks for getting back.

Navigation

[0] Message Index

[#] Next page

Go to full version