Pfsense OpenVPN never seems to resonnect after Inactivity timeout, AUTH_FAILED



  • 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]

    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
    

    [OpenVPN Log]

    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)
    
    


  • Failed again

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

    
    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)
    

  • Netgate

    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.



  • 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.


  • Netgate

    Cool. Good info. Thanks for getting back.



  • interesting.  i use the same provider but with 256 bit encryption..

    i have never had this occur although  i am connecting by IP instead of server name



  • I was seeing the same issue every time I got a new IP from my provider.

    I made the changes you supplied.  Hopefully this takes care of my issue.

    Thanks!

    @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.



  • i have started having this issue in the past few days after my post.  i'll need to change this when i get home as my entire home network is down….

    i even added systemwatchdog to monitor gateway and openvpn.... it apparently will not fix this either


  • Netgate

    Client side here:

    https://doc.pfsense.org/index.php/OpenVPN_Site_To_Site

    There is a huge thread here on connecting to PIA:

    https://forum.pfsense.org/index.php?topic=76015.0



  • after the change this is still an issue at least i was home this time.  i have been statically connecting to 64.237.37.121 for weeks now.  i think i am going to try another server…


 

© Copyright 2002 - 2018 Rubicon Communications, LLC | Privacy Policy