Winbind AD authentication failing

douglasarc · Post by **douglasarc** » Tue Aug 10, 2021 4:42 pm

Hello there, I'm new to the community so apologies if my post isn't formatted correctly.

I'm running OpenVPN on an Ubuntu 18.04 server, which is configured for AD auth using Winbind. The VM is domain bound and auth for access works perfectly. I'm trying to leverage Winbind + PAM + my newly created AD group to authenticate my VPN clients as well.

In the logs I can see their requests and passwords being received/passed, and auth.logs even shows me that auth suceeded, but it seems that the openvpn service never hears back so it just hangs there and, eventually, it times out and closes the client connection (please, see below).

Code: Select all

Aug 10 16:20:54 ops-b9-vpn01 openvpn[30012]: pam_winbind(openvpn:auth): getting password (0x000023c8)
Aug 10 16:20:55 ops-b9-vpn01 openvpn[30012]: pam_winbind(openvpn:auth): user 'this.user' granted access

Code: Select all

Tue Aug 10 16:20:54 2021 us=90805 <client.ip>:26045 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server'
Tue Aug 10 16:20:54 2021 us=90812 <client.ip>:26045 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1558,tun-mtu 1500,proto UDPv4,comp-lzo,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client'
RTue Aug 10 16:20:54 2021 us=90855 <client.ip>:26045 TLS: Initial packet from [AF_INET]
Tue Aug 10 16:20:54 2021 us=486329 <client.ip>:26045 VERIFY OK: 
Tue Aug 10 16:20:54 2021 us=486458 <client.ip>:26045 peer info: IV_VER=2.4.11
Tue Aug 10 16:20:54 2021 us=486468 <client.ip>:26045 peer info: IV_PLAT=win
Tue Aug 10 16:20:54 2021 us=486474 <client.ip>:26045 peer info: IV_PROTO=2
Tue Aug 10 16:20:54 2021 us=486479 <client.ip>:26045 peer info: IV_NCP=2
Tue Aug 10 16:20:54 2021 us=486485 <client.ip>:26045 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:AES-256-CBC
Tue Aug 10 16:20:54 2021 us=486511 <client.ip>:26045 peer info: IV_LZ4=1
Tue Aug 10 16:20:54 2021 us=486517 <client.ip>:26045 peer info: IV_LZ4v2=1
Tue Aug 10 16:20:54 2021 us=486522 <client.ip>:26045 peer info: IV_LZO=1
Tue Aug 10 16:20:54 2021 us=486527 <client.ip>:26045 peer info: IV_COMP_STUB=1
Tue Aug 10 16:20:54 2021 us=486532 <client.ip>:26045 peer info: IV_COMP_STUBv2=1
Tue Aug 10 16:20:54 2021 us=486537 <client.ip>:26045 peer info: IV_TCPNL=1
Tue Aug 10 16:20:54 2021 us=486542 <client.ip>:26045 peer info: IV_GUI_VER=Viscosity_1.9.3_1723
AUTH-PAM: BACKGROUND: received command code: 0
AUTH-PAM: BACKGROUND: USER: this.user
AUTH-PAM: BACKGROUND: my_conv[0] query='Password: ' style=1
Tue Aug 10 16:20:55 2021 us=397117 <client.ip>:26045 PLUGIN_CALL: POST /usr/lib/openvpn/openvpn-plugin-auth-pam.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
Tue Aug 10 16:20:55 2021 us=397174 <client.ip>:26045 TLS: Username/Password authentication deferred for username 'this.user' [CN SET]
WWRRTue Aug 10 16:20:55 2021 us=602547 <client.ip>:26045 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Tue Aug 10 16:20:55 2021 us=602593 <client.ip>:26045 [this.user] Peer Connection Initiated with [AF_INET]<client.ip>:26045
RTue Aug 10 16:20:55 2021 us=602775 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:20:56 2021 us=980659 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:20:58 2021 us=368416 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:20:58 2021 us=580977 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:20:59 2021 us=958150 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:01 2021 us=344457 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:01 2021 us=554665 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:02 2021 us=938694 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:04 2021 us=325416 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:04 2021 us=533833 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:06 2021 us=595 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:07 2021 us=465200 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:08 2021 us=928588 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:10 2021 us=392887 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:10 2021 us=603265 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:12 2021 us=57080 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:13 2021 us=524467 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:14 2021 us=800598 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:16 2021 us=51234 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:17 2021 us=311071 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:17 2021 us=522885 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:18 2021 us=793272 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:20 2021 us=54148 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:21 2021 us=323631 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:21 2021 us=530672 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:22 2021 us=799023 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:24 2021 us=62242 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:25 2021 us=385080 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:25 2021 us=594184 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:26 2021 us=911793 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:28 2021 us=233621 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:29 2021 us=543198 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:30 2021 us=855143 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:32 2021 us=167348 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:33 2021 us=489242 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:34 2021 us=718757 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:35 2021 us=957763 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:37 2021 us=193322 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:38 2021 us=421934 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:38 2021 us=637201 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:39 2021 us=857327 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:41 2021 us=89443 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:42 2021 us=319285 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:42 2021 us=508576 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:43 2021 us=722150 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:45 2021 us=48430 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:46 2021 us=380536 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:46 2021 us=581291 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:47 2021 us=920983 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:49 2021 us=259462 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:50 2021 us=586687 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:51 2021 us=916276 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:53 2021 us=244394 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 16:21:54 2021 us=574330 <client.ip>:26045 PUSH: Received control message: 'PUSH_REQUEST'
Tue Aug 10 16:21:54 2021 us=574368 <client.ip>:26045 Delayed exit in 5 seconds
Tue Aug 10 16:21:54 2021 us=574383 <client.ip>:26045 SENT CONTROL [this.user]: 'AUTH_FAILED' (status=1)
WWWTue Aug 10 16:21:59 2021 us=881557 <client.ip>:26045 SIGTERM[soft,delayed-exit] received, client-instance exiting

My understanding is that invocation / data flow should work like: OpenVPN > auth-plugin > pam > winbind (AD auth). Configuration looks like:

Code: Select all

mode server
ca /etc/openvpn/branch/keys/ca.crt
cert /etc/openvpn/branch/keys/server.crt
key /etc/openvpn/branch/keys/server.key
dh /etc/openvpn/branch/keys/dh2048.pem
crl-verify /etc/openvpn/branch/crl.pem
proto udp
port 1194
comp-lzo
group nogroup
user nobody
log-append /var/log/openvpn/branch.log
status /var/log/openvpn-status.log
status-version 2
dev tun0
local <server.ip>
server 172.20.48.0 255.255.255.0
push "dhcp-option DOMAIN <domain>"
push "route <route1>"
push "route <route2>"
push "dhcp-option DNS <dns1.ip>"
push "dhcp-option DNS <dns2.ip>"
keepalive 10 120
topology subnet
verb 5
cipher AES-256-CBC
tls-cipher TLS-DHE-RSA-WITH-AES-256-GCM-SHA384:TLS-DHE-RSA-WITH-AES-256-CBC-SHA256:TLS-DHE-RSA-WITH-AES-128-GCM-SHA256:TLS-DHE-RSA-WITH-AES-128-CBC-SHA256
persist-key
persist-tun
plugin /usr/lib/openvpn/openvpn-plugin-auth-pam.so openvpn
management localhost unix
username-as-common-name
duplicate-cn

# Additional custom options
management-client-auth
reneg-sec 36000

Code: Select all

user@ops-b9-vpn01:~$ sudo cat /etc/pam.d/openvpn
auth            required        /lib/x86_64-linux-gnu/security/pam_winbind.so  require_membership_of=S-1-5-21-2145081466-1512320950-1280385560-43151

I have set verbosity level to 9, but nothing different between invocation of the auth-plugin and never hearing as response back. Could this be something missing on the DC side? Any help here would be much appreciated. Thank you!

TinCanTech · Post by **TinCanTech** » Tue Aug 10, 2021 4:53 pm

See --auth-user-pass-verify in the manual.

douglasarc · Post by **douglasarc** » Tue Aug 10, 2021 7:08 pm

@TinCanTech, thanks for your reply. I got the impression that the auth-user-pass-verify and plugin options were mutually exclusive.
https://openvpn.net/community-resources ... on-methods

In any case, I tried swapping to the auth-pam.pl, but got the exact same behavior.

Code: Select all

Tue Aug 10 18:15:16 2021 us=279068 client.ip:28049 peer info: IV_GUI_VER=Viscosity_1.9.3_1723
Tue Aug 10 18:15:17 2021 us=49389 client.ip:28049 TLS: Username/Password authentication deferred for username 'this.user' [CN SET]
WWRRTue Aug 10 18:15:17 2021 us=239707 client.ip:28049 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384, 2048 bit RSA
Tue Aug 10 18:15:17 2021 us=239759 client.ip:28049 [this.user] Peer Connection Initiated with [AF_INET]client.ip:28049
RTue Aug 10 18:15:17 2021 us=239873 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:18 2021 us=470478 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:18 2021 us=664958 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:19 2021 us=897862 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:21 2021 us=120539 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:22 2021 us=351166 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:22 2021 us=541262 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:23 2021 us=765671 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:24 2021 us=995789 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:26 2021 us=228195 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:27 2021 us=473822 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:27 2021 us=665448 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:28 2021 us=918637 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'
WRTue Aug 10 18:15:30 2021 us=164606 client.ip:28049 PUSH: Received control message: 'PUSH_REQUEST'

Any other thoughts? Thank you.

TinCanTech · Post by **TinCanTech** » Tue Aug 10, 2021 8:03 pm

douglasarc wrote: ↑
Tue Aug 10, 2021 7:08 pm
I got the impression that the auth-user-pass-verify and plugin options were mutually exclusive

I think you are correct but at least you read the documentation.

Which version of openvpn is your server running ?

douglasarc · Post by **douglasarc** » Tue Aug 10, 2021 9:11 pm

Which version of openvpn is your server running ?

That would be:

Code: Select all

openvpn/bionic-updates,now 2.4.4-2ubuntu1.6 amd64 [installed]

TinCanTech · Post by **TinCanTech** » Tue Aug 10, 2021 9:37 pm

You might like to try version 2.5 soon ..

Anyway, maybe there is something useful to be found here:
https://github.com/OpenVPN/openvpn/tree ... s/auth-pam

OpenVPN Support Forum

Winbind AD authentication failing

Winbind AD authentication failing

Re: Winbind AD authentication failing

Re: Winbind AD authentication failing

Re: Winbind AD authentication failing

Re: Winbind AD authentication failing

Re: Winbind AD authentication failing