Hello,
I am attempting to configure 2 factor authentication using Google
Authenticator + AD (Winbind), ultimately for use in my Cisco and Windows
VPN environment.
The environment is as follows:
-Fedora 22
-Freeradius 3.0.4
-Samba 4.2.2
Authentication using Winbind is successful and the journalCTL log files
verifies this as you will see below.
For testing purposes, I've disabled Google Authenticator line in the
/etc/pam.d/radiusd config file so I can focus on PAM_Winbind
functionality. This is the only line that I'm using.
----------------------
#/etc/pam.d/radius
auth required /usr/lib64/security/pam_winbind.so debug
----------------------
When I authenticate via radtest I get rejected:
------------
[root@hlsfreeradius01 ~]# radtest -x -t pap test-user-123 test-password
localhost 1812 testing123
Sending Access-Request Id 172 from 0.0.0.0:55300 to 127.0.0.1:1812
User-Name = 'test-user-123'
User-Password = 'test-password'
NAS-IP-Address = 10.101.1.8
NAS-Port = 1812
Message-Authenticator = 0x00
Received Access-Reject Id 172 from 127.0.0.1:1812 to 127.0.0.1:55300 length
20
(0) -: Expected Access-Accept got Access-Reject
--------------
Here is the JournalCTL output from Fedora that proves the winbind was
successful:
----------------------
Jul 24 16:37:25 hlsfreeradius01 radiusd[2995]: pam_winbind(radiusd:auth):
[pamh: 0x7f0bff4029c0] ENTER: pam_sm_authenticate (flags: 0x0000)
J
ul 24 16:37:25 hlsfreeradius01 radiusd[2995]: pam_winbind(radiusd:auth):
getting password (0x00000001)
Jul 24 16:37:25 hlsfreeradius01 radiusd[2995]: pam_winbind(radiusd:auth):
Verify user 'test-user-123'
Jul 24 16:37:25 hlsfreeradius01 radiusd[2995]: pam_winbind(radiusd:auth):
request wbcLogonUser succeeded
Jul 24 16:37:25 hlsfreeradius01 radiusd[2995]: pam_winbind(radiusd:auth):
user 'test-user-123' granted access
Jul 24 16:37:25 hlsfreeradius01 radiusd[2995]: pam_winbind(radiusd:auth):
Returned user was 'test-user-123'
Jul 24 16:37:25 hlsfreeradius01 radiusd[2995]: pam_winbind(radiusd:auth):
[pamh: 0x7f0bff4029c0] LEAVE: pam_sm_authenticate returning 0 (PAM_SUCCESS)
Jul 24 16:37:25 hlsfreeradius01 audit[2995]: <audit-1100> pid=2995 uid=0
auid=0 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
msg='op=PAM:authentication grantors=pam_winbind acct="test-user-123"
exe="/usr/sbin/radiusd" hostname=? addr=? terminal=pts/1 res=success'
Jul 24 16:37:25 hlsfreeradius01 audit[2995]: <audit-1101> pid=2995 uid=0
auid=0 ses=2 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023
msg='op=PAM:accounting grantors=? acct="test-user-123"
exe="/usr/sbin/radiusd" hostname=? addr=? terminal=pts/1 res=failed'
-----------------------
Specific radiusd -XXX log output showing the PAM user authentication
rejected:
-----------------------
Received Access-Request Id 172 from 127.0.0.1:55300 to 127.0.0.1:1812
length 78
User-Name = 'test-user-123'
User-Password = 'test-password'
NAS-IP-Address = 10.101.1.8
NAS-Port = 1812
Message-Authenticator = 0x82a2d0ae5c2192628b6263c968890117
Fri Jul 24 16:37:25 2015 : Debug: (0) Received Access-Request packet from
host 127.0.0.1 port 55300, id=172, length=78
Fri Jul 24 16:37:25 2015 : Debug: (0) User-Name = 'test-user-123'
Fri Jul 24 16:37:25 2015 : Debug: (0) User-Password = 'test-password'
Fri Jul 24 16:37:25 2015 : Debug: (0) NAS-IP-Address = 10.101.1.8
Fri Jul 24 16:37:25 2015 : Debug: (0) NAS-Port = 1812
Fri Jul 24 16:37:25 2015 : Debug: (0) Message-Authenticator =
0x82a2d0ae5c2192628b6263c968890117
Fri Jul 24 16:37:25 2015 : Debug: (0) # Executing section authorize from
file /etc/raddb/sites-enabled/default
Fri Jul 24 16:37:25 2015 : Debug: (0) authorize {
Fri Jul 24 16:37:25 2015 : Debug: (0) filter_username filter_username {
Fri Jul 24 16:37:25 2015 : Debug: (0) if (!&User-Name)
Fri Jul 24 16:37:25 2015 : Debug: (0) if (!&User-Name) -> FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ / /)
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ / /) -> FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /@.*@/ )
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /@.*@/ ) ->
FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /\\.\\./ )
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /\\.\\./ ) ->
FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) if ((&User-Name =~ /@/) &&
(&User-Name !~ /(a)(.+)\\.(.+)$/))
Fri Jul 24 16:37:25 2015 : Debug: (0) if ((&User-Name =~ /@/) &&
(&User-Name !~ /(a)(.+)\\.(.+)$/)) -> FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /\\.$/)
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /\\.$/) ->
FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /(a)\\./)
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&User-Name =~ /(a)\\./) ->
FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) } # filter_username filter_username
= notfound
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [preprocess] = ok
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling chap
(rlm_chap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
chap (rlm_chap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [chap] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling mschap
(rlm_mschap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
mschap (rlm_mschap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [mschap] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling suffix
(rlm_realm) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) suffix : Checking for suffix after
"@"
Fri Jul 24 16:37:25 2015 : Debug: (0) suffix : No '@' in User-Name =
"test-user-123", looking up realm NULL
Fri Jul 24 16:37:25 2015 : Debug: (0) suffix : No such realm "NULL"
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
suffix (rlm_realm) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [suffix] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling eap
(rlm_eap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) eap : No EAP-Message, not doing EAP
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
eap (rlm_eap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [eap] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling files
(rlm_files) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) files : users: Matched entry DEFAULT
at line 182
Fri Jul 24 16:37:25 2015 : Debug: (0) files : ::: FROM 0 TO 0 MAX 0
Fri Jul 24 16:37:25 2015 : Debug: (0) files : ::: TO in 0 out 0
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
files (rlm_files) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [files] = ok
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling
expiration (rlm_expiration) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
expiration (rlm_expiration) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [expiration] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling
logintime (rlm_logintime) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
logintime (rlm_logintime) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [logintime] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: calling pap
(rlm_pap) for request 0
Fri Jul 24 16:37:25 2015 : WARNING: (0) pap : No "known good" password
found for the user. Not setting Auth-Type
Fri Jul 24 16:37:25 2015 : WARNING: (0) pap : Authentication will fail
unless a "known good" password is available
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authorize]: returned from
pap (rlm_pap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [pap] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) } # authorize = ok
#PAM authentication sequence begins
Fri Jul 24 16:37:25 2015 : Debug: (0) Found Auth-Type = PAM
Fri Jul 24 16:37:25 2015 : Debug: (0) # Executing group from file
/etc/raddb/sites-enabled/default
Fri Jul 24 16:37:25 2015 : Debug: (0) authenticate {
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authenticate]: calling pam
(rlm_pam) for request 0
Fri Jul 24 16:37:25 2015 : Debug: pam_pass: using pamauth string <radiusd>
for pam.conf lookup
Fri Jul 24 16:37:25 2015 : Debug: pam_pass: function pam_acct_mgmt FAILED
for <test-user-123>. Reason: Authentication failure
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[authenticate]: returned
from pam (rlm_pam) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [pam] = reject
Fri Jul 24 16:37:25 2015 : Debug: (0) } # authenticate = reject
Fri Jul 24 16:37:25 2015 : Debug: (0) Failed to authenticate the user
Fri Jul 24 16:37:25 2015 : Auth: (0) Login incorrect:
[test-user-123/test-password] (from client localhost port 1812)
Fri Jul 24 16:37:25 2015 : Debug: (0) Using Post-Auth-Type Reject
Fri Jul 24 16:37:25 2015 : Debug: (0) # Executing group from file
/etc/raddb/sites-enabled/default
Fri Jul 24 16:37:25 2015 : Debug: (0) Post-Auth-Type REJECT {
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[post-auth]: calling
attr_filter.access_reject (rlm_attr_filter) for request 0
Fri Jul 24 16:37:25 2015 : Debug: %{User-Name}
Fri Jul 24 16:37:25 2015 : Debug: Parsed xlat tree:
Fri Jul 24 16:37:25 2015 : Debug: attribute --> User-Name
Fri Jul 24 16:37:25 2015 : Debug: (0) attr_filter.access_reject : EXPAND
%{User-Name}
Fri Jul 24 16:37:25 2015 : Debug: (0) attr_filter.access_reject : -->
test-user-123
Fri Jul 24 16:37:25 2015 : Debug: (0) attr_filter.access_reject : Matched
entry DEFAULT at line 11
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[post-auth]: returned from
attr_filter.access_reject (rlm_attr_filter) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [attr_filter.access_reject] =
updated
# Ends
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[post-auth]: calling eap
(rlm_eap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) eap : Request didn't contain an
EAP-Message, not inserting EAP-Failure
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[post-auth]: returned from
eap (rlm_eap) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [eap] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) remove_reply_message_if_eap
remove_reply_message_if_eap {
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&reply:EAP-Message &&
&reply:Reply-Message)
Fri Jul 24 16:37:25 2015 : Debug: (0) if (&reply:EAP-Message &&
&reply:Reply-Message) -> FALSE
Fri Jul 24 16:37:25 2015 : Debug: (0) else else {
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[post-auth]: calling noop
(rlm_always) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) modsingle[post-auth]: returned from
noop (rlm_always) for request 0
Fri Jul 24 16:37:25 2015 : Debug: (0) [noop] = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) } # else else = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) } # remove_reply_message_if_eap
remove_reply_message_if_eap = noop
Fri Jul 24 16:37:25 2015 : Debug: (0) } # Post-Auth-Type REJECT = updated
Fri Jul 24 16:37:25 2015 : Debug: (0) Delaying response for 1 seconds
Fri Jul 24 16:37:25 2015 : Debug: Waking up in 0.2 seconds.
Fri Jul 24 16:37:26 2015 : Debug: Waking up in 0.7 seconds.
Fri Jul 24 16:37:26 2015 : Debug: (0) Sending delayed response
Fri Jul 24 16:37:26 2015 : Debug: (0) Sending Access-Reject packet to host
127.0.0.1 port 55300, id=172, length=0
Sending Access-Reject Id 172 from 127.0.0.1:1812 to 127.0.0.1:55300
Fri Jul 24 16:37:26 2015 : Debug: Waking up in 3.9 seconds.
Fri Jul 24 16:37:30 2015 : Debug: (0) Cleaning up request packet ID 172
with timestamp +26
Fri Jul 24 16:37:30 2015 : Info: Ready to process requests
----------------
Standard NTLM via AD works very well, but utilizing the PAM module is
creating a whole new can of worms. My use case for PAM is 2 factor
authentication with Google Authenticator, but if there is a better way to
do this while still utilizing FreeRadius, then I am very interested.
However, at this point I have not been unable to find another
authentication methodology for Google OTP without the PAM component.
If anyone is able to shed some light on the existing authentication issue I
described, or even suggest a better way of doing this 2FA sequence in
question, I would be extremely grateful.
Also attaching the, radius -XXX startup output separately.
Have a great weekend.
-Josh