Issue with authentication for certain users
Wayne Sprouse
wayne.sprouse at lbsdk12.com
Thu Apr 3 14:45:50 UTC 2025
We use FreeRADIUS for our wireless authentication. Everything worked
correctly until around November 2024. Now, certain users are unable to
authenticate. The FreeRADIUS server points to our Google Workspace
domain using Google Secure LDAP. Our domain has a primary domain and a
subdomain. Any user in the subdomain is affected by this issue. Below
are the results of the authentication attempt for two users in the
subdomain. These results are taken from running freeradius -X -x. If I
add an alias to any user in the subdomain to point to the primary,
they can log in. I am hoping someone here could give me some ideas on
what it might be because Google says it is not on their end.
Thu Apr 3 08:21:22 2025 : Debug: (8) Received Access-Request Id 12
from 192.168.1.5:60774 to 10.220.3.99:1812 length 81
Thu Apr 3 08:21:22 2025 : Debug: (8) User-Name =
"ben.tennyson at student.madeupdomain.com"
Thu Apr 3 08:21:22 2025 : Debug: (8) User-Password = "Omnitrix2024"
Thu Apr 3 08:21:22 2025 : Debug: (8) Framed-IP-Address = 192.168.1.5
Thu Apr 3 08:21:22 2025 : Debug: (8) session-state: No State attribute
Thu Apr 3 08:21:22 2025 : Debug: (8) # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:22 2025 : Debug: (8) authorize {
Thu Apr 3 08:21:22 2025 : Debug: (8) policy filter_username {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name) -> TRUE
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ / /) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ / /) -> FALSE
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ /@[^@]*@/ ) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~
/@[^@]*@/ ) -> FALSE
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ /\.\./ ) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ /\.\./
) -> FALSE
Thu Apr 3 08:21:22 2025 : Debug: (8) if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ /\.$/) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ /\.$/)
-> FALSE
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ /@\./) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (&User-Name =~ /@\./)
-> FALSE
Thu Apr 3 08:21:22 2025 : Debug: (8) } # if (&User-Name) = notfound
Thu Apr 3 08:21:22 2025 : Debug: (8) } # policy filter_username = notfound
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling preprocess (rlm_preprocess)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from preprocess (rlm_preprocess)
Thu Apr 3 08:21:22 2025 : Debug: (8) [preprocess] = ok
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling chap (rlm_chap)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from chap (rlm_chap)
Thu Apr 3 08:21:22 2025 : Debug: (8) [chap] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling mschap (rlm_mschap)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from mschap (rlm_mschap)
Thu Apr 3 08:21:22 2025 : Debug: (8) [mschap] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling digest (rlm_digest)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from digest (rlm_digest)
Thu Apr 3 08:21:22 2025 : Debug: (8) [digest] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling suffix (rlm_realm)
Thu Apr 3 08:21:22 2025 : Debug: (8) suffix: Checking for suffix after "@"
Thu Apr 3 08:21:22 2025 : Debug: (8) suffix: Looking up realm
"student.madeupdomain.com" for User-Name =
"ben.tennyson at student.madeupdomain.com"
Thu Apr 3 08:21:22 2025 : Debug: (8) suffix: Found realm
"student.madeupdomain.com"
Thu Apr 3 08:21:22 2025 : Debug: (8) suffix: Adding
Stripped-User-Name = "ben.tennyson"
Thu Apr 3 08:21:22 2025 : Debug: (8) suffix: Adding Realm =
"student.madeupdomain.com"
Thu Apr 3 08:21:22 2025 : Debug: (8) suffix: Authentication realm is LOCAL
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from suffix (rlm_realm)
Thu Apr 3 08:21:22 2025 : Debug: (8) [suffix] = ok
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling eap (rlm_eap)
Thu Apr 3 08:21:22 2025 : Debug: (8) eap: No EAP-Message, not doing EAP
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from eap (rlm_eap)
Thu Apr 3 08:21:22 2025 : Debug: (8) [eap] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling files (rlm_files)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from files (rlm_files)
Thu Apr 3 08:21:22 2025 : Debug: (8) [files] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling ldap (rlm_ldap)
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: EXPAND (mail=%{User-Name})
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: -->
(mail=ben.tennyson at student.madeupdomain.com)
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Performing search in
"dc=madeupdomain,dc=com" with filter
"(mail=ben.tennyson at student.madeupdomain.com)", scope "sub"
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Waiting for search result...
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: User object found at DN
"uid=ben.tennyson,ou=LBHS,ou=Students,ou=Users,dc=madeupdomain,dc=com"
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Processing user attributes
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Attribute "userPassword"
not found in LDAP object
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Attribute
"radiusControlAttribute" not found in LDAP object
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Attribute
"radiusRequestAttribute" not found in LDAP object
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Attribute
"radiusReplyAttribute" not found in LDAP object
Thu Apr 3 08:21:22 2025 : WARNING: (8) ldap: No "known good" password
added. Ensure the admin user has permission to read the password
attribute
Thu Apr 3 08:21:22 2025 : WARNING: (8) ldap: PAP authentication will
*NOT* work with Active Directory (if that is what you were trying to
configure)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from ldap (rlm_ldap)
Thu Apr 3 08:21:22 2025 : Debug: (8) [ldap] = ok
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling expiration (rlm_expiration)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from expiration (rlm_expiration)
Thu Apr 3 08:21:22 2025 : Debug: (8) [expiration] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling logintime (rlm_logintime)
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from logintime (rlm_logintime)
Thu Apr 3 08:21:22 2025 : Debug: (8) [logintime] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
calling pap (rlm_pap)
Thu Apr 3 08:21:22 2025 : WARNING: (8) pap: No "known good" password
found for the user. Not setting Auth-Type
Thu Apr 3 08:21:22 2025 : WARNING: (8) pap: Authentication will fail
unless a "known good" password is available
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authorize]:
returned from pap (rlm_pap)
Thu Apr 3 08:21:22 2025 : Debug: (8) [pap] = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) if (User-Password) {
Thu Apr 3 08:21:22 2025 : Debug: (8) if (User-Password) -> TRUE
Thu Apr 3 08:21:22 2025 : Debug: (8) if (User-Password) {
Thu Apr 3 08:21:22 2025 : Debug: (8) update control {
Thu Apr 3 08:21:22 2025 : Debug: (8) Auth-Type := LDAP
Thu Apr 3 08:21:22 2025 : Debug: (8) } # update control = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) } # if (User-Password) = noop
Thu Apr 3 08:21:22 2025 : Debug: (8) } # authorize = ok
Thu Apr 3 08:21:22 2025 : Debug: (8) Found Auth-Type = LDAP
Thu Apr 3 08:21:22 2025 : Debug: (8) # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:22 2025 : Debug: (8) authenticate {
Thu Apr 3 08:21:22 2025 : Debug: (8) modsingle[authenticate]:
calling ldap (rlm_ldap)
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Login attempt by "ben.tennyson"
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Using user DN from request
"uid=ben.tennyson,ou=LBHS,ou=Students,ou=Users,dc=madeupdomain,dc=com"
Thu Apr 3 08:21:22 2025 : Debug: (8) ldap: Waiting for bind result...
Thu Apr 3 08:21:23 2025 : ERROR: (8) ldap: Bind credentials
incorrect: Invalid credentials
Thu Apr 3 08:21:23 2025 : ERROR: (8) ldap: Server said: Incorrect password.
Thu Apr 3 08:21:23 2025 : Debug: (8) modsingle[authenticate]:
returned from ldap (rlm_ldap)
Thu Apr 3 08:21:23 2025 : Debug: (8) [ldap] = reject
Thu Apr 3 08:21:23 2025 : Debug: (8) } # authenticate = reject
Thu Apr 3 08:21:23 2025 : Debug: (8) Failed to authenticate the user
Thu Apr 3 08:21:23 2025 : Debug: (8) Using Post-Auth-Type Reject
Thu Apr 3 08:21:23 2025 : Debug: (8) # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:23 2025 : Debug: (8) Post-Auth-Type REJECT {
Thu Apr 3 08:21:23 2025 : Debug: (8) modsingle[post-auth]:
calling attr_filter.access_reject (rlm_attr_filter)
Thu Apr 3 08:21:23 2025 : Debug: %{User-Name}
Thu Apr 3 08:21:23 2025 : Debug: Parsed xlat tree:
Thu Apr 3 08:21:23 2025 : Debug: attribute --> User-Name
Thu Apr 3 08:21:23 2025 : Debug: (8) attr_filter.access_reject:
EXPAND %{User-Name}
Thu Apr 3 08:21:23 2025 : Debug: (8) attr_filter.access_reject:
--> ben.tennyson at student.madeupdomain.com
Thu Apr 3 08:21:23 2025 : Debug: (8) attr_filter.access_reject:
Matched entry DEFAULT at line 11
Thu Apr 3 08:21:23 2025 : Debug: (8) modsingle[post-auth]:
returned from attr_filter.access_reject (rlm_attr_filter)
Thu Apr 3 08:21:23 2025 : Debug: (8) [attr_filter.access_reject] = updated
Thu Apr 3 08:21:23 2025 : Debug: (8) modsingle[post-auth]:
calling eap (rlm_eap)
Thu Apr 3 08:21:23 2025 : Debug: (8) eap: Request didn't contain an
EAP-Message, not inserting EAP-Failure
Thu Apr 3 08:21:23 2025 : Debug: (8) modsingle[post-auth]:
returned from eap (rlm_eap)
Thu Apr 3 08:21:23 2025 : Debug: (8) [eap] = noop
Thu Apr 3 08:21:23 2025 : Debug: (8) policy remove_reply_message_if_eap {
Thu Apr 3 08:21:23 2025 : Debug: (8) if (&reply:EAP-Message &&
&reply:Reply-Message) {
Thu Apr 3 08:21:23 2025 : Debug: (8) if (&reply:EAP-Message &&
&reply:Reply-Message) -> FALSE
Thu Apr 3 08:21:23 2025 : Debug: (8) else {
Thu Apr 3 08:21:23 2025 : Debug: (8) modsingle[post-auth]:
calling noop (rlm_always)
Thu Apr 3 08:21:23 2025 : Debug: (8) modsingle[post-auth]:
returned from noop (rlm_always)
Thu Apr 3 08:21:23 2025 : Debug: (8) [noop] = noop
Thu Apr 3 08:21:23 2025 : Debug: (8) } # else = noop
Thu Apr 3 08:21:23 2025 : Debug: (8) } # policy
remove_reply_message_if_eap = noop
Thu Apr 3 08:21:23 2025 : Debug: (8) } # Post-Auth-Type REJECT = updated
Thu Apr 3 08:21:23 2025 : Auth: (8) Login incorrect (ldap: Bind
credentials incorrect: Invalid credentials):
[ben.tennyson at student.madeupdomain.com/Omnitrix2024] (from client LBSD
port 0)
Thu Apr 3 08:21:23 2025 : Debug: (8) Delaying response for 1.000000 seconds
Thu Apr 3 08:21:35 2025 : Debug: (36) Received Access-Request Id 13
from 192.168.1.5:61800 to 10.220.3.99:1812 length 77
Thu Apr 3 08:21:35 2025 : Debug: (36) User-Name =
"johnny.test at student.madeupdomain.com"
Thu Apr 3 08:21:35 2025 : Debug: (36) User-Password = "Dookie2025"
Thu Apr 3 08:21:35 2025 : Debug: (36) Framed-IP-Address = 192.168.1.5
Thu Apr 3 08:21:35 2025 : Debug: (36) session-state: No State attribute
Thu Apr 3 08:21:35 2025 : Debug: (36) # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:35 2025 : Debug: (36) authorize {
Thu Apr 3 08:21:35 2025 : Debug: (36) policy filter_username {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name) -> TRUE
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~ / /) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~ / /) -> FALSE
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~ /@[^@]*@/ ) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~
/@[^@]*@/ ) -> FALSE
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~ /\.\./ ) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~
/\.\./ ) -> FALSE
Thu Apr 3 08:21:35 2025 : Debug: (36) if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~ /\.$/) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~
/\.$/) -> FALSE
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~ /@\./) {
Thu Apr 3 08:21:35 2025 : Debug: (36) if (&User-Name =~
/@\./) -> FALSE
Thu Apr 3 08:21:35 2025 : Debug: (36) } # if (&User-Name) = notfound
Thu Apr 3 08:21:35 2025 : Debug: (36) } # policy filter_username = notfound
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling preprocess (rlm_preprocess)
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
returned from preprocess (rlm_preprocess)
Thu Apr 3 08:21:35 2025 : Debug: (36) [preprocess] = ok
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling chap (rlm_chap)
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
returned from chap (rlm_chap)
Thu Apr 3 08:21:35 2025 : Debug: (36) [chap] = noop
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling mschap (rlm_mschap)
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
returned from mschap (rlm_mschap)
Thu Apr 3 08:21:35 2025 : Debug: (36) [mschap] = noop
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling digest (rlm_digest)
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
returned from digest (rlm_digest)
Thu Apr 3 08:21:35 2025 : Debug: (36) [digest] = noop
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling suffix (rlm_realm)
Thu Apr 3 08:21:35 2025 : Debug: (36) suffix: Checking for suffix after "@"
Thu Apr 3 08:21:35 2025 : Debug: (36) suffix: Looking up realm
"student.madeupdomain.com" for User-Name =
"johnny.test at student.madeupdomain.com"
Thu Apr 3 08:21:35 2025 : Debug: (36) suffix: Found realm
"student.madeupdomain.com"
Thu Apr 3 08:21:35 2025 : Debug: (36) suffix: Adding
Stripped-User-Name = "johnny.test"
Thu Apr 3 08:21:35 2025 : Debug: (36) suffix: Adding Realm =
"student.madeupdomain.com"
Thu Apr 3 08:21:35 2025 : Debug: (36) suffix: Authentication realm is LOCAL
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
returned from suffix (rlm_realm)
Thu Apr 3 08:21:35 2025 : Debug: (36) [suffix] = ok
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling eap (rlm_eap)
Thu Apr 3 08:21:35 2025 : Debug: (36) eap: No EAP-Message, not doing EAP
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
returned from eap (rlm_eap)
Thu Apr 3 08:21:35 2025 : Debug: (36) [eap] = noop
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling files (rlm_files)
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
returned from files (rlm_files)
Thu Apr 3 08:21:35 2025 : Debug: (36) [files] = noop
Thu Apr 3 08:21:35 2025 : Debug: (36) modsingle[authorize]:
calling ldap (rlm_ldap)
Thu Apr 3 08:21:35 2025 : Debug: (36) ldap: Waiting for bind result...
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Bind successful
Thu Apr 3 08:21:36 2025 : Debug: (mail=%{User-Name})
Thu Apr 3 08:21:36 2025 : Debug: Parsed xlat tree:
Thu Apr 3 08:21:36 2025 : Debug: literal --> (mail=
Thu Apr 3 08:21:36 2025 : Debug: attribute --> User-Name
Thu Apr 3 08:21:36 2025 : Debug: literal --> )
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: EXPAND (mail=%{User-Name})
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: -->
(mail=johnny.test at student.madeupdomain.com)
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Performing search in
"dc=madeupdomain,dc=com" with filter
"(mail=johnny.test at student.madeupdomain.com)", scope "sub"
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Waiting for search result...
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: User object found at DN
"uid=johnny.test,ou=LBHS,ou=Students,ou=Users,dc=madeupdomain,dc=com"
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Processing user attributes
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Attribute "userPassword"
not found in LDAP object
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Attribute
"radiusControlAttribute" not found in LDAP object
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Attribute
"radiusRequestAttribute" not found in LDAP object
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Attribute
"radiusReplyAttribute" not found in LDAP object
Thu Apr 3 08:21:36 2025 : WARNING: (36) ldap: No "known good"
password added. Ensure the admin user has permission to read the
password attribute
Thu Apr 3 08:21:36 2025 : WARNING: (36) ldap: PAP authentication will
*NOT* work with Active Directory (if that is what you were trying to
configure)
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authorize]:
returned from ldap (rlm_ldap)
Thu Apr 3 08:21:36 2025 : Debug: (36) [ldap] = ok
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authorize]:
calling expiration (rlm_expiration)
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authorize]:
returned from expiration (rlm_expiration)
Thu Apr 3 08:21:36 2025 : Debug: (36) [expiration] = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authorize]:
calling logintime (rlm_logintime)
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authorize]:
returned from logintime (rlm_logintime)
Thu Apr 3 08:21:36 2025 : Debug: (36) [logintime] = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authorize]:
calling pap (rlm_pap)
Thu Apr 3 08:21:36 2025 : WARNING: (36) pap: No "known good" password
found for the user. Not setting Auth-Type
Thu Apr 3 08:21:36 2025 : WARNING: (36) pap: Authentication will fail
unless a "known good" password is available
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authorize]:
returned from pap (rlm_pap)
Thu Apr 3 08:21:36 2025 : Debug: (36) [pap] = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) if (User-Password) {
Thu Apr 3 08:21:36 2025 : Debug: (36) if (User-Password) -> TRUE
Thu Apr 3 08:21:36 2025 : Debug: (36) if (User-Password) {
Thu Apr 3 08:21:36 2025 : Debug: (36) update control {
Thu Apr 3 08:21:36 2025 : Debug: (36) Auth-Type := LDAP
Thu Apr 3 08:21:36 2025 : Debug: (36) } # update control = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) } # if (User-Password) = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) } # authorize = ok
Thu Apr 3 08:21:36 2025 : Debug: (36) Found Auth-Type = LDAP
Thu Apr 3 08:21:36 2025 : Debug: (36) # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:36 2025 : Debug: (36) authenticate {
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authenticate]:
calling ldap (rlm_ldap)
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Login attempt by "johnny.test"
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Using user DN from
request "uid=johnny.test,ou=LBHS,ou=Students,ou=Users,dc=madeupdomain,dc=com"
Thu Apr 3 08:21:36 2025 : Debug: (36) ldap: Waiting for bind result...
Thu Apr 3 08:21:36 2025 : ERROR: (36) ldap: Bind credentials
incorrect: Invalid credentials
Thu Apr 3 08:21:36 2025 : ERROR: (36) ldap: Server said: Incorrect password.
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[authenticate]:
returned from ldap (rlm_ldap)
Thu Apr 3 08:21:36 2025 : Debug: (36) [ldap] = reject
Thu Apr 3 08:21:36 2025 : Debug: (36) } # authenticate = reject
Thu Apr 3 08:21:36 2025 : Debug: (36) Failed to authenticate the user
Thu Apr 3 08:21:36 2025 : Debug: (36) Using Post-Auth-Type Reject
Thu Apr 3 08:21:36 2025 : Debug: (36) # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:36 2025 : Debug: (36) Post-Auth-Type REJECT {
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[post-auth]:
calling attr_filter.access_reject (rlm_attr_filter)
Thu Apr 3 08:21:36 2025 : Debug: %{User-Name}
Thu Apr 3 08:21:36 2025 : Debug: Parsed xlat tree:
Thu Apr 3 08:21:36 2025 : Debug: attribute --> User-Name
Thu Apr 3 08:21:36 2025 : Debug: (36) attr_filter.access_reject:
EXPAND %{User-Name}
Thu Apr 3 08:21:36 2025 : Debug: (36) attr_filter.access_reject:
--> johnny.test at student.madeupdomain.com
Thu Apr 3 08:21:36 2025 : Debug: (36) attr_filter.access_reject:
Matched entry DEFAULT at line 11
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[post-auth]:
returned from attr_filter.access_reject (rlm_attr_filter)
Thu Apr 3 08:21:36 2025 : Debug: (36) [attr_filter.access_reject] = updated
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[post-auth]:
calling eap (rlm_eap)
Thu Apr 3 08:21:36 2025 : Debug: (36) eap: Request didn't contain an
EAP-Message, not inserting EAP-Failure
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[post-auth]:
returned from eap (rlm_eap)
Thu Apr 3 08:21:36 2025 : Debug: (36) [eap] = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) policy remove_reply_message_if_eap {
Thu Apr 3 08:21:36 2025 : Debug: (36) if (&reply:EAP-Message &&
&reply:Reply-Message) {
Thu Apr 3 08:21:36 2025 : Debug: (36) if (&reply:EAP-Message &&
&reply:Reply-Message) -> FALSE
Thu Apr 3 08:21:36 2025 : Debug: (36) else {
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[post-auth]:
calling noop (rlm_always)
Thu Apr 3 08:21:36 2025 : Debug: (36) modsingle[post-auth]:
returned from noop (rlm_always)
Thu Apr 3 08:21:36 2025 : Debug: (36) [noop] = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) } # else = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) } # policy
remove_reply_message_if_eap = noop
Thu Apr 3 08:21:36 2025 : Debug: (36) } # Post-Auth-Type REJECT = updated
Thu Apr 3 08:21:36 2025 : Auth: (36) Login incorrect (ldap: Bind
credentials incorrect: Invalid credentials):
[johnny.test at student.madeupdomain.com/Dookie2025] (from client LBSD
port 0)
Thu Apr 3 08:21:36 2025 : Debug: (36) Delaying response for 1.000000 seconds
Thu Apr 3 08:21:50 2025 : Debug: (59) Received Access-Request Id 14
from 192.168.1.5:62921 to 10.220.3.99:1812 length 77
Thu Apr 3 08:21:50 2025 : Debug: (59) User-Name =
"johnny.test at student.madeupdomain.com"
Thu Apr 3 08:21:50 2025 : Debug: (59) User-Password = "12345678"
Thu Apr 3 08:21:50 2025 : Debug: (59) Framed-IP-Address = 192.168.1.5
Thu Apr 3 08:21:50 2025 : Debug: (59) session-state: No State attribute
Thu Apr 3 08:21:50 2025 : Debug: (59) # Executing section authorize
from file /etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:50 2025 : Debug: (59) authorize {
Thu Apr 3 08:21:50 2025 : Debug: (59) policy filter_username {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name) -> TRUE
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~ / /) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~ / /) -> FALSE
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~ /@[^@]*@/ ) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~
/@[^@]*@/ ) -> FALSE
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~ /\.\./ ) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~
/\.\./ ) -> FALSE
Thu Apr 3 08:21:50 2025 : Debug: (59) if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if ((&User-Name =~ /@/)
&& (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~ /\.$/) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~
/\.$/) -> FALSE
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~ /@\./) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&User-Name =~
/@\./) -> FALSE
Thu Apr 3 08:21:50 2025 : Debug: (59) } # if (&User-Name) = notfound
Thu Apr 3 08:21:50 2025 : Debug: (59) } # policy filter_username = notfound
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling preprocess (rlm_preprocess)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from preprocess (rlm_preprocess)
Thu Apr 3 08:21:50 2025 : Debug: (59) [preprocess] = ok
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling chap (rlm_chap)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from chap (rlm_chap)
Thu Apr 3 08:21:50 2025 : Debug: (59) [chap] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling mschap (rlm_mschap)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from mschap (rlm_mschap)
Thu Apr 3 08:21:50 2025 : Debug: (59) [mschap] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling digest (rlm_digest)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from digest (rlm_digest)
Thu Apr 3 08:21:50 2025 : Debug: (59) [digest] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling suffix (rlm_realm)
Thu Apr 3 08:21:50 2025 : Debug: (59) suffix: Checking for suffix after "@"
Thu Apr 3 08:21:50 2025 : Debug: (59) suffix: Looking up realm
"student.madeupdomain.com" for User-Name =
"johnny.test at student.madeupdomain.com"
Thu Apr 3 08:21:50 2025 : Debug: (59) suffix: Found realm
"student.madeupdomain.com"
Thu Apr 3 08:21:50 2025 : Debug: (59) suffix: Adding
Stripped-User-Name = "johnny.test"
Thu Apr 3 08:21:50 2025 : Debug: (59) suffix: Adding Realm =
"student.madeupdomain.com"
Thu Apr 3 08:21:50 2025 : Debug: (59) suffix: Authentication realm is LOCAL
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from suffix (rlm_realm)
Thu Apr 3 08:21:50 2025 : Debug: (59) [suffix] = ok
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling eap (rlm_eap)
Thu Apr 3 08:21:50 2025 : Debug: (59) eap: No EAP-Message, not doing EAP
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from eap (rlm_eap)
Thu Apr 3 08:21:50 2025 : Debug: (59) [eap] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling files (rlm_files)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from files (rlm_files)
Thu Apr 3 08:21:50 2025 : Debug: (59) [files] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling ldap (rlm_ldap)
Thu Apr 3 08:21:50 2025 : Debug: rlm_ldap (ldap): Reserved connection (1)
Thu Apr 3 08:21:50 2025 : Debug: (mail=%{User-Name})
Thu Apr 3 08:21:50 2025 : Debug: Parsed xlat tree:
Thu Apr 3 08:21:50 2025 : Debug: literal --> (mail=
Thu Apr 3 08:21:50 2025 : Debug: attribute --> User-Name
Thu Apr 3 08:21:50 2025 : Debug: literal --> )
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: EXPAND (mail=%{User-Name})
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: -->
(mail=johnny.test at student.madeupdomain.com)
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Performing search in
"dc=madeupdomain,dc=com" with filter
"(mail=johnny.test at student.madeupdomain.com)", scope "sub"
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Waiting for search result...
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: User object found at DN
"uid=johnny.test,ou=LBHS,ou=Students,ou=Users,dc=madeupdomain,dc=com"
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Processing user attributes
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Attribute "userPassword"
not found in LDAP object
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Attribute
"radiusControlAttribute" not found in LDAP object
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Attribute
"radiusRequestAttribute" not found in LDAP object
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Attribute
"radiusReplyAttribute" not found in LDAP object
Thu Apr 3 08:21:50 2025 : WARNING: (59) ldap: No "known good"
password added. Ensure the admin user has permission to read the
password attribute
Thu Apr 3 08:21:50 2025 : WARNING: (59) ldap: PAP authentication will
*NOT* work with Active Directory (if that is what you were trying to
configure)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from ldap (rlm_ldap)
Thu Apr 3 08:21:50 2025 : Debug: (59) [ldap] = ok
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling expiration (rlm_expiration)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from expiration (rlm_expiration)
Thu Apr 3 08:21:50 2025 : Debug: (59) [expiration] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling logintime (rlm_logintime)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from logintime (rlm_logintime)
Thu Apr 3 08:21:50 2025 : Debug: (59) [logintime] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
calling pap (rlm_pap)
Thu Apr 3 08:21:50 2025 : WARNING: (59) pap: No "known good" password
found for the user. Not setting Auth-Type
Thu Apr 3 08:21:50 2025 : WARNING: (59) pap: Authentication will fail
unless a "known good" password is available
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authorize]:
returned from pap (rlm_pap)
Thu Apr 3 08:21:50 2025 : Debug: (59) [pap] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) if (User-Password) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (User-Password) -> TRUE
Thu Apr 3 08:21:50 2025 : Debug: (59) if (User-Password) {
Thu Apr 3 08:21:50 2025 : Debug: (59) update control {
Thu Apr 3 08:21:50 2025 : Debug: (59) Auth-Type := LDAP
Thu Apr 3 08:21:50 2025 : Debug: (59) } # update control = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) } # if (User-Password) = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) } # authorize = ok
Thu Apr 3 08:21:50 2025 : Debug: (59) Found Auth-Type = LDAP
Thu Apr 3 08:21:50 2025 : Debug: (59) # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:50 2025 : Debug: (59) authenticate {
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authenticate]:
calling ldap (rlm_ldap)
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Login attempt by "johnny.test"
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Using user DN from
request "uid=johnny.test,ou=LBHS,ou=Students,ou=Users,dc=madeupdomain,dc=com"
Thu Apr 3 08:21:50 2025 : Debug: (59) ldap: Waiting for bind result...
Thu Apr 3 08:21:50 2025 : ERROR: (59) ldap: Bind credentials
incorrect: Invalid credentials
Thu Apr 3 08:21:50 2025 : ERROR: (59) ldap: Server said: Incorrect password.
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[authenticate]:
returned from ldap (rlm_ldap)
Thu Apr 3 08:21:50 2025 : Debug: (59) [ldap] = reject
Thu Apr 3 08:21:50 2025 : Debug: (59) } # authenticate = reject
Thu Apr 3 08:21:50 2025 : Debug: (59) Failed to authenticate the user
Thu Apr 3 08:21:50 2025 : Debug: (59) Using Post-Auth-Type Reject
Thu Apr 3 08:21:50 2025 : Debug: (59) # Executing group from file
/etc/freeradius/3.0/sites-enabled/default
Thu Apr 3 08:21:50 2025 : Debug: (59) Post-Auth-Type REJECT {
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[post-auth]:
calling attr_filter.access_reject (rlm_attr_filter)
Thu Apr 3 08:21:50 2025 : Debug: %{User-Name}
Thu Apr 3 08:21:50 2025 : Debug: Parsed xlat tree:
Thu Apr 3 08:21:50 2025 : Debug: attribute --> User-Name
Thu Apr 3 08:21:50 2025 : Debug: (59) attr_filter.access_reject:
EXPAND %{User-Name}
Thu Apr 3 08:21:50 2025 : Debug: (59) attr_filter.access_reject:
--> johnny.test at student.madeupdomain.com
Thu Apr 3 08:21:50 2025 : Debug: (59) attr_filter.access_reject:
Matched entry DEFAULT at line 11
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[post-auth]:
returned from attr_filter.access_reject (rlm_attr_filter)
Thu Apr 3 08:21:50 2025 : Debug: (59) [attr_filter.access_reject] = updated
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[post-auth]:
calling eap (rlm_eap)
Thu Apr 3 08:21:50 2025 : Debug: (59) eap: Request didn't contain an
EAP-Message, not inserting EAP-Failure
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[post-auth]:
returned from eap (rlm_eap)
Thu Apr 3 08:21:50 2025 : Debug: (59) [eap] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) policy remove_reply_message_if_eap {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&reply:EAP-Message &&
&reply:Reply-Message) {
Thu Apr 3 08:21:50 2025 : Debug: (59) if (&reply:EAP-Message &&
&reply:Reply-Message) -> FALSE
Thu Apr 3 08:21:50 2025 : Debug: (59) else {
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[post-auth]:
calling noop (rlm_always)
Thu Apr 3 08:21:50 2025 : Debug: (59) modsingle[post-auth]:
returned from noop (rlm_always)
Thu Apr 3 08:21:50 2025 : Debug: (59) [noop] = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) } # else = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) } # policy
remove_reply_message_if_eap = noop
Thu Apr 3 08:21:50 2025 : Debug: (59) } # Post-Auth-Type REJECT = updated
Thu Apr 3 08:21:50 2025 : Auth: (59) Login incorrect (ldap: Bind
credentials incorrect: Invalid credentials):
[johnny.test at student.madeupdomain.com/12345678] (from client LBSD port
0)
Thu Apr 3 08:21:50 2025 : Debug: (59) Delaying response for 1.000000 seconds
Wayne Sprouse, CNA,CCNA,CEH,A+
Long Beach School District
Network Administrator
Work Phone: 228-575-4056
--
"The
foregoing electronic message and any files transmitted with it are
confidential and are intended only for the use of the intended recipient
named above. This communication may contain material protected by the
Family Educational Rights and Privacy Act (FERPA). If you are not the
intended recipient, copying, distribution or use of the contents of this
message is strictly prohibited. If you received this electronic
message
in error, please notify us immediately at (228-864-1146**)."**
More information about the Freeradius-Users
mailing list