pfSense Support Subscription

Author Topic: pfsense OpenVPN never seems to resonnect after Inactivity timeout, AUTH_FAILED  (Read 513 times)

0 Members and 1 Guest are viewing this topic.

Offline rcmpayne

  • Newbie
  • *
  • Posts: 19
  • Karma: +1/-0
    • View Profile
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: [Select]
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]
Code: [Select]
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)
« Last Edit: October 08, 2017, 07:17:27 pm by rcmpayne »

Offline rcmpayne

  • Newbie
  • *
  • Posts: 19
  • Karma: +1/-0
    • View Profile
Failed again


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


Code: [Select]
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)

Offline Derelict

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 9222
  • Karma: +1048/-308
    • View Profile
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.
Las Vegas, Nevada, USA
Use this diagram to describe your issue.
The pfSense Book is now available for just $24.70!
Do Not PM For Help! NO_WAN_EGRESSTM

Offline rcmpayne

  • Newbie
  • *
  • Posts: 19
  • Karma: +1/-0
    • View Profile
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.

Offline Derelict

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 9222
  • Karma: +1048/-308
    • View Profile
Cool. Good info. Thanks for getting back.
Las Vegas, Nevada, USA
Use this diagram to describe your issue.
The pfSense Book is now available for just $24.70!
Do Not PM For Help! NO_WAN_EGRESSTM

Offline bcruze

  • Jr. Member
  • **
  • Posts: 33
  • Karma: +1/-0
    • View Profile
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

Offline curious44

  • Newbie
  • *
  • Posts: 1
  • Karma: +0/-0
    • View Profile
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!

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.

Offline bcruze

  • Jr. Member
  • **
  • Posts: 33
  • Karma: +1/-0
    • View Profile
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

Offline Derelict

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 9222
  • Karma: +1048/-308
    • View Profile
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
Las Vegas, Nevada, USA
Use this diagram to describe your issue.
The pfSense Book is now available for just $24.70!
Do Not PM For Help! NO_WAN_EGRESSTM

Offline bcruze

  • Jr. Member
  • **
  • Posts: 33
  • Karma: +1/-0
    • View Profile
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...