If you just use radiusd -X it hides the passwords in the debug output for you. That's why on the list we always ask for the output of radiusd -X not radiusd -Xx. 99% of the time you should use radiusd -X. I use radiusd -X when i'm debugging configs. The rest of the output isn't useful unless you're trying to debug a specific issue in code, it just makes the debug output harder to read.
Fri Feb 27 11:47:46 2015 : Debug: if { Fri Feb 27 11:47:46 2015 : Debug: attribute --> Stripped-User-Name Fri Feb 27 11:47:46 2015 : Debug: } Fri Feb 27 11:47:46 2015 : Debug: else { Fri Feb 27 11:47:46 2015 : Debug: attribute --> User-Name Fri Feb 27 11:47:46 2015 : Debug: } Fri Feb 27 11:47:46 2015 : Debug: literal --> ) Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}}) Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: --> (uid=qaresdon) Fri Feb 27 11:47:46 2015 : Debug: ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:46 2015 : Debug: Parsed xlat tree: Fri Feb 27 11:47:46 2015 : Debug: literal --> ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: EXPAND ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: --> ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: Performing search in 'ou=Customers,dc=brighthouse,dc=com' with filter '(uid=qaresdon)', scope 'sub' Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: Waiting for search result... Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: User object found at DN "rrCustomerID=A6398B1D-9057-4873-B13F-E41B1808B52A,ou=18,ou=Customers,dc=brighthouse,dc=com" Fri Feb 27 11:47:46 2015 : Debug: (1) ldap: Added eDirectory password. control:Cleartext-Password += 'xxxxxxxxx' Fri Feb 27 11:47:46 2015 : Debug: rlm_ldap (ldap): Released connection (4) Fri Feb 27 11:47:46 2015 : Info: rlm_ldap (ldap): Closing connection (0), from 1 unused connections Fri Feb 27 11:47:46 2015 : Debug: rlm_ldap: Closing libldap handle 0x1ae5a40 Fri Feb 27 11:47:46 2015 : Debug: (1) modsingle[authorize]: returned from ldap (rlm_ldap) for request 1 Fri Feb 27 11:47:46 2015 : Debug: (1) [ldap] = ok Fri Feb 27 11:47:46 2015 : Debug: (1) modsingle[authorize]: calling expiration (rlm_expiration) for request 1 Fri Feb 27 11:47:46 2015 : Debug: (1) modsingle[authorize]: returned from expiration (rlm_expiration) for request 1 Fri Feb 27 11:47:46 2015 : Debug: (1) [expiration] = noop Fri Feb 27 11:47:46 2015 : Debug: (1) modsingle[authorize]: calling logintime (rlm_logintime) for request 1 Fri Feb 27 11:47:46 2015 : Debug: (1) modsingle[authorize]: returned from logintime (rlm_logintime) for request 1 Fri Feb 27 11:47:46 2015 : Debug: (1) [logintime] = noop Fri Feb 27 11:47:46 2015 : Debug: (1) } # authorize = updated
Don't list LDAP in the outer server, you only need passwords in the inner server.
Fri Feb 27 11:47:49 2015 : Debug: (6) eap_ttls: Sending tunneled request Fri Feb 27 11:47:49 2015 : Debug: (6) Virtual server received request Fri Feb 27 11:47:49 2015 : Debug: (6) User-Name = 'qaresdon' Fri Feb 27 11:47:49 2015 : Debug: (6) MS-CHAP-Challenge = 0xaf2fdf5314c6b2d4080496ccd142e6e1 Fri Feb 27 11:47:49 2015 : Debug: (6) MS-CHAP2-Response = 0xd2001d385400b1d0f0200000002b00000057000000000000000066eec45b7cacf02aff803f58e135eecfd4655da4e2ee2efe Fri Feb 27 11:47:49 2015 : Debug: (6) server inner-tunnel { Fri Feb 27 11:47:49 2015 : Debug: (6) session-state: No State attribute Fri Feb 27 11:47:49 2015 : Debug: (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Fri Feb 27 11:47:49 2015 : Debug: (6) authorize { Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: calling suffix (rlm_realm) for request 6 Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: Checking for suffix after "@" Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: No '@' in User-Name = "qaresdon", looking up realm NULL Fri Feb 27 11:47:49 2015 : Debug: (6) suffix: No such realm "NULL" Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: returned from suffix (rlm_realm) for request 6 Fri Feb 27 11:47:49 2015 : Debug: (6) [suffix] = noop Fri Feb 27 11:47:49 2015 : Debug: (6) update control { Fri Feb 27 11:47:49 2015 : Debug: (6) &Proxy-To-Realm := 'LOCAL' Fri Feb 27 11:47:49 2015 : Debug: (6) } # update control = noop Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: calling files (rlm_files) for request 6 Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: returned from files (rlm_files) for request 6 Fri Feb 27 11:47:49 2015 : Debug: (6) [files] = noop Fri Feb 27 11:47:49 2015 : Debug: (6) update control { Fri Feb 27 11:47:49 2015 : Debug: (6) Cache-Status-Only = yes Fri Feb 27 11:47:49 2015 : Debug: (6) } # update control = noop Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: calling cache (rlm_cache) for request 6 Fri Feb 27 11:47:49 2015 : Debug: %{User-Name}%{outer.request:Calling-Station-Id} Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree: Fri Feb 27 11:47:49 2015 : Debug: attribute --> User-Name Fri Feb 27 11:47:49 2015 : Debug: attribute --> Calling-Station-Id Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id} Fri Feb 27 11:47:49 2015 : Debug: (6) cache: --> qaresdone899c47233d8 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex acquired Fri Feb 27 11:47:49 2015 : Debug: (6) cache: No cache entry found for "qaresdone899c47233d8" Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex released Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: returned from cache (rlm_cache) for request 6 Fri Feb 27 11:47:49 2015 : Debug: (6) [cache] = notfound
and the user hasn't been found, because cache hasn't been called before and the rbtree driver doesn't persist the cache contents across server restarts.
Fri Feb 27 11:47:49 2015 : Debug: (6) if (notfound) { Fri Feb 27 11:47:49 2015 : Debug: (6) if (notfound) -> TRUE Fri Feb 27 11:47:49 2015 : Debug: (6) if (notfound) { Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: calling ldap (rlm_ldap) for request 6 Fri Feb 27 11:47:49 2015 : Debug: rlm_ldap (ldap): Reserved connection (4) Fri Feb 27 11:47:49 2015 : Debug: (uid=%{%{Stripped-User-Name}:-%{User-Name}}) Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree: Fri Feb 27 11:47:49 2015 : Debug: literal --> (uid= Fri Feb 27 11:47:49 2015 : Debug: if { Fri Feb 27 11:47:49 2015 : Debug: attribute --> Stripped-User-Name Fri Feb 27 11:47:49 2015 : Debug: } Fri Feb 27 11:47:49 2015 : Debug: else { Fri Feb 27 11:47:49 2015 : Debug: attribute --> User-Name Fri Feb 27 11:47:49 2015 : Debug: } Fri Feb 27 11:47:49 2015 : Debug: literal --> ) Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}}) Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: --> (uid=qaresdon) Fri Feb 27 11:47:49 2015 : Debug: ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree: Fri Feb 27 11:47:49 2015 : Debug: literal --> ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: EXPAND ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: --> ou=Customers,dc=brighthouse,dc=com Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: Performing search in 'ou=Customers,dc=brighthouse,dc=com' with filter '(uid=qaresdon)', scope 'sub' Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: Waiting for search result... Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: User object found at DN "rrCustomerID=A6398B1D-9057-4873-B13F-E41B1808B52A,ou=18,ou=Customers,dc=brighthouse,dc=com" Fri Feb 27 11:47:49 2015 : Debug: (6) ldap: Added eDirectory password. control:Cleartext-Password += 'xxxxxxxxx' Fri Feb 27 11:47:49 2015 : Debug: rlm_ldap (ldap): Released connection (4) Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[authorize]: returned from ldap (rlm_ldap) for request 6 Fri Feb 27 11:47:49 2015 : Debug: (6) [ldap] = ok Fri Feb 27 11:47:49 2015 : Debug: attribute --> User-Name Fri Feb 27 11:47:49 2015 : Debug: attribute --> Calling-Station-Id Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{User-Name}%{outer.request:Calling-Station-Id} Fri Feb 27 11:47:49 2015 : Debug: (6) cache: --> qaresdone899c47233d8 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex acquired Fri Feb 27 11:47:49 2015 : Debug: (6) cache: No cache entry found for "qaresdone899c47233d8" Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Creating new cache entry Fri Feb 27 11:47:49 2015 : Debug: %{control:NT-Password} Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree: Fri Feb 27 11:47:49 2015 : Debug: attribute --> NT-Password Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{control:NT-Password} Fri Feb 27 11:47:49 2015 : Debug: (6) cache: --> 0x5835048ce94ad0564e29a924a03510ef Fri Feb 27 11:47:49 2015 : Debug: (6) cache: control:NT-Password := 0x5835048ce94ad0564e29a924a03510ef Fri Feb 27 11:47:49 2015 : Debug: %{control:LM-Password} Fri Feb 27 11:47:49 2015 : Debug: Parsed xlat tree: Fri Feb 27 11:47:49 2015 : Debug: attribute --> LM-Password Fri Feb 27 11:47:49 2015 : Debug: (6) cache: EXPAND %{control:LM-Password} Fri Feb 27 11:47:49 2015 : Debug: (6) cache: --> 0xe52cac67419a9a2238f10713b629b565 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: control:LM-Password := 0xe52cac67419a9a2238f10713b629b565 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Merging cache entry into request Fri Feb 27 11:47:49 2015 : Debug: (6) cache: &control:NT-Password := 0x5835048ce94ad0564e29a924a03510ef Fri Feb 27 11:47:49 2015 : Debug: (6) cache: &control:LM-Password := 0xe52cac67419a9a2238f10713b629b565
This works. It's not really more secure than caching the cleartext password, but it does avoid some small overhead rehashing the cleartext password each time.
Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: FROM 2 TO 6 MAX 8 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: Examining NT-Password Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: OVERWRITING NT-Password FROM 0 TO 4 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: Examining LM-Password Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: OVERWRITING LM-Password FROM 1 TO 5 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: TO in 6 out 6 Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[0] = Proxy-To-Realm Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[1] = Ldap-UserDn Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[2] = Cleartext-Password Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[3] = Auth-Type Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[4] = NT-Password Fri Feb 27 11:47:49 2015 : Debug: (6) cache: ::: to[5] = LM-Password Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Commited entry, TTL 86400 seconds Fri Feb 27 11:47:49 2015 : Debug: (6) cache: Mutex released Fri Feb 27 11:47:49 2015 : Debug: (6) modsingle[post-auth]: returned from cache (rlm_cache) for request 6 Fri Feb 27 11:47:49 2015 : Debug: (6) [cache] = updated Fri Feb 27 11:47:49 2015 : Debug: (6) } # post-auth = updated Fri Feb 27 11:47:49 2015 : Debug: (6) } # server inner-tunnel
and no more calls to cache, so i'm not sure what you were expecting to happen. For the PEAP request the cache will have been cleared as the server has been restarted. If you want a persistent cache, you need to use the memcached driver and run a memcached server. That won't persist across memcached restarts though. For that there'd need to be a new file system based cache driver. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2