Freeradius + Ldap - Authorise OK but NO dynamic VLANs

[Matthew Pulis]

Hi Alan

thanks for your suggestion.

I added that snippet in the authorize {} section too. But!!! :

How come it is seeing that it is not a member of SeminaryAdmin when
ldapsearch specifically says it is. I didn't touch the default schema in
OpenLDAP so it should be pretty much straight forward from that side.

Thanks

Mon Aug 22 17:43:18 2016 : Debug: rlm_ldap (ldap): Bind successful
Mon Aug 22 17:43:18 2016 : Debug: (0)     User is not a member of
"SeminaryAdmin" <============================!!!!!!!!!
Mon Aug 22 17:43:18 2016 : Debug: (0)     if (Ldap-Group ==
"SeminaryAdmin")  -> FALSE
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from preprocess (rlm_preprocess) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [preprocess] = ok
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
chap (rlm_chap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from chap (rlm_chap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [chap] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
mschap (rlm_mschap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from mschap (rlm_mschap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [mschap] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
suffix (rlm_realm) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0) suffix: Checking for suffix after "@"
Mon Aug 22 17:43:18 2016 : Debug: (0) suffix: No '@' in User-Name =
"ttester", looking up realm NULL
Mon Aug 22 17:43:18 2016 : Debug: (0) suffix: No such realm "NULL"
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from suffix (rlm_realm) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [suffix] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling eap
(rlm_eap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0) eap: No EAP-Message, not doing EAP
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from eap (rlm_eap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [eap] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
files (rlm_files) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from files (rlm_files) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [files] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
ldap (rlm_ldap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: rlm_ldap (ldap): Reserved connection (1)
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL XLAT
Mon Aug 22 17:43:18 2016 : Debug:
(uid=%{%{Stripped-User-Name}:-%{User-Name}})
Mon Aug 22 17:43:18 2016 : Debug: Parsed xlat tree:
Mon Aug 22 17:43:18 2016 : Debug: literal --> (uid=
Mon Aug 22 17:43:18 2016 : Debug: if {
Mon Aug 22 17:43:18 2016 : Debug:       attribute --> Stripped-User-Name
Mon Aug 22 17:43:18 2016 : Debug: }
Mon Aug 22 17:43:18 2016 : Debug: else {
Mon Aug 22 17:43:18 2016 : Debug:       attribute --> User-Name
Mon Aug 22 17:43:18 2016 : Debug: }
Mon Aug 22 17:43:18 2016 : Debug: literal --> )
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND
(uid=%{%{Stripped-User-Name}:-%{User-Name}})
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap:    --> (uid=ttester)
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND TMPL LITERAL
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Performing search in
"ou=SeminaryOU,dc=seminary,dc=local" with filter "(uid=ttester)", scope
"sub"
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Waiting for search result...
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: User object found at DN
"cn=ttester,cn=SeminaryAdmin,ou=SeminaryOU,dc=seminary,dc=local"
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Processing user attributes
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: control:Password-With-Header +=
'{SSHA}8IQ1qEkhjMJHRJH0vm7ajuRNcSBw9yrp'
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Attribute "radiusReplyMessage"
not found in LDAP object
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Attribute "radiusTunnelType"
not found in LDAP object
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Attribute
"radiusTunnelMediumType" not found in LDAP object
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Attribute
"radiusTunnelPrivategroupId" not found in LDAP object
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Attribute
"radiusControlAttribute" not found in LDAP object
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Attribute
"radiusRequestAttribute" not found in LDAP object
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Attribute
"radiusReplyAttribute" not found in LDAP object
Mon Aug 22 17:43:18 2016 : Debug: rlm_ldap (ldap): Released connection (1)
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from ldap (rlm_ldap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [ldap] = updated
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
expiration (rlm_expiration) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from expiration (rlm_expiration) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [expiration] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling
logintime (rlm_logintime) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from logintime (rlm_logintime) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [logintime] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: calling pap
(rlm_pap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0) pap: Converted: Password-With-Header
= '{SSHA}8IQ1qEkhjMJHRJH0vm7ajuRNcSBw9yrp' -> SSHA1-Password =
'0x3849513171456b686a4d4a48524a4830766d37616a75524e6353427739797270'
Mon Aug 22 17:43:18 2016 : Debug: (0) pap: Removing
&control:Password-With-Header
Mon Aug 22 17:43:18 2016 : Debug: (0) pap: Normalizing SSHA1-Password from
base64 encoding, 32 bytes -> 24 bytes
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authorize]: returned
from pap (rlm_pap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [pap] = updated
Mon Aug 22 17:43:18 2016 : Debug: (0)   } # authorize = updated
Mon Aug 22 17:43:18 2016 : Debug: (0) Found Auth-Type = PAP
Mon Aug 22 17:43:18 2016 : Debug: (0) # Executing group from file
/etc/freeradius/sites-enabled/default
Mon Aug 22 17:43:18 2016 : Debug: (0)   Auth-Type PAP {
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authenticate]: calling
pap (rlm_pap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0) pap: Login attempt with password
"openldap" (8)
Mon Aug 22 17:43:18 2016 : Debug: (0) pap: Comparing with "known-good"
SSHA-Password
Mon Aug 22 17:43:18 2016 : Debug: (0) pap: User authenticated successfully
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[authenticate]: returned
from pap (rlm_pap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [pap] = ok
Mon Aug 22 17:43:18 2016 : Debug: (0)   } # Auth-Type PAP = ok
Mon Aug 22 17:43:18 2016 : Debug: (0) # Executing section post-auth from
file /etc/freeradius/sites-enabled/default
Mon Aug 22 17:43:18 2016 : Debug: (0)   post-auth {
Mon Aug 22 17:43:18 2016 : Debug: (0)     update {
Mon Aug 22 17:43:18 2016 : Debug: (0)       No attributes updated
Mon Aug 22 17:43:18 2016 : Debug: (0)     } # update = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     if (Ldap-Group ==
"SeminaryAdmin") {
Mon Aug 22 17:43:18 2016 : Debug: (0)     Searching for user in group
"SeminaryAdmin"
Mon Aug 22 17:43:18 2016 : Debug: rlm_ldap (ldap): Reserved connection (2)
Mon Aug 22 17:43:18 2016 : Debug: (0)     Using user DN from request
"cn=ttester,cn=SeminaryAdmin,ou=SeminaryOU,dc=seminary,dc=local"
Mon Aug 22 17:43:18 2016 : Debug: (0)     Checking user object's memberOf
attributes
Mon Aug 22 17:43:18 2016 : Debug: (0)       Performing unfiltered search in
"cn=ttester,cn=SeminaryAdmin,ou=SeminaryOU,dc=seminary,dc=local", scope
"base"
Mon Aug 22 17:43:18 2016 : Debug: (0)       Waiting for search result...
Mon Aug 22 17:43:18 2016 : Debug: (0)     No group membership attribute(s)
found in user object
Mon Aug 22 17:43:18 2016 : Debug: rlm_ldap (ldap): Released connection (2)
Mon Aug 22 17:43:18 2016 : Debug: (0)     User is not a member of
"SeminaryAdmin"
Mon Aug 22 17:43:18 2016 : Debug: (0)     if (Ldap-Group ==
"SeminaryAdmin")  -> FALSE
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[post-auth]: calling
ldap (rlm_ldap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: .
Mon Aug 22 17:43:18 2016 : Debug: Parsed xlat tree:
Mon Aug 22 17:43:18 2016 : Debug: literal --> .
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND .
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap:    --> .
Mon Aug 22 17:43:18 2016 : Debug: Authenticated at %S
Mon Aug 22 17:43:18 2016 : Debug: Parsed xlat tree:
Mon Aug 22 17:43:18 2016 : Debug: literal --> Authenticated at
Mon Aug 22 17:43:18 2016 : Debug: percent --> S
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: EXPAND Authenticated at %S
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap:    --> Authenticated at
2016-08-22 17:43:18
Mon Aug 22 17:43:18 2016 : Debug: rlm_ldap (ldap): Reserved connection (3)
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Using user DN from request
"cn=ttester,cn=SeminaryAdmin,ou=SeminaryOU,dc=seminary,dc=local"
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Modifying object with DN
"cn=ttester,cn=SeminaryAdmin,ou=SeminaryOU,dc=seminary,dc=local"
Mon Aug 22 17:43:18 2016 : Debug: (0) ldap: Waiting for modify result...
Mon Aug 22 17:43:18 2016 : Debug: rlm_ldap (ldap): Released connection (3)
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[post-auth]: returned
from ldap (rlm_ldap) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [ldap] = ok
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[post-auth]: calling
exec (rlm_exec) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     modsingle[post-auth]: returned
from exec (rlm_exec) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)     [exec] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     policy
remove_reply_message_if_eap {
Mon Aug 22 17:43:18 2016 : Debug: (0)       if (&reply:EAP-Message &&
&reply:Reply-Message) {
Mon Aug 22 17:43:18 2016 : Debug: (0)       if (&reply:EAP-Message &&
&reply:Reply-Message)  -> FALSE
Mon Aug 22 17:43:18 2016 : Debug: (0)       else {
Mon Aug 22 17:43:18 2016 : Debug: (0)         modsingle[post-auth]: calling
noop (rlm_always) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)         modsingle[post-auth]:
returned from noop (rlm_always) for request 0
Mon Aug 22 17:43:18 2016 : Debug: (0)         [noop] = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)       } # else = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)     } # policy
remove_reply_message_if_eap = noop
Mon Aug 22 17:43:18 2016 : Debug: (0)   } # post-auth = ok
Mon Aug 22 17:43:18 2016 : Debug: (0) Sent Access-Accept Id 100 from
127.0.0.1:1812 to 127.0.0.1:41765 length 0
Mon Aug 22 17:43:18 2016 : Debug: (0) Finished request
Mon Aug 22 17:43:18 2016 : Debug: Waking up in 4.9 seconds.
Mon Aug 22 17:43:23 2016 : Debug: (0) Cleaning up request packet ID 100
with timestamp +4
Mon Aug 22 17:43:23 2016 : Info: Ready to process requests