Bug #11183
closed
Mutliply OpenVPN Backend for authentication lead to permanent AUTH_FAIL
Added by DRago_Angel [InV@DER] over 3 years ago. Updated over 3 years ago.
0%
Description
On 2.4.5 and from far ago I was used OpenVPN with 2 backends without any issues.
After updating to 2.5.0.a.20201127.0650 I can't connect to my existing OpenVPN. After trying to fix it by switching options I found that if I leave only one authentication backend it start working fine. No matter what of 2 backends I leave it will work. Also Auth Diagnostic displays that user can authenticate with both backends. OpenVPN Logs not provide many info.
Updated by Viktor Gurov over 3 years ago
unable to reproduce it on 2.5.0.a.20201230.0250,
I can successfully authenticate to OpenVPN server with a mix of RADIUS/LDAP auth backends
Please provide more info
Updated by DRago_Angel [InV@DER] over 3 years ago
Hi Viktor, when my openvpn server have multiple ldap backends I simply got AUTH_FAIL in logs. Could you please provide info which debug logging I need to enable and where to provide more details on this case, thank you in advance.
Updated by DRago_Angel [InV@DER] over 3 years ago
Also Viktor you mention 2.5.0.a.20201230.0250 version, when for my instance 2.5.0.a.20201127.0650 is reported as latest available. I also have another instance on 2.4.5_p1 and if I change to 2.5.x devel branch on it, it also reports 2.5.0.a.20201127.0650 as latest. To note I speak in both cases about pfSense non-Community edition on XG-7100U.
Updated by Viktor Gurov over 3 years ago
Updated by DRago_Angel [InV@DER] over 3 years ago
Not sure about #10704 as on 2.4.5_p1 it was working correctly. Issue appear right after update to 2.5.0.a.
I have in my case Win2012R2 also.
1st: dc1.ldap.company.com
2nd: dc2.ldap.company.com
Both Auth servers use SSL 636 and their certs issued by same CA. This is internal CA is trusted by pfSense (certificate issued from pfSense managed CA).
As you asked I changed Peer Certificate Authority for Auth servers from exact match of my internal CA to Global Root CA List. Tried diagnostic -> auth - it works as expected, same it was works with exact math. While not work under OpenVPN. I can't test\change OpenVPN setting now, sorry, as there now many clients and I doesn't want to interrupt them. I will provide feedback later when I can restart OpenVPN.
Now I had workaround by creating one ldap.company.com Auth entry in pfSense which point to ldap.company.com. As I think it use SRV records to find dc1 and dc2 automatically. I was need to reissue for dc1 and for dc2 certs to get SubjAltName additional DNS=ldap.company.com and after this it works fine. To note: my Peer Certificate Authority in this workaround point to exactly my internal CA.
So this also one of possible workarounds till issue not resolved :).
Updated by DRago_Angel [InV@DER] over 3 years ago
Hi Viktor, changed OpenVPN settings to use 2 auth backends after adjust CA to Global CA list, and still same AUTH_FAILED. Change it back to only one (any of both) auth backend - all works. I changed OpenVPN log level to 6, but this not provide any details on why it fails.
Jan 4 01:03:29 openvpn 57180 MANAGEMENT: Client disconnected
Jan 4 01:03:29 openvpn 57180 MANAGEMENT: CMD 'quit'
Jan 4 01:03:28 openvpn 57180 MANAGEMENT: CMD 'status 2'
Jan 4 01:03:28 openvpn 57180 TCP/UDP: Closing socket
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 SIGUSR1[soft,connection-reset] received, client-instance restarting
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 Connection reset, restarting [0]
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [88] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=2655 DATA len=74
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [62] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 SENT CONTROL [*USERNAME*]: 'AUTH_FAILED' (status=1)
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 Delayed exit in 5 seconds
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 PUSH: Received control message: 'PUSH_REQUEST'
Jan 4 01:03:28 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [89] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=2911 DATA len=75
Jan 4 01:03:28 openvpn 57180 MANAGEMENT: Client connected from /var/etc/openvpn/server2/sock
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 [*USERNAME*] Peer Connection Initiated with [AF_INET6]::ffff:*CLIENTIP*:51086
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [289] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=2143 DATA len=275
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [224] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=1887 DATA len=210
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TLS: Username/Password authentication deferred for username '*USERNAME*' [CN SET]
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_GUI_VER=OpenVPN_GUI_11
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_TCPNL=1
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_COMP_STUBv2=1
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_COMP_STUB=1
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_LZO=1
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_LZ4v2=1
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_LZ4=1
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_CIPHERS=AES-256-GCM:AES-256-CBC:AES-128-GCM:AES-128-CBC
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_NCP=2
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_PROTO=6
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_PLAT=win
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 peer info: IV_VER=2.5.0
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [668] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=2143 DATA len=654
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [248] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=1631 DATA len=234
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [1112] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=1375 DATA len=1098
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [1112] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=1119 DATA len=1098
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [1112] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=863 DATA len=1098
Jan 4 01:03:27 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [1124] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=607 DATA len=1110
Jan 4 01:03:26 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [331] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_V1 kid=0 [ ] pid=863 DATA len=317
Jan 4 01:03:26 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [62] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_ACK_V1 kid=0 [ ]
Jan 4 01:03:26 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER WRITE [66] to [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=351 DATA len=52
Jan 4 01:03:26 openvpn 57180 *CLIENTIP*:51086 TLS: Initial packet from [AF_INET6]::ffff:*CLIENTIP*:51086, sid=43be6a3d 470c83a2
Jan 4 01:03:26 openvpn 57180 *CLIENTIP*:51086 TCPv6_SERVER READ [54] from [AF_INET6]::ffff:*CLIENTIP*:51086: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=351 DATA len=40
Jan 4 01:03:26 openvpn 57180 TCPv6_SERVER link remote: [AF_INET6]::ffff:*CLIENTIP*:51086
Jan 4 01:03:26 openvpn 57180 TCPv6_SERVER link local: (not bound)
Jan 4 01:03:26 openvpn 57180 TCP connection established with [AF_INET6]::ffff:*CLIENTIP*:51086
Jan 4 01:03:26 openvpn 57180 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1551,tun-mtu 1500,proto TCPv4_CLIENT,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
Jan 4 01:03:26 openvpn 57180 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1551,tun-mtu 1500,proto TCPv4_SERVER,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
Jan 4 01:03:26 openvpn 57180 Data Channel MTU parms [ L:1623 D:1450 EF:123 EB:406 ET:0 EL:3 ]
Jan 4 01:03:26 openvpn 57180 Control Channel MTU parms [ L:1623 D:1154 EF:96 EB:0 ET:0 EL:3 ]
Jan 4 01:03:26 openvpn 57180 Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jan 4 01:03:26 openvpn 57180 Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jan 4 01:03:26 openvpn 57180 Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jan 4 01:03:26 openvpn 57180 Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jan 4 01:03:26 openvpn 57180 Re-using SSL/TLS context
Jan 4 01:03:26 openvpn 57180 MULTI: multi_create_instance called
Also I found that in my log this 3 lines permanently spamming my pfsense log. It appear 5 times in one second and repeat endlessly with debug log enabled:
Jan 4 00:29:13 openvpn 29277 MANAGEMENT: Client disconnected
Jan 4 00:29:13 openvpn 29277 MANAGEMENT: CMD 'status 2'
Jan 4 00:29:13 openvpn 29277 MANAGEMENT: Client connected from /var/etc/openvpn/server2/sock
Is this fine for debug log level to spam rapidly such events?
Maybe if I provide openvpn config or auth server config this can help?
Or how I can debug plugin "/usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so /usr/local/sbin/ovpn_auth_verify_async" or "/etc/inc/openvpn.auth-user.php"?
If I rapidly run "cat /tmp/openvpn_acf_*" I can see that with both auth servers I get 0 (failed?) in tmp files and with only one server get 1 (success?) in reply which mean that this "/etc/inc/openvpn.auth-user.php" return incorrect response, yes?
To note:- I done testing when I was only one person who was used OpenVPN server.
- For me issue solved as workaround with one server which point to root of ldap domain, but I want help find root case of issue to fix this for other people :)
Updated by Jim Pingle over 3 years ago
- Status changed from New to Duplicate
- Target version deleted (
2.5.0)
Duplicate of #11104