Freeradius on AWS ECS Fargate problem to authenticate using EAP-PEAP (MSCHAPv2) - Reading winbind reply failed! (0xc0000001)
Antonio Castillo
antonio at yieldmo.com
Mon May 13 20:13:57 CEST 2019
Hello all!,
I am trying to use Freeradius to authenticate our wifi clients against
AWS Simple AD server using EAP-PEAP (MSCHAPv2)
The tricky part is that I'm trying to run Freeradius in a AWS ECS
Fargate service container.
I'm using the Freeradius Docker Hub image:
https://hub.docker.com/r/freeradius/freeradius-server
Container OS version:
root at b17cc3ba869c:/etc/freeradius# cat /etc/*release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=18.04
I have a test EC2 instance running Freeradius that it's working fine,
I can connect to the WiFi network using my Simple AD credentials with
no issues.
I built this test EC2 box to know exactly what needs to be done in
order to use Freeradius for authentication and add the necessary steps
to the Dockerfile for the Freeradius container.
On Fargate, the problem seems to be caused by winbind
On EC2, winbind works just fine.
This is the winbind error:
Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Program returned code
(1) and output 'Reading winbind reply failed! (0xc0000001)'
Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Reading winbind reply
failed! (0xc0000001)
Mon May 13 17:06:00 2019 : Debug: (3) mschap: Authentication failed
(full freeradius debug log added at the end of this email)
radtest works fine for pap:
$ radtest antonio '<MY_PASSWORD>' 10.0.153.139 0 <MY_SECRET>
Sent Access-Request Id 88 from 0.0.0.0:61601 to 10.0.153.139:1812 length 77
User-Name = "antonio"
User-Password = "<MY_PASSWORD>"
NAS-IP-Address = 127.0.0.1
NAS-Port = 0
Message-Authenticator = 0x00
Cleartext-Password = "<MY_PASSWORD>"
Received Access-Accept Id 88 from 10.0.153.139:1812 to
172.16.0.54:61601 length 36
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "10"
but it fails with mschap:
$ radtest -t mschap antonio '<MY_PASSWORD>' 10.0.153.139 0 <MY_SECRET>
Sent Access-Request Id 7 from 0.0.0.0:61367 to 10.0.153.139:1812 length 133
User-Name = "antonio"
MS-CHAP-Password = "<MY_PASSWORD>"
NAS-IP-Address = 127.0.0.1
NAS-Port = 0
Message-Authenticator = 0x00
Cleartext-Password = "<MY_PASSWORD>"
MS-CHAP-Challenge = 0x2e3ecfc58cff680f
MS-CHAP-Response =
0x0001000000000000000000000000000000000000000000000000c067bb42d3a35102436e299186f135f6f664ea811f2a148f
Received Access-Reject Id 7 from 10.0.153.139:1812 to
172.16.0.54:61367 length 77
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "10"
MS-CHAP-Error = "\000E=691 R=1 C=ed4c6cae95574d22 V=2"
(0) -: Expected Access-Accept got Access-Reject
I have added the 'freerad' user to the 'winbindd_priv' group and
changed the permissions to 'root:winbindd_priv' on
/var/lib/samba/winbindd_privileged/ as someone suggested on this link:
https://xenomorph.net/linux/samba/issues/exec-program-output-reading-winbind-reply-failed/
Also added some debugging lines to confirm that in fact the
permissions and group changes are taking place and they did.
Could it be that winbind wasn't made to be executed in a docker container?
As I mentioned before, Freeradius is working fine when running on an
EC2 instance, it runs fine in a docker container too, but winbind
fails when running in a container.
Any ideas?
Thank you.
Regards,
Tono
Here are the logs when trying to authenticate using mschap with
radtest from my laptop.
from /var/log/freeradius/radius.log in debug mode:
Mon May 13 17:06:00 2019 : Debug: (3) Received Access-Request Id 7
from 10.0.0.191:61367 to 10.0.153.139:1812 length 133
Mon May 13 17:06:00 2019 : Debug: (3) User-Name = "antonio"
Mon May 13 17:06:00 2019 : Debug: (3) NAS-IP-Address = 127.0.0.1
Mon May 13 17:06:00 2019 : Debug: (3) NAS-Port = 0
Mon May 13 17:06:00 2019 : Debug: (3) Message-Authenticator =
0xc70ca8663c85700b5a484bcd4cd5931d
Mon May 13 17:06:00 2019 : Debug: (3) MS-CHAP-Challenge = 0x2e3ecfc58cff680f
Mon May 13 17:06:00 2019 : Debug: (3) MS-CHAP-Response =
0x0001000000000000000000000000000000000000000000000000c067bb42d3a35102436e299186f135f6f664ea811f2a148f
Mon May 13 17:06:00 2019 : Debug: (3) session-state: No State attribute
Mon May 13 17:06:00 2019 : Debug: (3) # Executing section authorize
from file /etc/freeradius/sites-enabled/default
Mon May 13 17:06:00 2019 : Debug: (3) authorize {
Mon May 13 17:06:00 2019 : Debug: (3) policy filter_username {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name) -> TRUE
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ / /) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ / /) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /@[^@]*@/ ) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.\./ ) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.\./ ) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) {
Mon May 13 17:06:00 2019 : Debug: (3) if ((&User-Name =~ /@/) &&
(&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.$/) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /\.$/) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /@\./) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /@\./) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) } # if (&User-Name) = notfound
Mon May 13 17:06:00 2019 : Debug: (3) } # policy filter_username = notfound
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
preprocess (rlm_preprocess)
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from preprocess (rlm_preprocess)
Mon May 13 17:06:00 2019 : Debug: (3) [preprocess] = ok
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
chap (rlm_chap)
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from chap (rlm_chap)
Mon May 13 17:06:00 2019 : Debug: (3) [chap] = noop
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
mschap (rlm_mschap)
Mon May 13 17:06:00 2019 : Debug: (3) mschap: Found MS-CHAP
attributes. Setting 'Auth-Type = mschap'
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from mschap (rlm_mschap)
Mon May 13 17:06:00 2019 : Debug: (3) [mschap] = ok
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
digest (rlm_digest)
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from digest (rlm_digest)
Mon May 13 17:06:00 2019 : Debug: (3) [digest] = noop
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
suffix (rlm_realm)
Mon May 13 17:06:00 2019 : Debug: (3) suffix: Checking for suffix after "@"
Mon May 13 17:06:00 2019 : Debug: (3) suffix: No '@' in User-Name =
"antonio", looking up realm NULL
Mon May 13 17:06:00 2019 : Debug: (3) suffix: No such realm "NULL"
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from suffix (rlm_realm)
Mon May 13 17:06:00 2019 : Debug: (3) [suffix] = noop
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
eap (rlm_eap)
Mon May 13 17:06:00 2019 : Debug: (3) eap: No EAP-Message, not doing EAP
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from eap (rlm_eap)
Mon May 13 17:06:00 2019 : Debug: (3) [eap] = noop
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
files (rlm_files)
Mon May 13 17:06:00 2019 : Debug: (3) files: Searching for user in
group "CN=VLAN Accounting,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com"
Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Closing connection
(11): Hit idle_timeout, was idle for 395 seconds
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): You probably need
to lower "min"
Mon May 13 17:06:00 2019 : Debug: rlm_ldap: Closing libldap handle
0x7f6ef4001150
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): 0 of 0 connections
in use. You may need to increase "spare"
Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Opening additional
connection (12), 1 of 32 pending slots used
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Connecting to
ldap://10.0.151.172:389
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): New libldap handle
0x7f6ee80010b0
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result...
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Reserved connection (12)
Mon May 13 17:06:00 2019 : Debug:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree:
Mon May 13 17:06:00 2019 : Debug: literal --> (sAMAccountName=
Mon May 13 17:06:00 2019 : Debug: XLAT-IF {
Mon May 13 17:06:00 2019 : Debug: attribute --> Stripped-User-Name
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE {
Mon May 13 17:06:00 2019 : Debug: attribute --> User-Name
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: literal --> )
Mon May 13 17:06:00 2019 : Debug: (3) files: EXPAND
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
Mon May 13 17:06:00 2019 : Debug: (3) files: --> (sAMAccountName=antonio)
Mon May 13 17:06:00 2019 : Debug: (3) files: Performing search in
"DC=ldap,DC=yieldmo,DC=com" with filter "(sAMAccountName=antonio)",
scope "sub"
Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result...
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Rebinding to URL
ldap://ldap.yieldmo.com/CN=Configuration,DC=ldap,DC=yieldmo,DC=com
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result...
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful
Mon May 13 17:06:00 2019 : Debug: (3) files: User object found at DN
"CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com"
Mon May 13 17:06:00 2019 : Debug: (3) files: Checking for user in group objects
Mon May 13 17:06:00 2019 : Debug:
(&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn}))))
Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree:
Mon May 13 17:06:00 2019 : Debug: literal -->
(&(objectClass=Group)(|(&(objectClass=group)(member=
Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN
Mon May 13 17:06:00 2019 : Debug: literal -->
))(&(objectClass=top)(uniquemember=
Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN
Mon May 13 17:06:00 2019 : Debug: literal --> ))))
Mon May 13 17:06:00 2019 : Debug: (3) files: EXPAND
(&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn}))))
Mon May 13 17:06:00 2019 : Debug: (3) files: -->
(&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))))
Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for bind result...
Mon May 13 17:06:00 2019 : Debug: (3) files: Bind successful
Mon May 13 17:06:00 2019 : Debug: (3) files: Performing search in
"CN=VLAN Accounting,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" with
filter "(&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))))",
scope "sub"
Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result...
Mon May 13 17:06:00 2019 : Debug: (3) files: Search returned no results
Mon May 13 17:06:00 2019 : Debug: (3) files: Checking user object's
memberOf attributes
Mon May 13 17:06:00 2019 : Debug: (3) files: Performing unfiltered
search in "CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com", scope
"base"
Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result...
Mon May 13 17:06:00 2019 : Debug: (3) files: Processing memberOf value
"CN=VLAN Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com" as
a DN
Mon May 13 17:06:00 2019 : Debug: (3) files: Processing memberOf value
"CN=XWikiAdmins,OU=xwiki,OU=Groups,DC=ldap,DC=yieldmo,DC=com" as a DN
Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Deleting connection
(12) - Was referred to a different LDAP server
Mon May 13 17:06:00 2019 : Debug: rlm_ldap: Closing libldap handle
0x7f6ee80010b0
Mon May 13 17:06:00 2019 : Info: Need 3 more connections to reach min
connections (3)
Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Opening additional
connection (13), 1 of 32 pending slots used
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Connecting to
ldap://10.0.151.172:389
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): New libldap handle
0x7f6ee80010b0
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result...
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful
Mon May 13 17:06:00 2019 : Debug: (3) files: User is not a member of
"CN=VLAN Accounting,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com"
Mon May 13 17:06:00 2019 : Debug: (3) files: Searching for user in
group "CN=VLAN Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com"
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Reserved connection (13)
Mon May 13 17:06:00 2019 : Debug: (3) files: Using user DN from
request "CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com"
Mon May 13 17:06:00 2019 : Debug: (3) files: Checking for user in group objects
Mon May 13 17:06:00 2019 : Debug:
(&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn}))))
Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree:
Mon May 13 17:06:00 2019 : Debug: literal -->
(&(objectClass=Group)(|(&(objectClass=group)(member=
Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN
Mon May 13 17:06:00 2019 : Debug: literal -->
))(&(objectClass=top)(uniquemember=
Mon May 13 17:06:00 2019 : Debug: attribute --> LDAP-UserDN
Mon May 13 17:06:00 2019 : Debug: literal --> ))))
Mon May 13 17:06:00 2019 : Debug: (3) files: EXPAND
(&(objectClass=Group)(|(&(objectClass=group)(member=%{control:Ldap-UserDn}))(&(objectClass=top)(uniquemember=%{control:Ldap-UserDn}))))
Mon May 13 17:06:00 2019 : Debug: (3) files: -->
(&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))))
Mon May 13 17:06:00 2019 : Debug: (3) files: Performing search in
"CN=VLAN Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com"
with filter "(&(objectClass=Group)(|(&(objectClass=group)(member=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))(&(objectClass=top)(uniquemember=CN\3dantonio\2cCN\3dUsers\2cDC\3dldap\2cDC\3dyieldmo\2cDC\3dcom))))",
scope "sub"
Mon May 13 17:06:00 2019 : Debug: (3) files: Waiting for search result...
Mon May 13 17:06:00 2019 : Debug: (3) files: User found in group
object "CN=VLAN
Engineering,OU=VLANs,OU=Groups,DC=ldap,DC=yieldmo,DC=com"
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Released connection (13)
Mon May 13 17:06:00 2019 : Debug: (3) files: users: Matched entry
DEFAULT at line 225
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from files (rlm_files)
Mon May 13 17:06:00 2019 : Debug: (3) [files] = ok
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
ldap (rlm_ldap)
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Reserved connection (13)
Mon May 13 17:06:00 2019 : Debug:
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree:
Mon May 13 17:06:00 2019 : Debug: literal --> (sAMAccountName=
Mon May 13 17:06:00 2019 : Debug: XLAT-IF {
Mon May 13 17:06:00 2019 : Debug: attribute --> Stripped-User-Name
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE {
Mon May 13 17:06:00 2019 : Debug: attribute --> User-Name
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: literal --> )
Mon May 13 17:06:00 2019 : Debug: (3) ldap: EXPAND
(sAMAccountName=%{%{Stripped-User-Name}:-%{User-Name}})
Mon May 13 17:06:00 2019 : Debug: (3) ldap: --> (sAMAccountName=antonio)
Mon May 13 17:06:00 2019 : Debug: (3) ldap: Performing search in
"DC=ldap,DC=yieldmo,DC=com" with filter "(sAMAccountName=antonio)",
scope "sub"
Mon May 13 17:06:00 2019 : Debug: (3) ldap: Waiting for search result...
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Rebinding to URL
ldap://ldap.yieldmo.com/CN=Configuration,DC=ldap,DC=yieldmo,DC=com
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Waiting for bind result...
Mon May 13 17:06:00 2019 : Debug: rlm_ldap (ldap): Bind successful
Mon May 13 17:06:00 2019 : Debug: (3) ldap: User object found at DN
"CN=antonio,CN=Users,DC=ldap,DC=yieldmo,DC=com"
Mon May 13 17:06:00 2019 : Debug: (3) ldap: Processing user attributes
Mon May 13 17:06:00 2019 : Debug: (3) ldap:
control:Password-With-Header +=
'{SSHA}6OROoSPG9FfFPEm6nEGhpm37x4hOSGJi'
Mon May 13 17:06:00 2019 : Info: rlm_ldap (ldap): Deleting connection
(13) - Was referred to a different LDAP server
Mon May 13 17:06:00 2019 : Debug: rlm_ldap: Closing libldap handle
0x7f6ee80010b0
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from ldap (rlm_ldap)
Mon May 13 17:06:00 2019 : Debug: (3) [ldap] = updated
Mon May 13 17:06:00 2019 : Debug: (3) if ((ok || updated) && User-Password) {
Mon May 13 17:06:00 2019 : Debug: (3) if ((ok || updated) &&
User-Password) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
expiration (rlm_expiration)
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from expiration (rlm_expiration)
Mon May 13 17:06:00 2019 : Debug: (3) [expiration] = noop
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
logintime (rlm_logintime)
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from logintime (rlm_logintime)
Mon May 13 17:06:00 2019 : Debug: (3) [logintime] = noop
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: calling
pap (rlm_pap)
Mon May 13 17:06:00 2019 : Debug: (3) pap: Converted:
&control:Password-With-Header =
'{SSHA}6OROoSPG9FfFPEm6nEGhpm37x4hOSGJi' -> &control:SSHA1-Password =
'0x364f524f6f5350473946664650456d366e454768706d33377834684f53474a69'
Mon May 13 17:06:00 2019 : Debug: (3) pap: Removing
&control:Password-With-Header
Mon May 13 17:06:00 2019 : Debug: (3) pap: Normalizing SSHA1-Password
from base64 encoding, 32 bytes -> 24 bytes
Mon May 13 17:06:00 2019 : WARNING: (3) pap: Auth-Type already set.
Not setting to PAP
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authorize]: returned
from pap (rlm_pap)
Mon May 13 17:06:00 2019 : Debug: (3) [pap] = noop
Mon May 13 17:06:00 2019 : Debug: (3) } # authorize = updated
Mon May 13 17:06:00 2019 : Debug: (3) Found Auth-Type = mschap
Mon May 13 17:06:00 2019 : Debug: (3) # Executing group from file
/etc/freeradius/sites-enabled/default
Mon May 13 17:06:00 2019 : Debug: (3) authenticate {
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authenticate]: calling
mschap (rlm_mschap)
Mon May 13 17:06:00 2019 : Debug: (3) mschap: Client is using
MS-CHAPv1 with NT-Password
Mon May 13 17:06:00 2019 : Debug: (3) mschap: Executing:
/usr/bin/ntlm_auth --request-nt-key
--username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}}
--challenge=%{%{mschap:Challenge}:-00}
--nt-response=%{%{mschap:NT-Response}:-00}:
Mon May 13 17:06:00 2019 : Debug:
--username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}}
Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree:
Mon May 13 17:06:00 2019 : Debug: literal --> --username=
Mon May 13 17:06:00 2019 : Debug: XLAT-IF {
Mon May 13 17:06:00 2019 : Debug: attribute --> Stripped-User-Name
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE {
Mon May 13 17:06:00 2019 : Debug: XLAT-IF {
Mon May 13 17:06:00 2019 : Debug: attribute --> User-Name
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE {
Mon May 13 17:06:00 2019 : Debug: literal --> None
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: (3) mschap: EXPAND
--username=%{%{Stripped-User-Name}:-%{%{User-Name}:-None}}
Mon May 13 17:06:00 2019 : Debug: (3) mschap: --> --username=antonio
Mon May 13 17:06:00 2019 : Debug: --challenge=%{%{mschap:Challenge}:-00}
Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree:
Mon May 13 17:06:00 2019 : Debug: literal --> --challenge=
Mon May 13 17:06:00 2019 : Debug: XLAT-IF {
Mon May 13 17:06:00 2019 : Debug: xlat --> mschap
Mon May 13 17:06:00 2019 : Debug: {
Mon May 13 17:06:00 2019 : Debug: literal --> Challenge
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE {
Mon May 13 17:06:00 2019 : Debug: literal --> 00
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: (3) mschap: mschap1: 2e
Mon May 13 17:06:00 2019 : Debug: (3) mschap: EXPAND
--challenge=%{%{mschap:Challenge}:-00}
Mon May 13 17:06:00 2019 : Debug: (3) mschap: --> --challenge=2e3ecfc58cff680f
Mon May 13 17:06:00 2019 : Debug: --nt-response=%{%{mschap:NT-Response}:-00}
Mon May 13 17:06:00 2019 : Debug: Parsed xlat tree:
Mon May 13 17:06:00 2019 : Debug: literal --> --nt-response=
Mon May 13 17:06:00 2019 : Debug: XLAT-IF {
Mon May 13 17:06:00 2019 : Debug: xlat --> mschap
Mon May 13 17:06:00 2019 : Debug: {
Mon May 13 17:06:00 2019 : Debug: literal --> NT-Response
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: XLAT-ELSE {
Mon May 13 17:06:00 2019 : Debug: literal --> 00
Mon May 13 17:06:00 2019 : Debug: }
Mon May 13 17:06:00 2019 : Debug: (3) mschap: EXPAND
--nt-response=%{%{mschap:NT-Response}:-00}
Mon May 13 17:06:00 2019 : Debug: (3) mschap: -->
--nt-response=c067bb42d3a35102436e299186f135f6f664ea811f2a148f
Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Program returned code
(1) and output 'Reading winbind reply failed! (0xc0000001)'
Mon May 13 17:06:00 2019 : ERROR: (3) mschap: Reading winbind reply
failed! (0xc0000001)
Mon May 13 17:06:00 2019 : Debug: (3) mschap: Authentication failed
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[authenticate]:
returned from mschap (rlm_mschap)
Mon May 13 17:06:00 2019 : Debug: (3) [mschap] = fail
Mon May 13 17:06:00 2019 : Debug: (3) } # authenticate = fail
Mon May 13 17:06:00 2019 : Debug: (3) Failed to authenticate the user
Mon May 13 17:06:00 2019 : Debug: (3) Using Post-Auth-Type Reject
Mon May 13 17:06:00 2019 : Debug: (3) # Executing group from file
/etc/freeradius/sites-enabled/default
Mon May 13 17:06:00 2019 : Debug: (3) Post-Auth-Type REJECT {
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: calling
eap (rlm_eap)
Mon May 13 17:06:00 2019 : Debug: (3) eap: Request didn't contain an
EAP-Message, not inserting EAP-Failure
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: returned
from eap (rlm_eap)
Mon May 13 17:06:00 2019 : Debug: (3) [eap] = noop
Mon May 13 17:06:00 2019 : Debug: (3) policy remove_reply_message_if_eap {
Mon May 13 17:06:00 2019 : Debug: (3) if (&reply:EAP-Message &&
&reply:Reply-Message) {
Mon May 13 17:06:00 2019 : Debug: (3) if (&reply:EAP-Message &&
&reply:Reply-Message) -> FALSE
Mon May 13 17:06:00 2019 : Debug: (3) else {
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: calling
noop (rlm_always)
Mon May 13 17:06:00 2019 : Debug: (3) modsingle[post-auth]: returned
from noop (rlm_always)
Mon May 13 17:06:00 2019 : Debug: (3) [noop] = noop
Mon May 13 17:06:00 2019 : Debug: (3) } # else = noop
Mon May 13 17:06:00 2019 : Debug: (3) } # policy
remove_reply_message_if_eap = noop
Mon May 13 17:06:00 2019 : Debug: (3) } # Post-Auth-Type REJECT = noop
Mon May 13 17:06:00 2019 : Auth: (3) Login incorrect (mschap: Program
returned code (1) and output 'Reading winbind reply failed!
(0xc0000001)'): [antonio/<via Auth-Type = mschap>] (from client vpn
port 0)
Mon May 13 17:06:00 2019 : Debug: (3) Delaying response for 1.000000 seconds
Mon May 13 17:06:00 2019 : Debug: Thread 2 waiting to be assigned a request
Mon May 13 17:06:01 2019 : Debug: Waking up in 0.8 seconds.
Mon May 13 17:06:01 2019 : Debug: (3) Sending delayed response
Mon May 13 17:06:01 2019 : Debug: (3) Sent Access-Reject Id 7 from
10.0.153.139:1812 to 10.0.0.191:61367 length 77
Mon May 13 17:06:01 2019 : Debug: (3) Tunnel-Type = VLAN
Mon May 13 17:06:01 2019 : Debug: (3) Tunnel-Medium-Type = IEEE-802
Mon May 13 17:06:01 2019 : Debug: (3) Tunnel-Private-Group-Id = "10"
Mon May 13 17:06:01 2019 : Debug: (3) MS-CHAP-Error = "\000E=691 R=1
C=ed4c6cae95574d22 V=2"
Mon May 13 17:06:01 2019 : Debug: Waking up in 3.9 seconds.
Mon May 13 17:06:05 2019 : Debug: (3) Cleaning up request packet ID 7
with timestamp +1631
Mon May 13 17:06:05 2019 : Info: Ready to process requests
And just in case, this is radtest using mschap against Freeradius
running on EC2:
$ radtest -t mschap antonio '<MY_PASSWORD>' 10.0.1.187 0 <MY_SECRET>
Sent Access-Request Id 27 from 0.0.0.0:55903 to 10.0.1.187:1812 length 133
User-Name = "antonio"
MS-CHAP-Password = "<MY_PASSWORD>"
NAS-IP-Address = 127.0.0.1
NAS-Port = 0
Message-Authenticator = 0x00
Cleartext-Password = "<MY_PASSWORD>"
MS-CHAP-Challenge = 0x9508ba134034af62
MS-CHAP-Response =
0x0001000000000000000000000000000000000000000000000000884e7789a08f90f4f58ecef575a97965556a3f9bc8fefe5a
Received Access-Accept Id 27 from 10.0.1.187:1812 to 172.16.0.54:55903 length 36
Tunnel-Type:0 = VLAN
Tunnel-Medium-Type:0 = IEEE-802
Tunnel-Private-Group-Id:0 = "10"
More information about the Freeradius-Users
mailing list