User Auth Failed

ryoung81

Hi, I'm stuck... I've tried a few different routes to this VPN back working. I'm getting AUTH_FAILED. I've tried recreating the VPN, CA, verified the user access works though the Diagnostics > Authentication.

CONF File:

dev ovpns5
verb 5
dev-type tun
dev-node /dev/tun5
writepid /var/run/openvpn_server5.pid
#user nobody
#group nobody
script-security 3
daemon
keepalive 10 60
ping-timer-rem
persist-tun
persist-key
proto tcp4-server
cipher AES-128-CBC
auth SHA256
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
multihome
tls-server
server 10.0.11.0 255.255.255.0
client-config-dir /var/etc/openvpn-csc/server5
verify-client-cert none
username-as-common-name
plugin /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so /usr/local/sbin/ovpn_auth_verify_async user TG9jYWwgRGF0YWJhc2U= false server5 1199
tls-verify "/usr/local/sbin/ovpn_auth_verify tls 'RGVEC-NEW-VPN' 1"
lport 1199
management /var/etc/openvpn/server5.sock unix
max-clients 5
client-to-client
duplicate-cn
ca /var/etc/openvpn/server5.ca 
cert /var/etc/openvpn/server5.cert 
key /var/etc/openvpn/server5.key 
dh /etc/dh-parameters.2048
tls-auth /var/etc/openvpn/server5.tls-auth 0
ncp-ciphers AES-128-GCM
compress 
persist-remote-ip
float
topology subnet

OVPN File:

code_tedev tun
persist-tun
persist-key
data-ciphers AES-128-GCM
data-ciphers-fallback AES-128-CBC
auth SHA256
tls-client
client
resolv-retry infinite
remote 173.209.78.58 1199 tcp4
auth-user-pass
remote-cert-tls server
compress 
verb 6

<ca>
-----BEGIN CERTIFICATE-----
Removed
-----END CERTIFICATE-----
</ca>
setenv CLIENT_CERT 0
key-direction 1
<tls-auth>
#
# 2048 bit OpenVPN static key
#
-----BEGIN OpenVPN Static key V1-----
removed
-----END OpenVPN Static key V1-----
</tls-auth>
xt

PFSENSE OVPN LOG:

Apr 22 09:46:41	openvpn	90594	TCP/UDP: Closing socket
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 SIGUSR1[soft,connection-reset] received, client-instance restarting
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 Connection reset, restarting [0]
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [95] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #12 ] [ ] pid=8 DATA len=41
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [62] to [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #11 ] [ 5 ]
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 SENT CONTROL [ryoung81]: 'AUTH_FAILED' (status=1)
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 Delayed exit in 5 seconds
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 PUSH: Received control message: 'PUSH_REQUEST'
Apr 22 09:46:41	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [96] from [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #11 ] [ ] pid=5 DATA len=42
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [62] to [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #10 ] [ 4 ]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 PUSH: Received control message: 'PUSH_REQUEST'
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [96] from [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #10 ] [ ] pid=4 DATA len=42
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 [ryoung81] Peer Connection Initiated with [AF_INET]192.168.0.138:60432
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [62] from [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #9 ] [ 7 ]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [328] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #9 ] [ 3 ] pid=7 DATA len=262
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 WARNING: 'cipher' is used inconsistently, local='cipher AES-128-CBC', remote='cipher BF-CBC'
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1572', remote='link-mtu 1556'
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TLS: Username/Password authentication deferred for username 'ryoung81' [CN SET]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_BS64DL=1
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_COMP_STUBv2=1
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_COMP_STUB=1
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_LZO_STUB=1
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_PROTO=2
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_TCPNL=1
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_NCP=2
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_PLAT=win
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_VER=3.git::f225fcd0
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 peer info: IV_GUI_VER=OCmacOS_3.1.3-713
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [544] from [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #8 ] [ 6 ] pid=3 DATA len=478
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [117] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #8 ] [ 2 ] pid=6 DATA len=51
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [192] from [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #7 ] [ 5 ] pid=2 DATA len=126
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [62] from [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #6 ] [ 4 ]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [62] from [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #5 ] [ 3 ]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [62] from [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #4 ] [ 2 ]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [1095] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #7 ] [ ] pid=5 DATA len=1041
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [62] from [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #3 ] [ 1 ]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [1144] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #6 ] [ ] pid=4 DATA len=1090
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [1144] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #5 ] [ ] pid=3 DATA len=1090
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [1144] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #4 ] [ ] pid=2 DATA len=1090
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [1144] to [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #3 ] [ ] pid=1 DATA len=1090
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [62] to [AF_INET]192.168.0.138:60432: P_ACK_V1 kid=0 pid=[ #2 ] [ 1 ]
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [262] from [AF_INET]192.168.0.138:60432: P_CONTROL_V1 kid=0 pid=[ #2 ] [ 0 ] pid=1 DATA len=196
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER WRITE [66] to [AF_INET]192.168.0.138:60432: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 pid=[ #1 ] [ 0 ] pid=0 DATA len=0
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TLS: Initial packet from [AF_INET]192.168.0.138:60432, sid=a49db0c1 7ad618dc
Apr 22 09:46:40	openvpn	90594	192.168.0.138:60432 TCPv4_SERVER READ [54] from [AF_INET]192.168.0.138:60432: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0
Apr 22 09:46:40	openvpn	90594	TCPv4_SERVER link remote: [AF_INET]192.168.0.138:60432
Apr 22 09:46:40	openvpn	90594	TCPv4_SERVER link local: (not bound)
Apr 22 09:46:40	openvpn	90594	TCP connection established with [AF_INET]192.168.0.138:60432
Apr 22 09:46:40	openvpn	90594	Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher AES-128-CBC,auth SHA256,keysize 128,tls-auth,key-method 2,tls-client'
Apr 22 09:46:40	openvpn	90594	Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1572,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher AES-128-CBC,auth SHA256,keysize 128,tls-auth,key-method 2,tls-server'
Apr 22 09:46:40	openvpn	90594	Data Channel MTU parms [ L:1624 D:1450 EF:124 EB:406 ET:0 EL:3 ]
Apr 22 09:46:40	openvpn	90594	Control Channel MTU parms [ L:1624 D:1170 EF:80 EB:0 ET:0 EL:3 ]

blasterspike

I'm having a similar issue.
What version of pfSense do you have?
How did you set the "Server Mode" for the OpenVPN server? "Remote Access (User Auth)"?

ryoung81

@blasterspike I originally setup with the wizard, then opened the VPN settings and manually changed it.

Oh, I'm on 2.4.5-RELEASE

ryoung81

@ryoung81
I also now see I'm generating a PHP error message, not sure if it's related:

PHP ERROR: Type: 64, File: /etc/inc/notices.inc, Line: 444, Message: require_once(): Failed opening required 'Net/Growl/Autoload.php' (include_path='.:/etc/inc:/usr/local/www:/usr/local/captiveportal:/usr/local/pkg:/usr/local/www/classes:/usr/local/www/classes/Form:/usr/local/share/pear:/usr/local/share/openssl_x509_crl/') @ 2022-04-22 10:15:19

blasterspike

I'm testing a fix, let me know if this works for you as well.
Get a shell access to your pfSense box, edit this file

/usr/local/sbin/ovpn_auth_verify_async

and change line #78 from

if [ "${result}" = "OK" ]; then

to

if [ "${result}" = "....OK" ]; then

bpmartin

@blasterspike I'm having the same problem with ovpn_auth_verify (no _async). The equivalent fix seems to resolve the problem, but I can't see where the "...." prefix is coming from. I'm no PHP guy, but the routine it calls to generate ${RESULT} appears to just be returning "OK" (no dots). Yet when I run it from the command line, dots appear.

My fix was to leave the conditional as-is, and insert immediately above it:

[ "${RESULT}" = "...OK" ]] && RESULT="OK" # Remove dots if present

If yours is the fix, is it going into some future update? I don't want to have to keep patching this myself.

blasterspike

Unfortunately I know very little too about PHP to be able to debug this issue.
I don't think that Netgate is aware of this, therefore I don't see a patch coming. I have seen a tendency in their issue tracker that you have to provide the complete debug and point at where the error is for the bug to be taken into consideration.
I have already spent enough time debugging it, hopefully someone more capable on PHP will be able to help us.

I hate too thinking about patching this at every upgrade.

ryoung81

@blasterspike we actually just went ahead and moved our production over to fortigate. No issues :/

bpmartin

Looking into the further, I believe I've found out why it's happening. When ovpn_auth_verify runs the php-cgi command to run /etc/inc/openvpn.auth-user.php, ovpn.auth-user.php or some lower level command may conditionally print dots as a progress indicator. On fast systems, no dots appear. On slower systems, 1 or more dots may appear. Probably they would appear on a fast system too, if the system were under a heavy load.

This also means that the number of dots preceding "OK" is variable. Matching a specific number of leading dots is not reliable. My new patch is:

41a42
> RESULT=$(echo $RESULT | tr -d ".")

The variable number of dots also explains why reports aren't more widespread. It only happens on variably, depending on system performance and load.

bpmartin

I neglected to mention that I'm experiencing this on the current stable release, 2.6.0, built 31/Jan/2022.

bpmartin

@blasterspike I know you've subsequently migrated off of pfSense, but is there any chance you can tell me what release of pfSense you were running when you last experienced this problem?

I have but 13327 open with the developers, but they're rejecting it because they think the report is on an outdated release. I'd like to document which release you were experiencing this problem with, and what hardware you were running pfSense on.

Also, was this the reason you migrated off, or or there other issues?

blasterspike

@bpmartin I'm still using pfSense, I think you are confusing me with ryoung81.

I'm using

2.6.0-RELEASE (amd64)
built on Mon Jan 31 19:57:53 UTC 2022
FreeBSD 12.3-STABLE

In total, I had to edit 2 files with this "....OK" trick to have OpenVPN working again
/usr/local/sbin/ovpn_auth_verify
/usr/local/sbin/ovpn_auth_verify_async

I discovered this problem about User Auth Failed while debugging this other issue
https://forum.netgate.com/topic/171707/openvpn-server-certificate-verify-failed-on-pfsense-2-6-0/3

I don't even think that my hardware is suffering to justify this behaviour, I'm using pfSense at home and the traffic is low.
However this is the box where it is running

Intel(R) Celeron(R) CPU J3160 @ 1.60GHz
4 CPUs: 1 package(s) x 4 core(s)
AES-NI CPU Crypto: Yes (active)
QAT Crypto: No 

4GB of RAM

bpmartin

Apologies for the confustion @blasterspike ... I was obviously reading and writing too early in the morning.

The bug report can be found at:

https://redmine.pfsense.org/issues/13327

It's currently in "Rejected" status because the developer thought it was in regards to an obsolete release. I'd appreciate it if you and others that are on current releases would update the ticket to include that it's affecting you, too. I think it may be performance related, so basic hardware information may be useful too. I just copied my CPU info off the pfSense Dashboard, and added the amount of memory I have.

Right now I'm afraid I have a credibility problem, understandably, since this is a widely used package and I'm the only one reporting it. Showing that more sites are experiencing it might be enough to get it fixed. Especially so since one possible fix is just one line of code that I've already provided.

blasterspike

@bpmartin I have replied to that issue as well. Unfortunately as it is closed, I believe it will go into oblivion...

bpmartin

@blasterspike Thank you for updating the bug. Since Jim Pingle took ownership and rejected it, I'm hoping he'll get update notifications, review it, and consider reopening it. If not, I'll look for other ways to reach out. I suppose you could open a bug of your own, too, if you thought that was a good idea. You could just refer to 13327 and report you're having the same experience on the current release. I'm not sure which approach will be the most effective. We know it's a real bug - it's just that the developers don't.