- Freeradius-Users - lists.freeradius.org

Maximum number of lines in authorize file
by Gianni Costanzi 14 May '19

14 May '19

Hi, is there a maximum number of lines or "blocks" that can be defined in authorize (old users) file? Best regards, Gianni Costanzi

2 2

Freeradius on AWS ECS Fargate problem to authenticate using EAP-PEAP (MSCHAPv2) - Reading winbind reply failed! (0xc0000001)
by Antonio Castillo 13 May '19

13 May '19

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-winbin… 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 !~ /(a)(.+)\.(.+)$/)) { Mon May 13 17:06:00 2019 : Debug: (3) if ((&User-Name =~ /@/) && (&User-Name !~ /(a)(.+)\.(.+)$/)) -> 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 =~ /(a)\./) { Mon May 13 17:06:00 2019 : Debug: (3) if (&User-Name =~ /(a)\./) -> 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"

2 1

update disconnect is not working in accounting section
by One Zero Art 11 May '19

11 May '19

Hi, I am trying to disconnect the user in the accounting section. Is FreeRadius support auto disconnection? In the accounting section, I tried this update disconnect { Framed-IP-Address = "%{Framed-IP-Address}" User-Name = "%{request:User-Name}" } This giving me error in accounting section when debuging. I am also using CoA successfully. CoA is working great. This error message showing in debug (7) if (&control:Tmp-Integer-4 == 1){ (7) if (&control:Tmp-Integer-4 == 1) -> TRUE (7) if (&control:Tmp-Integer-4 == 1) { (7) if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3){ (7) if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3) -> TRUE (7) if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3) { (7) update disconnect { (7) *WARNING: List "disconnect" is not available (7) ERROR: Mapping "%{Framed-IP-Address}" -> "Framed-IP-Address" invalid in this context* (7) } # update disconnect = invalid (7) } # if (&control:Tmp-Integer-2 > &control:Tmp-Integer-3) = invalid (7) } # if (&control:Tmp-Integer-4 == 1) = invalid (7) } # accounting = invalid (7) Sent CoA-Request Id 89 from 0.0.0.0:53274 to 192.168.0.10:3799 length 47 (7) Framed-IP-Address = 0.0.0.0 (7) User-Name = "user" (7) Mikrotik-Rate-Limit = "10M/10M" (7) Not sending reply to client. (7) Finished request (7) Cleaning up request packet ID 52 with timestamp +266 Waking up in 2.4 seconds. (7) Clearing existing &reply: attributes (7) Received CoA-NAK Id 89 from 192.168.0.10:3799 to 192.168.0.2:53274 length 42 (7) Error-Cause = Unsupported-Extension (7) NAS-Identifier = "MikroTik" (7) NAS-IP-Address = 192.168.0.10 (7) # Executing section post-proxy from file /etc/freeradius/3.0/sites-enabled/default (7) post-proxy { (7) eap: No pre-existing handler found (7) [eap] = noop (7) } # post-proxy = noop (7) Cleaning up request packet ID 52 with timestamp +266 Ready to process requests Thank you

2 1

Dynamic Client and TCP/TLS
by Karim Benayed 11 May '19

11 May '19

Hi, I am trying to setup Dynamic Client configuration where Redis is used to retrieve the secret, setup the FreeRADIUS-Client attributes and redirect for authentication. The model is working perfectly for UDP with Dynamic Clients and for TCP/TLS non-dynamic clients. The moment I enable Dynamic Clients against the TCP/TLS configuration, I get the following error: Error: Receive - Error receiving packet. Transport endpoint is not connected. This error is followed by Error, Ignoring request ... from unknown client. I tried to re-install and out of the box configuration, Used Fedora built and a 3.0.19 based compiled built against the default configuration and keys. The response is unfortunately exactly the same. Lastly, I tried to connect via openssl s_client host_ip and via FreeRadius acting as a proxy. It is always the same error :( To reproduce, Please try the default configuration, add tls to sites-enabled and connect via a radsec client. I truly appreciate any hints on if anything special is required. Thanks you, Karim

2 1

Update Noop In Authorize Section
by One Zero Art 10 May '19

10 May '19

Hi, I am trying to reject user by checking session time from radacct. I am using 4 SQL query and checking various things in debug mode every SQL query looking good but the only issue updates control noop. Debug mode shows update control noop. Below is my SQL queries. /default authorize section ============================================================= update control { Tmp-String-1 := "%{sql:=============================='}" Tmp-String-2 := "%{sql:================================}" Tmp-String-3 := "%{sql:=================================}'}" Tmp-String-3 := "%{expr:%{control:Tmp-String-3} * 3600}" Tmp-String-4 := "%{sql:S=================================='}" } if(%{control:Tmp-String-4} >= 1){ if(%{control:Tmp-String-2} >= %{control:Tmp-String-3}){ update reply { Reply-Message := 'Reached Session Limit' } reject } } All SQL query working fine and showing exact value. The only problem is that update control showing noop. Some reason update control is not working. Thank you very much

2 4

RE: hex:attribute-name behavior is changed
by Chaigneau, Nicolas 09 May '19

09 May '19

Hello, I've just opened an issue that looks very similar, this is probably the same: https://github.com/FreeRADIUS/freeradius-server/issues/2672 Regards, Nicolas. > Hi, > > Previously the expansion %{hex:DHCP-Client-Hardware-Address} worked correctly by expanding to the mac address value inside the attribute. > Now the latest master(#a88b05513956b21ec037383780f9b568eeb49124) is expanding the raw string "DHCP-Client-Hardware-Address" to hex. > > However, %{hex:%{DHCP-Client-Hardware-Address} is working as expected(expands the value inside the attribute). > > Is this behavior is an intended change or a mistake? > > debug out: > (1) if ("0x%{hex:DHCP-Client-Hardware-Address}" == "%{DHCP-Relay-Remote-Id}") { > (1) EXPAND 0x%{hex:DHCP-Client-Hardware-Address} > (1) EXPAND %{hex:DHCP-Client-Hardware-Address} > (1) --> 444843502d436c69656e742d48617264776172652d41646472657373 > (1) --> 0x444843502d436c69656e742d48617264776172652d41646472657373 > (1) EXPAND %{DHCP-Relay-Remote-Id} > (1) --> 0x00a0bc00000a > > (0) if ("0x%{hex:%{DHCP-Client-Hardware-Address}}" == "%{DHCP-Relay-Remote-Id}") { > (0) EXPAND 0x%{hex:%{DHCP-Client-Hardware-Address}} > (0) EXPAND %{DHCP-Client-Hardware-Address} > (0) --> 00:a0:bc:00:00:0a > (0) EXPAND %{hex:%{DHCP-Client-Hardware-Address}} > (0) (%{hex:00:a0:bc:00:00:0a}) > (0) --> 00a0bc00000a > (0) --> 0x00a0bc00000a > > > This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.

2 1

Radacct Reused ?
by Oscar 09 May '19

09 May '19

Hi, I've created a Trigger to save on a new table the las time a user has been stop connection (acctstoptime). So I've createad table and created this trigger: create TRIGGER UpdateStopTime AFTER UPDATE ON radacct FOR EACH ROW BEGIN INSERT into usuario_instalacion_stoptime ( select u.department as user,u.company as insta,if(r.acctstoptime is null,now(),r.acctstoptime) stoptime from radacct r,userinfo u where r.username=u.username and r.radacctid=NEW.radacctid ) ON DUPLICATE KEY UPDATE stoptime=if(NEW.acctstoptime is null,now(),NEW.acctstoptime) ; END$$ But now I'm facing that sems that radius rows from the past are beeign used on the present I mean, my radacctid is now arround 37.000.000 And I can see a user autheticated and updating a really old row: accstoptime=09-2018 and beeing update today with accstarttime=04-2019 How is that possible ? Is it correct ? Thanks,

3 20

Accounting - Input Octets64
by Nicolas Breuer 09 May '19

09 May '19

Hello, FreeRadius v3.0.19 Ready to process requests (0) Received Accounting-Request Id 205 from 112.112.166.34:1812 to 112.112.176.1:1813 length 610 (0) User-Name = "desclinz@XXXXX" (0) Acct-Status-Type = Interim-Update ... (0) Acct-Session-Time = 26401 (0) Acct-Input-Packets = 2241 (0) Acct-Output-Packets = 3514 (0) Acct-Input-Octets = 91936 (0) Acct-Output-Octets = 192756 (0) Acct-Input-Gigawords = 0 (0) Acct-Output-Gigawords = 0 (0) Acct-Input-Packets-64 = 2241 (0) Acct-Output-Packets-64 = 3514 (0) Acct-Input-Octets-64 = 91936 (0) Acct-Output-Octets-64 = 192756 (0) Acct-Mcast-In-Packets = 0 (0) Acct-Mcast-Out-Packets = 0 (0) Acct-Mcast-In-Octets = 0 (0) Acct-Mcast-Out-Octets = 0 (0) Acct-Mcast-In-Packets-64 = 0 I see the Input Octets 64 is decoded by freeradius, is it expected ? The same Accounting packet on Freeradius v2.2 Acct-Session-Time = 464417 Acct-Input-Packets = 3691542 Acct-Output-Packets = 3156045 Acct-Input-Octets = 822225356 Acct-Output-Octets = 709539148 Acct-Input-Gigawords = 0 Acct-Output-Gigawords = 0 Acct-Input-Packets-64 = 0x0000000000385416 Acct-Output-Packets-64 = 0x000000000030284d Acct-Input-Octets-64 = 0x00000000310229cc Acct-Output-Octets-64 = 0x000000002a4ab54c Acct-Mcast-In-Packets = 0 Acct-Mcast-Out-Packets = 0 Acct-Mcast-In-Octets = 0 Acct-Mcast-Out-Octets = 0 On 2.2, the Input Packets 64 is in Hexadecimal. Thanks

2 1

RE: redis_ippool module doesnot process lease_time in ack
by Chinnapaiyan, Nagamani 09 May '19

09 May '19

This works in latest git(#a88b05513956b21ec037383780f9b568eeb49124). (1) redis_ippool - &reply:DHCP-IP-Address-Lease-Time := 900 (1) redis_ippool - Requested IP address' "10.88.64.133" lease updated (1) redis_ippool - &reply:DHCP-Your-IP-Address := 10.88.64.133 (1) redis_ippool (updated) (1) ok (ok) Regards, Nagamani Chinnapaiyan

1 0

hex:attribute-name behavior is changed
by Chinnapaiyan, Nagamani 09 May '19

09 May '19

Hi, Previously the expansion %{hex:DHCP-Client-Hardware-Address} worked correctly by expanding to the mac address value inside the attribute. Now the latest master(#a88b05513956b21ec037383780f9b568eeb49124) is expanding the raw string "DHCP-Client-Hardware-Address" to hex. However, %{hex:%{DHCP-Client-Hardware-Address} is working as expected(expands the value inside the attribute). Is this behavior is an intended change or a mistake? debug out: (1) if ("0x%{hex:DHCP-Client-Hardware-Address}" == "%{DHCP-Relay-Remote-Id}") { (1) EXPAND 0x%{hex:DHCP-Client-Hardware-Address} (1) EXPAND %{hex:DHCP-Client-Hardware-Address} (1) --> 444843502d436c69656e742d48617264776172652d41646472657373 (1) --> 0x444843502d436c69656e742d48617264776172652d41646472657373 (1) EXPAND %{DHCP-Relay-Remote-Id} (1) --> 0x00a0bc00000a (0) if ("0x%{hex:%{DHCP-Client-Hardware-Address}}" == "%{DHCP-Relay-Remote-Id}") { (0) EXPAND 0x%{hex:%{DHCP-Client-Hardware-Address}} (0) EXPAND %{DHCP-Client-Hardware-Address} (0) --> 00:a0:bc:00:00:0a (0) EXPAND %{hex:%{DHCP-Client-Hardware-Address}} (0) (%{hex:00:a0:bc:00:00:0a}) (0) --> 00a0bc00000a (0) --> 0x00a0bc00000a Regards, Nagamani Chinnapaiyan

1 0