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@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... 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"