Freeradius can't authenticate pptp users from Windows XP to LDAP
Hi, Sorry to bother, I've been reading almost every post here that talks about the same problem that I'm encountering, but I didn't find any solution for my trouble. Here is the thing, I'm using freeradius + LDAP + pptpd, to authenticate windows VPN Users. When I put users Cleartext-password in the freeradius'users file, everything works fine, but when I remove this information from users'file and I want that the authentication to be done by LDAP database, nothing works. Here is my users in LDAP database, for tests : dn: uid=light,ou=vpn,dc=home objectClass: account objectClass: simpleSecurityObject objectClass: radiusprofile uid: light cn: The Tester structuralObjectClass: account entryUUID: 74eeffe8-47c0-102e-87e0-8d7f2b5bb553 creatorsName: createTimestamp: 20091007190752Z userPassword:: dGVzdGVy entryCSN: 20091007193817.121196Z#000000#000#000000 modifiersName: cn=admin,dc=home modifyTimestamp: 20091007193817Z dn: uid=flash,ou=vpn,dc=home objectClass: account objectClass: simpleSecurityObject objectClass: radiusprofile uid: flash cn: Second one userPassword:: dGVzdGVy structuralObjectClass: account entryUUID: 6fa73a2e-47c4-102e-8f78-e10206a13f31 creatorsName: createTimestamp: 20091007193621Z entryCSN: 20091007193621.607389Z#000000#000#000000 modifiersName: modifyTimestamp: 20091007193621Z And there, my Debug from freeradius : Info: FreeRADIUS Version 2.0.4, for host i486-pc-linux-gnu, built on Oct 3 2009 at 19:16:29 Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Info: PARTICULAR PURPOSE. Info: You may redistribute copies of FreeRADIUS under the terms of the Info: GNU General Public License. Info: Starting - reading configuration files ... Debug: including configuration file /etc/freeradius/radiusd.conf Debug: including configuration file /etc/freeradius/clients.conf Debug: including configuration file /etc/freeradius/policy.conf Debug: including files in directory /etc/freeradius/sites-enabled/ Debug: including configuration file /etc/freeradius/sites-enabled/default Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Debug: including dictionary file /etc/freeradius/dictionary Debug: main { Debug: prefix = "/usr" Debug: localstatedir = "/var" Debug: logdir = "/var/log/freeradius" Debug: libdir = "/usr/lib/freeradius" Debug: radacctdir = "/var/log/freeradius/radacct" Debug: hostname_lookups = no Debug: max_request_time = 30 Debug: cleanup_delay = 5 Debug: max_requests = 1024 Debug: allow_core_dumps = no Debug: pidfile = "/var/run/freeradius/freeradius.pid" Debug: user = "freerad" Debug: group = "freerad" Debug: checkrad = "/usr/sbin/checkrad" Debug: debug_level = 0 Debug: proxy_requests = yes Debug: security { Debug: max_attributes = 200 Debug: reject_delay = 1 Debug: status_server = yes Debug: } Debug: } Debug: client localhost { Debug: ipaddr = 127.0.0.1 Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: nastype = "other" Debug: } Debug: client 192.168.0.0/24 { Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: shortname = "private-network-1" Debug: } Debug: radiusd: #### Loading Realms and Home Servers #### Debug: radiusd: #### Instantiating modules #### Debug: instantiate { Debug: (Loaded rlm_exec, checking if it's valid) Debug: Module: Linked to module rlm_exec Debug: Module: Instantiating exec Debug: exec { Debug: wait = yes Debug: input_pairs = "request" Debug: shell_escape = yes Debug: } Debug: (Loaded rlm_expr, checking if it's valid) Debug: Module: Linked to module rlm_expr Debug: Module: Instantiating expr Debug: (Loaded rlm_expiration, checking if it's valid) Debug: Module: Linked to module rlm_expiration Debug: Module: Instantiating expiration Debug: expiration { Debug: reply-message = "Password Has Expired " Debug: } Debug: (Loaded rlm_logintime, checking if it's valid) Debug: Module: Linked to module rlm_logintime Debug: Module: Instantiating logintime Debug: logintime { Debug: reply-message = "You are calling outside your allowed timespan " Debug: minimum-timeout = 60 Debug: } Debug: } Debug: radiusd: #### Loading Virtual Servers #### Debug: server inner-tunnel { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: (Loaded rlm_pap, checking if it's valid) Debug: Module: Linked to module rlm_pap Debug: Module: Instantiating pap Debug: pap { Debug: encryption_scheme = "auto" Debug: auto_header = no Debug: } Debug: (Loaded rlm_chap, checking if it's valid) Debug: Module: Linked to module rlm_chap Debug: Module: Instantiating chap Debug: (Loaded rlm_mschap, checking if it's valid) Debug: Module: Linked to module rlm_mschap Debug: Module: Instantiating mschap Debug: mschap { Debug: use_mppe = yes Debug: require_encryption = no Debug: require_strong = no Debug: with_ntdomain_hack = no Debug: } Debug: (Loaded rlm_unix, checking if it's valid) Debug: Module: Linked to module rlm_unix Debug: Module: Instantiating unix Debug: unix { Debug: radwtmp = "/var/log/freeradius/radwtmp" Debug: } Debug: (Loaded rlm_ldap, checking if it's valid) Debug: Module: Linked to module rlm_ldap Debug: Module: Instantiating ldap Debug: ldap { Debug: server = "localhost" Debug: port = 389 Debug: password = "" Debug: identity = "" Debug: net_timeout = 1 Debug: timeout = 4 Debug: timelimit = 3 Debug: tls_mode = no Debug: start_tls = no Debug: tls_require_cert = "allow" Debug: tls { Debug: start_tls = no Debug: require_cert = "allow" Debug: } Debug: basedn = "ou=vpn,dc=home" Debug: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Debug: base_filter = "(objectclass=radiusprofile)" Debug: password_attribute = "userPassword" Debug: auto_header = yes Debug: access_attr_used_for_allow = yes Debug: groupname_attribute = "cn" Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Debug: dictionary_mapping = "/etc/freeradius/ldap.attrmap" Debug: ldap_debug = 0 Debug: ldap_connections_number = 5 Debug: compare_check_items = no Debug: do_xlat = yes Debug: edir_account_policy_check = no Debug: set_auth_type = no Debug: } Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Debug: rlm_ldap: reading ldap<->radius mappings from file /etc/freeradius/ldap.attrmap Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP digestHA1 mapped to RADIUS Digest-HA1 Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Debug: rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP ntHash mapped to RADIUS NT-Hash Debug: rlm_ldap: LDAP lmHash mapped to RADIUS LM-Hash Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Debug: conns: 0x85f0988 Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_realm, checking if it's valid) Debug: Module: Linked to module rlm_realm Debug: Module: Instantiating suffix Debug: realm suffix { Debug: format = "suffix" Debug: delimiter = "@" Debug: ignore_default = no Debug: ignore_null = no Debug: } Debug: (Loaded rlm_files, checking if it's valid) Debug: Module: Linked to module rlm_files Debug: Module: Instantiating files Debug: files { Debug: usersfile = "/etc/freeradius/users" Debug: acctusersfile = "/etc/freeradius/acct_users" Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Debug: compat = "no" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: (Loaded rlm_radutmp, checking if it's valid) Debug: Module: Linked to module rlm_radutmp Debug: Module: Instantiating radutmp Debug: radutmp { Debug: filename = "/var/log/freeradius/radutmp" Debug: username = "%{User-Name}" Debug: case_sensitive = yes Debug: check_with_nas = yes Debug: perm = 384 Debug: callerid = yes Debug: } Debug: Module: Checking post-auth {...} for more modules to load Debug: (Loaded rlm_attr_filter, checking if it's valid) Debug: Module: Linked to module rlm_attr_filter Debug: Module: Instantiating attr_filter.access_reject Debug: attr_filter attr_filter.access_reject { Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Debug: key = "%{User-Name}" Debug: } Debug: } Debug: } Debug: server { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_preprocess, checking if it's valid) Debug: Module: Linked to module rlm_preprocess Debug: Module: Instantiating preprocess Debug: preprocess { Debug: huntgroups = "/etc/freeradius/huntgroups" Debug: hints = "/etc/freeradius/hints" Debug: with_ascend_hack = no Debug: ascend_channels_per_line = 23 Debug: with_ntdomain_hack = no Debug: with_specialix_jetstream_hack = no Debug: with_cisco_vsa_hack = no Debug: with_alvarion_vsa_hack = no Debug: } Debug: Module: Checking preacct {...} for more modules to load Debug: (Loaded rlm_acct_unique, checking if it's valid) Debug: Module: Linked to module rlm_acct_unique Debug: Module: Instantiating acct_unique Debug: acct_unique { Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Debug: } Debug: Module: Checking accounting {...} for more modules to load Debug: (Loaded rlm_detail, checking if it's valid) Debug: Module: Linked to module rlm_detail Debug: Module: Instantiating detail Debug: detail { Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Debug: header = "%t" Debug: detailperm = 384 Debug: dirperm = 493 Debug: locking = no Debug: log_packet_header = no Debug: } Debug: Module: Instantiating attr_filter.accounting_response Debug: attr_filter attr_filter.accounting_response { Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Debug: key = "%{User-Name}" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: Module: Checking post-auth {...} for more modules to load Debug: } Debug: } Debug: radiusd: #### Opening IP addresses and Ports #### Debug: listen { Debug: type = "auth" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: listen { Debug: type = "acct" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: main { Debug: snmp = no Debug: smux_password = "" Debug: snmp_write_access = no Debug: } Debug: Listening on authentication address * port 1812 Debug: Listening on accounting address * port 1813 Debug: Listening on proxy address * port 1814 Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 42393, id=88, length=144 Service-Type = Framed-User Framed-Protocol = PPP User-Name = "light" MS-CHAP-Challenge = 0xb0e4f30555c866750a41eca5b070dd38 MS-CHAP2-Response = 0x0600ee6e8f48c9792c51f31cd89d99b33bdb0000000000000000b2e5571c233fe74a670d9dc9fbc59caf3076ab53eff195fe Calling-Station-Id = "192.168.0.1" NAS-IP-Address = 0x0101 NAS-Port = 0 Debug: +- entering group authorize Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Debug: ++[preprocess] returns ok Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Debug: ++[chap] returns noop Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Debug: rlm_ldap: - authorize Debug: rlm_ldap: performing user authorization for light Debug: WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Debug: expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=light) Debug: expand: ou=vpn,dc=home -> ou=vpn,dc=home Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Debug: rlm_ldap: attempting LDAP reconnection Debug: rlm_ldap: (re)connect to localhost:389, authentication 0 Debug: rlm_ldap: bind as / to localhost:389 Debug: rlm_ldap: waiting for bind result ... Debug: rlm_ldap: Bind was successful Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Debug: rlm_ldap: user light authorized to use remote access Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Debug: ++[ldap] returns ok Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns ok Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Debug: rlm_realm: No '@' in User-Name = "light", looking up realm NULL Debug: rlm_realm: No such realm "NULL" Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Debug: ++[suffix] returns noop Debug: modsingle[authorize]: calling unix (rlm_unix) for request 0 Debug: modsingle[authorize]: returned from unix (rlm_unix) for request 0 Debug: ++[unix] returns notfound Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Debug: ++[files] returns noop Debug: modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Debug: modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Debug: ++[expiration] returns noop Debug: modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Debug: modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Debug: ++[logintime] returns noop Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Debug: ++[pap] returns noop Debug: rad_check_password: Found Auth-Type mschap Debug: auth: type "MSCHAP" Debug: +- entering group MS-CHAP Debug: modsingle[authenticate]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: No Cleartext-Password configured. Cannot create LM-Password. Debug: rlm_mschap: No Cleartext-Password configured. Cannot create NT-Password. Debug: rlm_mschap: Told to do MS-CHAPv2 for light with NT-Password Debug: rlm_mschap: FAILED: No NT/LM-Password. Cannot perform authentication. Debug: rlm_mschap: FAILED: MS-CHAP2-Response is incorrect Debug: modsingle[authenticate]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns reject Debug: auth: Failed to validate the user. Auth: Login incorrect: [light/<via Auth-Type = mschap>] (from client localhost port 0 cli 192.168.0.1) Debug: Found Post-Auth-Type Reject Debug: +- entering group REJECT Debug: modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: expand: %{User-Name} -> light Debug: attr_filter: Matched entry DEFAULT at line 11 Debug: modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: ++[attr_filter.access_reject] returns updated Debug: Delaying reject of request 0 for 1 seconds Debug: Going to the next request Debug: Waking up in 0.9 seconds. Debug: Sending delayed reject for request 0 Sending Access-Reject of id 88 to 127.0.0.1 port 42393 Debug: Waking up in 4.9 seconds. Debug: Cleaning up request 0 ID 88 with timestamp +8 Debug: Ready to process requests. Thank you very much for your Help. Tede -- View this message in context: http://www.nabble.com/Freeradius-can%27t-authenticate-pptp-users-from-Window... Sent from the FreeRadius - User mailing list archive at Nabble.com.
Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly?
Hm, try adding mapping for Cleartext-Password as userPassword to ldap.attrmap. Ivan Kalik Kalik Informatika ISP
Ivan Kalik wrote:
Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly?
Hm, try adding mapping for Cleartext-Password as userPassword to ldap.attrmap.
Ivan Kalik Kalik Informatika ISP
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Ivan, first of all, thanks for answering me :) So, here is the result after adding mapping for Cleartext-Password as userPassword, as we can see in the radius mapping part of the debug : Info: FreeRADIUS Version 2.0.4, for host i486-pc-linux-gnu, built on Oct 3 2009 at 19:16:29 Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Info: PARTICULAR PURPOSE. Info: You may redistribute copies of FreeRADIUS under the terms of the Info: GNU General Public License. Info: Starting - reading configuration files ... Debug: including configuration file /etc/freeradius/radiusd.conf Debug: including configuration file /etc/freeradius/clients.conf Debug: including configuration file /etc/freeradius/policy.conf Debug: including files in directory /etc/freeradius/sites-enabled/ Debug: including configuration file /etc/freeradius/sites-enabled/default Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Debug: including dictionary file /etc/freeradius/dictionary Debug: main { Debug: prefix = "/usr" Debug: localstatedir = "/var" Debug: logdir = "/var/log/freeradius" Debug: libdir = "/usr/lib/freeradius" Debug: radacctdir = "/var/log/freeradius/radacct" Debug: hostname_lookups = no Debug: max_request_time = 30 Debug: cleanup_delay = 5 Debug: max_requests = 1024 Debug: allow_core_dumps = no Debug: pidfile = "/var/run/freeradius/freeradius.pid" Debug: user = "freerad" Debug: group = "freerad" Debug: checkrad = "/usr/sbin/checkrad" Debug: debug_level = 0 Debug: proxy_requests = yes Debug: security { Debug: max_attributes = 200 Debug: reject_delay = 1 Debug: status_server = yes Debug: } Debug: } Debug: client localhost { Debug: ipaddr = 127.0.0.1 Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: nastype = "other" Debug: } Debug: client 192.168.0.0/24 { Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: shortname = "private-network-1" Debug: } Debug: radiusd: #### Loading Realms and Home Servers #### Debug: radiusd: #### Instantiating modules #### Debug: instantiate { Debug: (Loaded rlm_exec, checking if it's valid) Debug: Module: Linked to module rlm_exec Debug: Module: Instantiating exec Debug: exec { Debug: wait = yes Debug: input_pairs = "request" Debug: shell_escape = yes Debug: } Debug: (Loaded rlm_expr, checking if it's valid) Debug: Module: Linked to module rlm_expr Debug: Module: Instantiating expr Debug: (Loaded rlm_expiration, checking if it's valid) Debug: Module: Linked to module rlm_expiration Debug: Module: Instantiating expiration Debug: expiration { Debug: reply-message = "Password Has Expired " Debug: } Debug: (Loaded rlm_logintime, checking if it's valid) Debug: Module: Linked to module rlm_logintime Debug: Module: Instantiating logintime Debug: logintime { Debug: reply-message = "You are calling outside your allowed timespan " Debug: minimum-timeout = 60 Debug: } Debug: } Debug: radiusd: #### Loading Virtual Servers #### Debug: server inner-tunnel { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: (Loaded rlm_pap, checking if it's valid) Debug: Module: Linked to module rlm_pap Debug: Module: Instantiating pap Debug: pap { Debug: encryption_scheme = "auto" Debug: auto_header = no Debug: } Debug: (Loaded rlm_chap, checking if it's valid) Debug: Module: Linked to module rlm_chap Debug: Module: Instantiating chap Debug: (Loaded rlm_mschap, checking if it's valid) Debug: Module: Linked to module rlm_mschap Debug: Module: Instantiating mschap Debug: mschap { Debug: use_mppe = yes Debug: require_encryption = no Debug: require_strong = no Debug: with_ntdomain_hack = no Debug: } Debug: (Loaded rlm_unix, checking if it's valid) Debug: Module: Linked to module rlm_unix Debug: Module: Instantiating unix Debug: unix { Debug: radwtmp = "/var/log/freeradius/radwtmp" Debug: } Debug: (Loaded rlm_ldap, checking if it's valid) Debug: Module: Linked to module rlm_ldap Debug: Module: Instantiating ldap Debug: ldap { Debug: server = "localhost" Debug: port = 389 Debug: password = "" Debug: identity = "" Debug: net_timeout = 1 Debug: timeout = 4 Debug: timelimit = 3 Debug: tls_mode = no Debug: start_tls = no Debug: tls_require_cert = "allow" Debug: tls { Debug: start_tls = no Debug: require_cert = "allow" Debug: } Debug: basedn = "ou=vpn,dc=home" Debug: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Debug: base_filter = "(objectclass=radiusprofile)" Debug: password_attribute = "userPassword" Debug: auto_header = yes Debug: access_attr_used_for_allow = yes Debug: groupname_attribute = "cn" Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Debug: dictionary_mapping = "/etc/freeradius/ldap.attrmap" Debug: ldap_debug = 0 Debug: ldap_connections_number = 5 Debug: compare_check_items = no Debug: do_xlat = yes Debug: edir_account_policy_check = no Debug: set_auth_type = no Debug: } Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Debug: rlm_ldap: reading ldap<->radius mappings from file /etc/freeradius/ldap.attrmap Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP digestHA1 mapped to RADIUS Digest-HA1 Debug: rlm_ldap: LDAP userPassword mapped to RADIUS Cleartext-Password Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Debug: rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP ntHash mapped to RADIUS NT-Hash Debug: rlm_ldap: LDAP lmHash mapped to RADIUS LM-Hash Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Debug: conns: 0x85c8988 Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_realm, checking if it's valid) Debug: Module: Linked to module rlm_realm Debug: Module: Instantiating suffix Debug: realm suffix { Debug: format = "suffix" Debug: delimiter = "@" Debug: ignore_default = no Debug: ignore_null = no Debug: } Debug: (Loaded rlm_files, checking if it's valid) Debug: Module: Linked to module rlm_files Debug: Module: Instantiating files Debug: files { Debug: usersfile = "/etc/freeradius/users" Debug: acctusersfile = "/etc/freeradius/acct_users" Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Debug: compat = "no" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: (Loaded rlm_radutmp, checking if it's valid) Debug: Module: Linked to module rlm_radutmp Debug: Module: Instantiating radutmp Debug: radutmp { Debug: filename = "/var/log/freeradius/radutmp" Debug: username = "%{User-Name}" Debug: case_sensitive = yes Debug: check_with_nas = yes Debug: perm = 384 Debug: callerid = yes Debug: } Debug: Module: Checking post-auth {...} for more modules to load Debug: (Loaded rlm_attr_filter, checking if it's valid) Debug: Module: Linked to module rlm_attr_filter Debug: Module: Instantiating attr_filter.access_reject Debug: attr_filter attr_filter.access_reject { Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Debug: key = "%{User-Name}" Debug: } Debug: } Debug: } Debug: server { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_preprocess, checking if it's valid) Debug: Module: Linked to module rlm_preprocess Debug: Module: Instantiating preprocess Debug: preprocess { Debug: huntgroups = "/etc/freeradius/huntgroups" Debug: hints = "/etc/freeradius/hints" Debug: with_ascend_hack = no Debug: ascend_channels_per_line = 23 Debug: with_ntdomain_hack = no Debug: with_specialix_jetstream_hack = no Debug: with_cisco_vsa_hack = no Debug: with_alvarion_vsa_hack = no Debug: } Debug: Module: Checking preacct {...} for more modules to load Debug: (Loaded rlm_acct_unique, checking if it's valid) Debug: Module: Linked to module rlm_acct_unique Debug: Module: Instantiating acct_unique Debug: acct_unique { Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Debug: } Debug: Module: Checking accounting {...} for more modules to load Debug: (Loaded rlm_detail, checking if it's valid) Debug: Module: Linked to module rlm_detail Debug: Module: Instantiating detail Debug: detail { Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Debug: header = "%t" Debug: detailperm = 384 Debug: dirperm = 493 Debug: locking = no Debug: log_packet_header = no Debug: } Debug: Module: Instantiating attr_filter.accounting_response Debug: attr_filter attr_filter.accounting_response { Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Debug: key = "%{User-Name}" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: Module: Checking post-auth {...} for more modules to load Debug: } Debug: } Debug: radiusd: #### Opening IP addresses and Ports #### Debug: listen { Debug: type = "auth" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: listen { Debug: type = "acct" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: main { Debug: snmp = no Debug: smux_password = "" Debug: snmp_write_access = no Debug: } Debug: Listening on authentication address * port 1812 Debug: Listening on accounting address * port 1813 Debug: Listening on proxy address * port 1814 Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 58943, id=90, length=144 Service-Type = Framed-User Framed-Protocol = PPP User-Name = "light" MS-CHAP-Challenge = 0x0478587b0fbb0f95a407ca180b2f8a37 MS-CHAP2-Response = 0xd300647b6787cf9c9d95e042b5ba55d38d180000000000000000261560ec809d3c64cefc034d7af5be715a3570723e5dbe2f Calling-Station-Id = "192.168.0.1" NAS-IP-Address = 0x0101 NAS-Port = 0 Debug: +- entering group authorize Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Debug: ++[preprocess] returns ok Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Debug: ++[chap] returns noop Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Debug: rlm_ldap: - authorize Debug: rlm_ldap: performing user authorization for light Debug: WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Debug: expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=light) Debug: expand: ou=vpn,dc=home -> ou=vpn,dc=home Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Debug: rlm_ldap: attempting LDAP reconnection Debug: rlm_ldap: (re)connect to localhost:389, authentication 0 Debug: rlm_ldap: bind as / to localhost:389 Debug: rlm_ldap: waiting for bind result ... Debug: rlm_ldap: Bind was successful Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Debug: rlm_ldap: user light authorized to use remote access Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Debug: ++[ldap] returns ok Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns ok Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Debug: rlm_realm: No '@' in User-Name = "light", looking up realm NULL Debug: rlm_realm: No such realm "NULL" Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Debug: ++[suffix] returns noop Debug: modsingle[authorize]: calling unix (rlm_unix) for request 0 Debug: modsingle[authorize]: returned from unix (rlm_unix) for request 0 Debug: ++[unix] returns notfound Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Debug: ++[files] returns noop Debug: modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Debug: modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Debug: ++[expiration] returns noop Debug: modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Debug: modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Debug: ++[logintime] returns noop Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Debug: ++[pap] returns noop Debug: rad_check_password: Found Auth-Type mschap Debug: auth: type "MSCHAP" Debug: +- entering group MS-CHAP Debug: modsingle[authenticate]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: No Cleartext-Password configured. Cannot create LM-Password. Debug: rlm_mschap: No Cleartext-Password configured. Cannot create NT-Password. Debug: rlm_mschap: Told to do MS-CHAPv2 for light with NT-Password Debug: rlm_mschap: FAILED: No NT/LM-Password. Cannot perform authentication. Debug: rlm_mschap: FAILED: MS-CHAP2-Response is incorrect Debug: modsingle[authenticate]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns reject Debug: auth: Failed to validate the user. Auth: Login incorrect: [light/<via Auth-Type = mschap>] (from client localhost port 0 cli 192.168.0.1) Debug: Found Post-Auth-Type Reject Debug: +- entering group REJECT Debug: modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: expand: %{User-Name} -> light Debug: attr_filter: Matched entry DEFAULT at line 11 Debug: modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: ++[attr_filter.access_reject] returns updated Debug: Delaying reject of request 0 for 1 seconds Debug: Going to the next request Debug: Waking up in 0.9 seconds. Debug: Sending delayed reject for request 0 Sending Access-Reject of id 90 to 127.0.0.1 port 58943 Debug: Waking up in 4.9 seconds. Debug: Cleaning up request 0 ID 90 with timestamp +7 Debug: Ready to process requests. -- View this message in context: http://www.nabble.com/Freeradius-can%27t-authenticate-pptp-users-from-Window... Sent from the FreeRadius - User mailing list archive at Nabble.com.
You can add NT / LM pairs to each LDAP user object. You must include the samba.schema into the ldap server schemas. Ex: sambaNTPassword: CAF13D4F321E608B27FD75D2549BA53C sambaLMPassword: 02D093CE93038E2FAAD3B435B51404EE This way pptp MSCHAP auth will work. Nelson Vale On Thursday 08 October 2009 12:53:21 tede wrote:
Ivan Kalik wrote:
Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly?
Hm, try adding mapping for Cleartext-Password as userPassword to ldap.attrmap.
Ivan Kalik Kalik Informatika ISP
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Ivan, first of all, thanks for answering me :)
So, here is the result after adding mapping for Cleartext-Password as userPassword, as we can see in the radius mapping part of the debug :
Info: FreeRADIUS Version 2.0.4, for host i486-pc-linux-gnu, built on Oct 3 2009 at 19:16:29 Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Info: PARTICULAR PURPOSE. Info: You may redistribute copies of FreeRADIUS under the terms of the Info: GNU General Public License. Info: Starting - reading configuration files ... Debug: including configuration file /etc/freeradius/radiusd.conf Debug: including configuration file /etc/freeradius/clients.conf Debug: including configuration file /etc/freeradius/policy.conf Debug: including files in directory /etc/freeradius/sites-enabled/ Debug: including configuration file /etc/freeradius/sites-enabled/default Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Debug: including dictionary file /etc/freeradius/dictionary Debug: main { Debug: prefix = "/usr" Debug: localstatedir = "/var" Debug: logdir = "/var/log/freeradius" Debug: libdir = "/usr/lib/freeradius" Debug: radacctdir = "/var/log/freeradius/radacct" Debug: hostname_lookups = no Debug: max_request_time = 30 Debug: cleanup_delay = 5 Debug: max_requests = 1024 Debug: allow_core_dumps = no Debug: pidfile = "/var/run/freeradius/freeradius.pid" Debug: user = "freerad" Debug: group = "freerad" Debug: checkrad = "/usr/sbin/checkrad" Debug: debug_level = 0 Debug: proxy_requests = yes Debug: security { Debug: max_attributes = 200 Debug: reject_delay = 1 Debug: status_server = yes Debug: } Debug: } Debug: client localhost { Debug: ipaddr = 127.0.0.1 Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: nastype = "other" Debug: } Debug: client 192.168.0.0/24 { Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: shortname = "private-network-1" Debug: } Debug: radiusd: #### Loading Realms and Home Servers #### Debug: radiusd: #### Instantiating modules #### Debug: instantiate { Debug: (Loaded rlm_exec, checking if it's valid) Debug: Module: Linked to module rlm_exec Debug: Module: Instantiating exec Debug: exec { Debug: wait = yes Debug: input_pairs = "request" Debug: shell_escape = yes Debug: } Debug: (Loaded rlm_expr, checking if it's valid) Debug: Module: Linked to module rlm_expr Debug: Module: Instantiating expr Debug: (Loaded rlm_expiration, checking if it's valid) Debug: Module: Linked to module rlm_expiration Debug: Module: Instantiating expiration Debug: expiration { Debug: reply-message = "Password Has Expired " Debug: } Debug: (Loaded rlm_logintime, checking if it's valid) Debug: Module: Linked to module rlm_logintime Debug: Module: Instantiating logintime Debug: logintime { Debug: reply-message = "You are calling outside your allowed timespan " Debug: minimum-timeout = 60 Debug: } Debug: } Debug: radiusd: #### Loading Virtual Servers #### Debug: server inner-tunnel { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: (Loaded rlm_pap, checking if it's valid) Debug: Module: Linked to module rlm_pap Debug: Module: Instantiating pap Debug: pap { Debug: encryption_scheme = "auto" Debug: auto_header = no Debug: } Debug: (Loaded rlm_chap, checking if it's valid) Debug: Module: Linked to module rlm_chap Debug: Module: Instantiating chap Debug: (Loaded rlm_mschap, checking if it's valid) Debug: Module: Linked to module rlm_mschap Debug: Module: Instantiating mschap Debug: mschap { Debug: use_mppe = yes Debug: require_encryption = no Debug: require_strong = no Debug: with_ntdomain_hack = no Debug: } Debug: (Loaded rlm_unix, checking if it's valid) Debug: Module: Linked to module rlm_unix Debug: Module: Instantiating unix Debug: unix { Debug: radwtmp = "/var/log/freeradius/radwtmp" Debug: } Debug: (Loaded rlm_ldap, checking if it's valid) Debug: Module: Linked to module rlm_ldap Debug: Module: Instantiating ldap Debug: ldap { Debug: server = "localhost" Debug: port = 389 Debug: password = "" Debug: identity = "" Debug: net_timeout = 1 Debug: timeout = 4 Debug: timelimit = 3 Debug: tls_mode = no Debug: start_tls = no Debug: tls_require_cert = "allow" Debug: tls { Debug: start_tls = no Debug: require_cert = "allow" Debug: } Debug: basedn = "ou=vpn,dc=home" Debug: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Debug: base_filter = "(objectclass=radiusprofile)" Debug: password_attribute = "userPassword" Debug: auto_header = yes Debug: access_attr_used_for_allow = yes Debug: groupname_attribute = "cn" Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=Group OfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Debug: dictionary_mapping = "/etc/freeradius/ldap.attrmap" Debug: ldap_debug = 0 Debug: ldap_connections_number = 5 Debug: compare_check_items = no Debug: do_xlat = yes Debug: edir_account_policy_check = no Debug: set_auth_type = no Debug: } Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Debug: rlm_ldap: reading ldap<->radius mappings from file /etc/freeradius/ldap.attrmap Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP digestHA1 mapped to RADIUS Digest-HA1 Debug: rlm_ldap: LDAP userPassword mapped to RADIUS Cleartext-Password Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Debug: rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP ntHash mapped to RADIUS NT-Hash Debug: rlm_ldap: LDAP lmHash mapped to RADIUS LM-Hash Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Debug: conns: 0x85c8988 Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_realm, checking if it's valid) Debug: Module: Linked to module rlm_realm Debug: Module: Instantiating suffix Debug: realm suffix { Debug: format = "suffix" Debug: delimiter = "@" Debug: ignore_default = no Debug: ignore_null = no Debug: } Debug: (Loaded rlm_files, checking if it's valid) Debug: Module: Linked to module rlm_files Debug: Module: Instantiating files Debug: files { Debug: usersfile = "/etc/freeradius/users" Debug: acctusersfile = "/etc/freeradius/acct_users" Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Debug: compat = "no" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: (Loaded rlm_radutmp, checking if it's valid) Debug: Module: Linked to module rlm_radutmp Debug: Module: Instantiating radutmp Debug: radutmp { Debug: filename = "/var/log/freeradius/radutmp" Debug: username = "%{User-Name}" Debug: case_sensitive = yes Debug: check_with_nas = yes Debug: perm = 384 Debug: callerid = yes Debug: } Debug: Module: Checking post-auth {...} for more modules to load Debug: (Loaded rlm_attr_filter, checking if it's valid) Debug: Module: Linked to module rlm_attr_filter Debug: Module: Instantiating attr_filter.access_reject Debug: attr_filter attr_filter.access_reject { Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Debug: key = "%{User-Name}" Debug: } Debug: } Debug: } Debug: server { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_preprocess, checking if it's valid) Debug: Module: Linked to module rlm_preprocess Debug: Module: Instantiating preprocess Debug: preprocess { Debug: huntgroups = "/etc/freeradius/huntgroups" Debug: hints = "/etc/freeradius/hints" Debug: with_ascend_hack = no Debug: ascend_channels_per_line = 23 Debug: with_ntdomain_hack = no Debug: with_specialix_jetstream_hack = no Debug: with_cisco_vsa_hack = no Debug: with_alvarion_vsa_hack = no Debug: } Debug: Module: Checking preacct {...} for more modules to load Debug: (Loaded rlm_acct_unique, checking if it's valid) Debug: Module: Linked to module rlm_acct_unique Debug: Module: Instantiating acct_unique Debug: acct_unique { Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Debug: } Debug: Module: Checking accounting {...} for more modules to load Debug: (Loaded rlm_detail, checking if it's valid) Debug: Module: Linked to module rlm_detail Debug: Module: Instantiating detail Debug: detail { Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Debug: header = "%t" Debug: detailperm = 384 Debug: dirperm = 493 Debug: locking = no Debug: log_packet_header = no Debug: } Debug: Module: Instantiating attr_filter.accounting_response Debug: attr_filter attr_filter.accounting_response { Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Debug: key = "%{User-Name}" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: Module: Checking post-auth {...} for more modules to load Debug: } Debug: } Debug: radiusd: #### Opening IP addresses and Ports #### Debug: listen { Debug: type = "auth" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: listen { Debug: type = "acct" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: main { Debug: snmp = no Debug: smux_password = "" Debug: snmp_write_access = no Debug: } Debug: Listening on authentication address * port 1812 Debug: Listening on accounting address * port 1813 Debug: Listening on proxy address * port 1814 Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 58943, id=90, length=144 Service-Type = Framed-User Framed-Protocol = PPP User-Name = "light" MS-CHAP-Challenge = 0x0478587b0fbb0f95a407ca180b2f8a37 MS-CHAP2-Response = 0xd300647b6787cf9c9d95e042b5ba55d38d180000000000000000261560ec809d3c64cefc0 34d7af5be715a3570723e5dbe2f Calling-Station-Id = "192.168.0.1" NAS-IP-Address = 0x0101 NAS-Port = 0 Debug: +- entering group authorize Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Debug: ++[preprocess] returns ok Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Debug: ++[chap] returns noop Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Debug: rlm_ldap: - authorize Debug: rlm_ldap: performing user authorization for light Debug: WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Debug: expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=light) Debug: expand: ou=vpn,dc=home -> ou=vpn,dc=home Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Debug: rlm_ldap: attempting LDAP reconnection Debug: rlm_ldap: (re)connect to localhost:389, authentication 0 Debug: rlm_ldap: bind as / to localhost:389 Debug: rlm_ldap: waiting for bind result ... Debug: rlm_ldap: Bind was successful Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Debug: rlm_ldap: user light authorized to use remote access Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Debug: ++[ldap] returns ok Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns ok Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Debug: rlm_realm: No '@' in User-Name = "light", looking up realm NULL Debug: rlm_realm: No such realm "NULL" Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Debug: ++[suffix] returns noop Debug: modsingle[authorize]: calling unix (rlm_unix) for request 0 Debug: modsingle[authorize]: returned from unix (rlm_unix) for request 0 Debug: ++[unix] returns notfound Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Debug: ++[files] returns noop Debug: modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Debug: modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Debug: ++[expiration] returns noop Debug: modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Debug: modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Debug: ++[logintime] returns noop Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Debug: ++[pap] returns noop Debug: rad_check_password: Found Auth-Type mschap Debug: auth: type "MSCHAP" Debug: +- entering group MS-CHAP Debug: modsingle[authenticate]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: No Cleartext-Password configured. Cannot create LM-Password. Debug: rlm_mschap: No Cleartext-Password configured. Cannot create NT-Password. Debug: rlm_mschap: Told to do MS-CHAPv2 for light with NT-Password Debug: rlm_mschap: FAILED: No NT/LM-Password. Cannot perform authentication. Debug: rlm_mschap: FAILED: MS-CHAP2-Response is incorrect Debug: modsingle[authenticate]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns reject Debug: auth: Failed to validate the user. Auth: Login incorrect: [light/<via Auth-Type = mschap>] (from client localhost port 0 cli 192.168.0.1) Debug: Found Post-Auth-Type Reject Debug: +- entering group REJECT Debug: modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: expand: %{User-Name} -> light Debug: attr_filter: Matched entry DEFAULT at line 11 Debug: modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: ++[attr_filter.access_reject] returns updated Debug: Delaying reject of request 0 for 1 seconds Debug: Going to the next request Debug: Waking up in 0.9 seconds. Debug: Sending delayed reject for request 0 Sending Access-Reject of id 90 to 127.0.0.1 port 58943 Debug: Waking up in 4.9 seconds. Debug: Cleaning up request 0 ID 90 with timestamp +7 Debug: Ready to process requests.
Just had a look at your ldap antries again. This doesn't look right: userPassword:: dGVzdGVy Shouldn't there be just one colon? Ivan Kalik Kalik Informatika ISP
You can add NT / LM pairs to each LDAP user object. You must include the samba.schema into the ldap server schemas.
Ex:
sambaNTPassword: CAF13D4F321E608B27FD75D2549BA53C sambaLMPassword: 02D093CE93038E2FAAD3B435B51404EE
This way pptp MSCHAP auth will work.
Nelson Vale
On Thursday 08 October 2009 12:53:21 tede wrote:
Ivan Kalik wrote:
Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly?
Hm, try adding mapping for Cleartext-Password as userPassword to ldap.attrmap.
Ivan Kalik Kalik Informatika ISP
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Ivan, first of all, thanks for answering me :)
So, here is the result after adding mapping for Cleartext-Password as userPassword, as we can see in the radius mapping part of the debug :
Info: FreeRADIUS Version 2.0.4, for host i486-pc-linux-gnu, built on Oct 3 2009 at 19:16:29 Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Info: PARTICULAR PURPOSE. Info: You may redistribute copies of FreeRADIUS under the terms of the Info: GNU General Public License. Info: Starting - reading configuration files ... Debug: including configuration file /etc/freeradius/radiusd.conf Debug: including configuration file /etc/freeradius/clients.conf Debug: including configuration file /etc/freeradius/policy.conf Debug: including files in directory /etc/freeradius/sites-enabled/ Debug: including configuration file /etc/freeradius/sites-enabled/default Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Debug: including dictionary file /etc/freeradius/dictionary Debug: main { Debug: prefix = "/usr" Debug: localstatedir = "/var" Debug: logdir = "/var/log/freeradius" Debug: libdir = "/usr/lib/freeradius" Debug: radacctdir = "/var/log/freeradius/radacct" Debug: hostname_lookups = no Debug: max_request_time = 30 Debug: cleanup_delay = 5 Debug: max_requests = 1024 Debug: allow_core_dumps = no Debug: pidfile = "/var/run/freeradius/freeradius.pid" Debug: user = "freerad" Debug: group = "freerad" Debug: checkrad = "/usr/sbin/checkrad" Debug: debug_level = 0 Debug: proxy_requests = yes Debug: security { Debug: max_attributes = 200 Debug: reject_delay = 1 Debug: status_server = yes Debug: } Debug: } Debug: client localhost { Debug: ipaddr = 127.0.0.1 Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: nastype = "other" Debug: } Debug: client 192.168.0.0/24 { Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: shortname = "private-network-1" Debug: } Debug: radiusd: #### Loading Realms and Home Servers #### Debug: radiusd: #### Instantiating modules #### Debug: instantiate { Debug: (Loaded rlm_exec, checking if it's valid) Debug: Module: Linked to module rlm_exec Debug: Module: Instantiating exec Debug: exec { Debug: wait = yes Debug: input_pairs = "request" Debug: shell_escape = yes Debug: } Debug: (Loaded rlm_expr, checking if it's valid) Debug: Module: Linked to module rlm_expr Debug: Module: Instantiating expr Debug: (Loaded rlm_expiration, checking if it's valid) Debug: Module: Linked to module rlm_expiration Debug: Module: Instantiating expiration Debug: expiration { Debug: reply-message = "Password Has Expired " Debug: } Debug: (Loaded rlm_logintime, checking if it's valid) Debug: Module: Linked to module rlm_logintime Debug: Module: Instantiating logintime Debug: logintime { Debug: reply-message = "You are calling outside your allowed timespan " Debug: minimum-timeout = 60 Debug: } Debug: } Debug: radiusd: #### Loading Virtual Servers #### Debug: server inner-tunnel { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: (Loaded rlm_pap, checking if it's valid) Debug: Module: Linked to module rlm_pap Debug: Module: Instantiating pap Debug: pap { Debug: encryption_scheme = "auto" Debug: auto_header = no Debug: } Debug: (Loaded rlm_chap, checking if it's valid) Debug: Module: Linked to module rlm_chap Debug: Module: Instantiating chap Debug: (Loaded rlm_mschap, checking if it's valid) Debug: Module: Linked to module rlm_mschap Debug: Module: Instantiating mschap Debug: mschap { Debug: use_mppe = yes Debug: require_encryption = no Debug: require_strong = no Debug: with_ntdomain_hack = no Debug: } Debug: (Loaded rlm_unix, checking if it's valid) Debug: Module: Linked to module rlm_unix Debug: Module: Instantiating unix Debug: unix { Debug: radwtmp = "/var/log/freeradius/radwtmp" Debug: } Debug: (Loaded rlm_ldap, checking if it's valid) Debug: Module: Linked to module rlm_ldap Debug: Module: Instantiating ldap Debug: ldap { Debug: server = "localhost" Debug: port = 389 Debug: password = "" Debug: identity = "" Debug: net_timeout = 1 Debug: timeout = 4 Debug: timelimit = 3 Debug: tls_mode = no Debug: start_tls = no Debug: tls_require_cert = "allow" Debug: tls { Debug: start_tls = no Debug: require_cert = "allow" Debug: } Debug: basedn = "ou=vpn,dc=home" Debug: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Debug: base_filter = "(objectclass=radiusprofile)" Debug: password_attribute = "userPassword" Debug: auto_header = yes Debug: access_attr_used_for_allow = yes Debug: groupname_attribute = "cn" Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=Group OfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Debug: dictionary_mapping = "/etc/freeradius/ldap.attrmap" Debug: ldap_debug = 0 Debug: ldap_connections_number = 5 Debug: compare_check_items = no Debug: do_xlat = yes Debug: edir_account_policy_check = no Debug: set_auth_type = no Debug: } Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Debug: rlm_ldap: reading ldap<->radius mappings from file /etc/freeradius/ldap.attrmap Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP digestHA1 mapped to RADIUS Digest-HA1 Debug: rlm_ldap: LDAP userPassword mapped to RADIUS Cleartext-Password Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Debug: rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP ntHash mapped to RADIUS NT-Hash Debug: rlm_ldap: LDAP lmHash mapped to RADIUS LM-Hash Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Debug: conns: 0x85c8988 Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_realm, checking if it's valid) Debug: Module: Linked to module rlm_realm Debug: Module: Instantiating suffix Debug: realm suffix { Debug: format = "suffix" Debug: delimiter = "@" Debug: ignore_default = no Debug: ignore_null = no Debug: } Debug: (Loaded rlm_files, checking if it's valid) Debug: Module: Linked to module rlm_files Debug: Module: Instantiating files Debug: files { Debug: usersfile = "/etc/freeradius/users" Debug: acctusersfile = "/etc/freeradius/acct_users" Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Debug: compat = "no" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: (Loaded rlm_radutmp, checking if it's valid) Debug: Module: Linked to module rlm_radutmp Debug: Module: Instantiating radutmp Debug: radutmp { Debug: filename = "/var/log/freeradius/radutmp" Debug: username = "%{User-Name}" Debug: case_sensitive = yes Debug: check_with_nas = yes Debug: perm = 384 Debug: callerid = yes Debug: } Debug: Module: Checking post-auth {...} for more modules to load Debug: (Loaded rlm_attr_filter, checking if it's valid) Debug: Module: Linked to module rlm_attr_filter Debug: Module: Instantiating attr_filter.access_reject Debug: attr_filter attr_filter.access_reject { Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Debug: key = "%{User-Name}" Debug: } Debug: } Debug: } Debug: server { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_preprocess, checking if it's valid) Debug: Module: Linked to module rlm_preprocess Debug: Module: Instantiating preprocess Debug: preprocess { Debug: huntgroups = "/etc/freeradius/huntgroups" Debug: hints = "/etc/freeradius/hints" Debug: with_ascend_hack = no Debug: ascend_channels_per_line = 23 Debug: with_ntdomain_hack = no Debug: with_specialix_jetstream_hack = no Debug: with_cisco_vsa_hack = no Debug: with_alvarion_vsa_hack = no Debug: } Debug: Module: Checking preacct {...} for more modules to load Debug: (Loaded rlm_acct_unique, checking if it's valid) Debug: Module: Linked to module rlm_acct_unique Debug: Module: Instantiating acct_unique Debug: acct_unique { Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Debug: } Debug: Module: Checking accounting {...} for more modules to load Debug: (Loaded rlm_detail, checking if it's valid) Debug: Module: Linked to module rlm_detail Debug: Module: Instantiating detail Debug: detail { Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Debug: header = "%t" Debug: detailperm = 384 Debug: dirperm = 493 Debug: locking = no Debug: log_packet_header = no Debug: } Debug: Module: Instantiating attr_filter.accounting_response Debug: attr_filter attr_filter.accounting_response { Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Debug: key = "%{User-Name}" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: Module: Checking post-auth {...} for more modules to load Debug: } Debug: } Debug: radiusd: #### Opening IP addresses and Ports #### Debug: listen { Debug: type = "auth" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: listen { Debug: type = "acct" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: main { Debug: snmp = no Debug: smux_password = "" Debug: snmp_write_access = no Debug: } Debug: Listening on authentication address * port 1812 Debug: Listening on accounting address * port 1813 Debug: Listening on proxy address * port 1814 Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 58943, id=90, length=144 Service-Type = Framed-User Framed-Protocol = PPP User-Name = "light" MS-CHAP-Challenge = 0x0478587b0fbb0f95a407ca180b2f8a37 MS-CHAP2-Response = 0xd300647b6787cf9c9d95e042b5ba55d38d180000000000000000261560ec809d3c64cefc0 34d7af5be715a3570723e5dbe2f Calling-Station-Id = "192.168.0.1" NAS-IP-Address = 0x0101 NAS-Port = 0 Debug: +- entering group authorize Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Debug: ++[preprocess] returns ok Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Debug: ++[chap] returns noop Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Debug: rlm_ldap: - authorize Debug: rlm_ldap: performing user authorization for light Debug: WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Debug: expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=light) Debug: expand: ou=vpn,dc=home -> ou=vpn,dc=home Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Debug: rlm_ldap: attempting LDAP reconnection Debug: rlm_ldap: (re)connect to localhost:389, authentication 0 Debug: rlm_ldap: bind as / to localhost:389 Debug: rlm_ldap: waiting for bind result ... Debug: rlm_ldap: Bind was successful Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Debug: rlm_ldap: user light authorized to use remote access Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Debug: ++[ldap] returns ok Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns ok Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Debug: rlm_realm: No '@' in User-Name = "light", looking up realm NULL Debug: rlm_realm: No such realm "NULL" Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Debug: ++[suffix] returns noop Debug: modsingle[authorize]: calling unix (rlm_unix) for request 0 Debug: modsingle[authorize]: returned from unix (rlm_unix) for request 0 Debug: ++[unix] returns notfound Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Debug: ++[files] returns noop Debug: modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Debug: modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Debug: ++[expiration] returns noop Debug: modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Debug: modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Debug: ++[logintime] returns noop Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Debug: ++[pap] returns noop Debug: rad_check_password: Found Auth-Type mschap Debug: auth: type "MSCHAP" Debug: +- entering group MS-CHAP Debug: modsingle[authenticate]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: No Cleartext-Password configured. Cannot create LM-Password. Debug: rlm_mschap: No Cleartext-Password configured. Cannot create NT-Password. Debug: rlm_mschap: Told to do MS-CHAPv2 for light with NT-Password Debug: rlm_mschap: FAILED: No NT/LM-Password. Cannot perform authentication. Debug: rlm_mschap: FAILED: MS-CHAP2-Response is incorrect Debug: modsingle[authenticate]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns reject Debug: auth: Failed to validate the user. Auth: Login incorrect: [light/<via Auth-Type = mschap>] (from client localhost port 0 cli 192.168.0.1) Debug: Found Post-Auth-Type Reject Debug: +- entering group REJECT Debug: modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: expand: %{User-Name} -> light Debug: attr_filter: Matched entry DEFAULT at line 11 Debug: modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: ++[attr_filter.access_reject] returns updated Debug: Delaying reject of request 0 for 1 seconds Debug: Going to the next request Debug: Waking up in 0.9 seconds. Debug: Sending delayed reject for request 0 Sending Access-Reject of id 90 to 127.0.0.1 port 58943 Debug: Waking up in 4.9 seconds. Debug: Cleaning up request 0 ID 90 with timestamp +7 Debug: Ready to process requests.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hello, anyone have to suggest a free EAP-GTC supplicant for Windows XP? -------------------------------------- Vincenzo Agosti Università degli Studi di Salerno Ufficio Sistemi Tecnologici Coordinamento Servizi Informatici Via Ponte don Melillo, s.n.c. 84084 - Fisciano (SA) Tel. +39 089 96 6101 - 9776 Fax +39 089 96 6368 - 9806 Cell. +39 335 427674 --------------------------------------
2009/10/8 Vincenzo Agosti <vagosti@unisa.it>:
Hello, anyone have to suggest a free EAP-GTC supplicant for Windows XP?
These are what I tested (with freeradius + LDAP + PEAP + GTC) and works on my setup: - http://www.securew2.com/ (a little confusinng to setup for me, but it works) - http://hostap.epitest.fi/wpa_supplicant/ (it has windows port as well) - http://www.juniper.net/customers/support/products/oac.jsp (not free, but IMHO has the best GUI) -- Fajar
On Thursday 08 October 2009 15:05:24 Ivan Kalik wrote:
Just had a look at your ldap antries again. This doesn't look right:
userPassword:: dGVzdGVy
Shouldn't there be just one colon?
Two colons means that it's a BASE64 encoded field.
Ivan Kalik Kalik Informatika ISP
You can add NT / LM pairs to each LDAP user object. You must include the samba.schema into the ldap server schemas.
Ex:
sambaNTPassword: CAF13D4F321E608B27FD75D2549BA53C sambaLMPassword: 02D093CE93038E2FAAD3B435B51404EE
This way pptp MSCHAP auth will work.
Nelson Vale
On Thursday 08 October 2009 12:53:21 tede wrote:
Ivan Kalik wrote:
Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly?
Hm, try adding mapping for Cleartext-Password as userPassword to ldap.attrmap.
Ivan Kalik Kalik Informatika ISP
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Ivan, first of all, thanks for answering me :)
So, here is the result after adding mapping for Cleartext-Password as userPassword, as we can see in the radius mapping part of the debug :
Info: FreeRADIUS Version 2.0.4, for host i486-pc-linux-gnu, built on Oct 3 2009 at 19:16:29 Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Info: PARTICULAR PURPOSE. Info: You may redistribute copies of FreeRADIUS under the terms of the Info: GNU General Public License. Info: Starting - reading configuration files ... Debug: including configuration file /etc/freeradius/radiusd.conf Debug: including configuration file /etc/freeradius/clients.conf Debug: including configuration file /etc/freeradius/policy.conf Debug: including files in directory /etc/freeradius/sites-enabled/ Debug: including configuration file /etc/freeradius/sites-enabled/default Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Debug: including dictionary file /etc/freeradius/dictionary Debug: main { Debug: prefix = "/usr" Debug: localstatedir = "/var" Debug: logdir = "/var/log/freeradius" Debug: libdir = "/usr/lib/freeradius" Debug: radacctdir = "/var/log/freeradius/radacct" Debug: hostname_lookups = no Debug: max_request_time = 30 Debug: cleanup_delay = 5 Debug: max_requests = 1024 Debug: allow_core_dumps = no Debug: pidfile = "/var/run/freeradius/freeradius.pid" Debug: user = "freerad" Debug: group = "freerad" Debug: checkrad = "/usr/sbin/checkrad" Debug: debug_level = 0 Debug: proxy_requests = yes Debug: security { Debug: max_attributes = 200 Debug: reject_delay = 1 Debug: status_server = yes Debug: } Debug: } Debug: client localhost { Debug: ipaddr = 127.0.0.1 Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: nastype = "other" Debug: } Debug: client 192.168.0.0/24 { Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: shortname = "private-network-1" Debug: } Debug: radiusd: #### Loading Realms and Home Servers #### Debug: radiusd: #### Instantiating modules #### Debug: instantiate { Debug: (Loaded rlm_exec, checking if it's valid) Debug: Module: Linked to module rlm_exec Debug: Module: Instantiating exec Debug: exec { Debug: wait = yes Debug: input_pairs = "request" Debug: shell_escape = yes Debug: } Debug: (Loaded rlm_expr, checking if it's valid) Debug: Module: Linked to module rlm_expr Debug: Module: Instantiating expr Debug: (Loaded rlm_expiration, checking if it's valid) Debug: Module: Linked to module rlm_expiration Debug: Module: Instantiating expiration Debug: expiration { Debug: reply-message = "Password Has Expired " Debug: } Debug: (Loaded rlm_logintime, checking if it's valid) Debug: Module: Linked to module rlm_logintime Debug: Module: Instantiating logintime Debug: logintime { Debug: reply-message = "You are calling outside your allowed timespan " Debug: minimum-timeout = 60 Debug: } Debug: } Debug: radiusd: #### Loading Virtual Servers #### Debug: server inner-tunnel { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: (Loaded rlm_pap, checking if it's valid) Debug: Module: Linked to module rlm_pap Debug: Module: Instantiating pap Debug: pap { Debug: encryption_scheme = "auto" Debug: auto_header = no Debug: } Debug: (Loaded rlm_chap, checking if it's valid) Debug: Module: Linked to module rlm_chap Debug: Module: Instantiating chap Debug: (Loaded rlm_mschap, checking if it's valid) Debug: Module: Linked to module rlm_mschap Debug: Module: Instantiating mschap Debug: mschap { Debug: use_mppe = yes Debug: require_encryption = no Debug: require_strong = no Debug: with_ntdomain_hack = no Debug: } Debug: (Loaded rlm_unix, checking if it's valid) Debug: Module: Linked to module rlm_unix Debug: Module: Instantiating unix Debug: unix { Debug: radwtmp = "/var/log/freeradius/radwtmp" Debug: } Debug: (Loaded rlm_ldap, checking if it's valid) Debug: Module: Linked to module rlm_ldap Debug: Module: Instantiating ldap Debug: ldap { Debug: server = "localhost" Debug: port = 389 Debug: password = "" Debug: identity = "" Debug: net_timeout = 1 Debug: timeout = 4 Debug: timelimit = 3 Debug: tls_mode = no Debug: start_tls = no Debug: tls_require_cert = "allow" Debug: tls { Debug: start_tls = no Debug: require_cert = "allow" Debug: } Debug: basedn = "ou=vpn,dc=home" Debug: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Debug: base_filter = "(objectclass=radiusprofile)" Debug: password_attribute = "userPassword" Debug: auto_header = yes Debug: access_attr_used_for_allow = yes Debug: groupname_attribute = "cn" Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=Gr oup OfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Debug: dictionary_mapping = "/etc/freeradius/ldap.attrmap" Debug: ldap_debug = 0 Debug: ldap_connections_number = 5 Debug: compare_check_items = no Debug: do_xlat = yes Debug: edir_account_policy_check = no Debug: set_auth_type = no Debug: } Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Debug: rlm_ldap: reading ldap<->radius mappings from file /etc/freeradius/ldap.attrmap Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP digestHA1 mapped to RADIUS Digest-HA1 Debug: rlm_ldap: LDAP userPassword mapped to RADIUS Cleartext-Password Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Debug: rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP ntHash mapped to RADIUS NT-Hash Debug: rlm_ldap: LDAP lmHash mapped to RADIUS LM-Hash Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Debug: conns: 0x85c8988 Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_realm, checking if it's valid) Debug: Module: Linked to module rlm_realm Debug: Module: Instantiating suffix Debug: realm suffix { Debug: format = "suffix" Debug: delimiter = "@" Debug: ignore_default = no Debug: ignore_null = no Debug: } Debug: (Loaded rlm_files, checking if it's valid) Debug: Module: Linked to module rlm_files Debug: Module: Instantiating files Debug: files { Debug: usersfile = "/etc/freeradius/users" Debug: acctusersfile = "/etc/freeradius/acct_users" Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Debug: compat = "no" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: (Loaded rlm_radutmp, checking if it's valid) Debug: Module: Linked to module rlm_radutmp Debug: Module: Instantiating radutmp Debug: radutmp { Debug: filename = "/var/log/freeradius/radutmp" Debug: username = "%{User-Name}" Debug: case_sensitive = yes Debug: check_with_nas = yes Debug: perm = 384 Debug: callerid = yes Debug: } Debug: Module: Checking post-auth {...} for more modules to load Debug: (Loaded rlm_attr_filter, checking if it's valid) Debug: Module: Linked to module rlm_attr_filter Debug: Module: Instantiating attr_filter.access_reject Debug: attr_filter attr_filter.access_reject { Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Debug: key = "%{User-Name}" Debug: } Debug: } Debug: } Debug: server { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_preprocess, checking if it's valid) Debug: Module: Linked to module rlm_preprocess Debug: Module: Instantiating preprocess Debug: preprocess { Debug: huntgroups = "/etc/freeradius/huntgroups" Debug: hints = "/etc/freeradius/hints" Debug: with_ascend_hack = no Debug: ascend_channels_per_line = 23 Debug: with_ntdomain_hack = no Debug: with_specialix_jetstream_hack = no Debug: with_cisco_vsa_hack = no Debug: with_alvarion_vsa_hack = no Debug: } Debug: Module: Checking preacct {...} for more modules to load Debug: (Loaded rlm_acct_unique, checking if it's valid) Debug: Module: Linked to module rlm_acct_unique Debug: Module: Instantiating acct_unique Debug: acct_unique { Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Debug: } Debug: Module: Checking accounting {...} for more modules to load Debug: (Loaded rlm_detail, checking if it's valid) Debug: Module: Linked to module rlm_detail Debug: Module: Instantiating detail Debug: detail { Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Debug: header = "%t" Debug: detailperm = 384 Debug: dirperm = 493 Debug: locking = no Debug: log_packet_header = no Debug: } Debug: Module: Instantiating attr_filter.accounting_response Debug: attr_filter attr_filter.accounting_response { Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Debug: key = "%{User-Name}" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: Module: Checking post-auth {...} for more modules to load Debug: } Debug: } Debug: radiusd: #### Opening IP addresses and Ports #### Debug: listen { Debug: type = "auth" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: listen { Debug: type = "acct" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: main { Debug: snmp = no Debug: smux_password = "" Debug: snmp_write_access = no Debug: } Debug: Listening on authentication address * port 1812 Debug: Listening on accounting address * port 1813 Debug: Listening on proxy address * port 1814 Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 58943, id=90, length=144 Service-Type = Framed-User Framed-Protocol = PPP User-Name = "light" MS-CHAP-Challenge = 0x0478587b0fbb0f95a407ca180b2f8a37 MS-CHAP2-Response = 0xd300647b6787cf9c9d95e042b5ba55d38d180000000000000000261560ec809d3c64ce fc0 34d7af5be715a3570723e5dbe2f Calling-Station-Id = "192.168.0.1" NAS-IP-Address = 0x0101 NAS-Port = 0 Debug: +- entering group authorize Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Debug: ++[preprocess] returns ok Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Debug: ++[chap] returns noop Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Debug: rlm_ldap: - authorize Debug: rlm_ldap: performing user authorization for light Debug: WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Debug: expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=light) Debug: expand: ou=vpn,dc=home -> ou=vpn,dc=home Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Debug: rlm_ldap: attempting LDAP reconnection Debug: rlm_ldap: (re)connect to localhost:389, authentication 0 Debug: rlm_ldap: bind as / to localhost:389 Debug: rlm_ldap: waiting for bind result ... Debug: rlm_ldap: Bind was successful Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Debug: rlm_ldap: user light authorized to use remote access Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Debug: ++[ldap] returns ok Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns ok Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Debug: rlm_realm: No '@' in User-Name = "light", looking up realm NULL Debug: rlm_realm: No such realm "NULL" Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Debug: ++[suffix] returns noop Debug: modsingle[authorize]: calling unix (rlm_unix) for request 0 Debug: modsingle[authorize]: returned from unix (rlm_unix) for request 0 Debug: ++[unix] returns notfound Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Debug: ++[files] returns noop Debug: modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Debug: modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Debug: ++[expiration] returns noop Debug: modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Debug: modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Debug: ++[logintime] returns noop Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0 Debug: ++[pap] returns noop Debug: rad_check_password: Found Auth-Type mschap Debug: auth: type "MSCHAP" Debug: +- entering group MS-CHAP Debug: modsingle[authenticate]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: No Cleartext-Password configured. Cannot create LM-Password. Debug: rlm_mschap: No Cleartext-Password configured. Cannot create NT-Password. Debug: rlm_mschap: Told to do MS-CHAPv2 for light with NT-Password Debug: rlm_mschap: FAILED: No NT/LM-Password. Cannot perform authentication. Debug: rlm_mschap: FAILED: MS-CHAP2-Response is incorrect Debug: modsingle[authenticate]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns reject Debug: auth: Failed to validate the user. Auth: Login incorrect: [light/<via Auth-Type = mschap>] (from client localhost port 0 cli 192.168.0.1) Debug: Found Post-Auth-Type Reject Debug: +- entering group REJECT Debug: modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: expand: %{User-Name} -> light Debug: attr_filter: Matched entry DEFAULT at line 11 Debug: modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: ++[attr_filter.access_reject] returns updated Debug: Delaying reject of request 0 for 1 seconds Debug: Going to the next request Debug: Waking up in 0.9 seconds. Debug: Sending delayed reject for request 0 Sending Access-Reject of id 90 to 127.0.0.1 port 58943 Debug: Waking up in 4.9 seconds. Debug: Cleaning up request 0 ID 90 with timestamp +7 Debug: Ready to process requests.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Nelson , Thank you to you all, for your help. I've lost so much time trying to find a solution for this. Just by adding NT/LM pairs to each LDAP users object, everything works fine now :) How come couldn't I get this tip before ? That would have saved me a lot of time. Anyway, now everything is ok, I can move on. Thanks so so much :) :) Tede. nf-vale a écrit :
On Thursday 08 October 2009 15:05:24 Ivan Kalik wrote:
Just had a look at your ldap antries again. This doesn't look right:
userPassword:: dGVzdGVy
Shouldn't there be just one colon?
Two colons means that it's a BASE64 encoded field.
Ivan Kalik Kalik Informatika ISP
You can add NT / LM pairs to each LDAP user object. You must include the samba.schema into the ldap server schemas.
Ex:
sambaNTPassword: CAF13D4F321E608B27FD75D2549BA53C sambaLMPassword: 02D093CE93038E2FAAD3B435B51404EE
This way pptp MSCHAP auth will work.
Nelson Vale
On Thursday 08 October 2009 12:53:21 tede wrote:
Ivan Kalik wrote:
Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly?
Hm, try adding mapping for Cleartext-Password as userPassword to ldap.attrmap.
Ivan Kalik Kalik Informatika ISP
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Ivan, first of all, thanks for answering me :)
So, here is the result after adding mapping for Cleartext-Password as userPassword, as we can see in the radius mapping part of the debug :
Info: FreeRADIUS Version 2.0.4, for host i486-pc-linux-gnu, built on Oct 3 2009 at 19:16:29 Info: Copyright (C) 1999-2008 The FreeRADIUS server project and contributors. Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Info: PARTICULAR PURPOSE. Info: You may redistribute copies of FreeRADIUS under the terms of the Info: GNU General Public License. Info: Starting - reading configuration files ... Debug: including configuration file /etc/freeradius/radiusd.conf Debug: including configuration file /etc/freeradius/clients.conf Debug: including configuration file /etc/freeradius/policy.conf Debug: including files in directory /etc/freeradius/sites-enabled/ Debug: including configuration file /etc/freeradius/sites-enabled/default Debug: including configuration file /etc/freeradius/sites-enabled/inner-tunnel Debug: including dictionary file /etc/freeradius/dictionary Debug: main { Debug: prefix = "/usr" Debug: localstatedir = "/var" Debug: logdir = "/var/log/freeradius" Debug: libdir = "/usr/lib/freeradius" Debug: radacctdir = "/var/log/freeradius/radacct" Debug: hostname_lookups = no Debug: max_request_time = 30 Debug: cleanup_delay = 5 Debug: max_requests = 1024 Debug: allow_core_dumps = no Debug: pidfile = "/var/run/freeradius/freeradius.pid" Debug: user = "freerad" Debug: group = "freerad" Debug: checkrad = "/usr/sbin/checkrad" Debug: debug_level = 0 Debug: proxy_requests = yes Debug: security { Debug: max_attributes = 200 Debug: reject_delay = 1 Debug: status_server = yes Debug: } Debug: } Debug: client localhost { Debug: ipaddr = 127.0.0.1 Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: nastype = "other" Debug: } Debug: client 192.168.0.0/24 { Debug: require_message_authenticator = no Debug: secret = "hometest" Debug: shortname = "private-network-1" Debug: } Debug: radiusd: #### Loading Realms and Home Servers #### Debug: radiusd: #### Instantiating modules #### Debug: instantiate { Debug: (Loaded rlm_exec, checking if it's valid) Debug: Module: Linked to module rlm_exec Debug: Module: Instantiating exec Debug: exec { Debug: wait = yes Debug: input_pairs = "request" Debug: shell_escape = yes Debug: } Debug: (Loaded rlm_expr, checking if it's valid) Debug: Module: Linked to module rlm_expr Debug: Module: Instantiating expr Debug: (Loaded rlm_expiration, checking if it's valid) Debug: Module: Linked to module rlm_expiration Debug: Module: Instantiating expiration Debug: expiration { Debug: reply-message = "Password Has Expired " Debug: } Debug: (Loaded rlm_logintime, checking if it's valid) Debug: Module: Linked to module rlm_logintime Debug: Module: Instantiating logintime Debug: logintime { Debug: reply-message = "You are calling outside your allowed timespan " Debug: minimum-timeout = 60 Debug: } Debug: } Debug: radiusd: #### Loading Virtual Servers #### Debug: server inner-tunnel { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: (Loaded rlm_pap, checking if it's valid) Debug: Module: Linked to module rlm_pap Debug: Module: Instantiating pap Debug: pap { Debug: encryption_scheme = "auto" Debug: auto_header = no Debug: } Debug: (Loaded rlm_chap, checking if it's valid) Debug: Module: Linked to module rlm_chap Debug: Module: Instantiating chap Debug: (Loaded rlm_mschap, checking if it's valid) Debug: Module: Linked to module rlm_mschap Debug: Module: Instantiating mschap Debug: mschap { Debug: use_mppe = yes Debug: require_encryption = no Debug: require_strong = no Debug: with_ntdomain_hack = no Debug: } Debug: (Loaded rlm_unix, checking if it's valid) Debug: Module: Linked to module rlm_unix Debug: Module: Instantiating unix Debug: unix { Debug: radwtmp = "/var/log/freeradius/radwtmp" Debug: } Debug: (Loaded rlm_ldap, checking if it's valid) Debug: Module: Linked to module rlm_ldap Debug: Module: Instantiating ldap Debug: ldap { Debug: server = "localhost" Debug: port = 389 Debug: password = "" Debug: identity = "" Debug: net_timeout = 1 Debug: timeout = 4 Debug: timelimit = 3 Debug: tls_mode = no Debug: start_tls = no Debug: tls_require_cert = "allow" Debug: tls { Debug: start_tls = no Debug: require_cert = "allow" Debug: } Debug: basedn = "ou=vpn,dc=home" Debug: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Debug: base_filter = "(objectclass=radiusprofile)" Debug: password_attribute = "userPassword" Debug: auto_header = yes Debug: access_attr_used_for_allow = yes Debug: groupname_attribute = "cn" Debug: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=Gr oup OfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Debug: dictionary_mapping = "/etc/freeradius/ldap.attrmap" Debug: ldap_debug = 0 Debug: ldap_connections_number = 5 Debug: compare_check_items = no Debug: do_xlat = yes Debug: edir_account_policy_check = no Debug: set_auth_type = no Debug: } Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Debug: rlm_ldap: reading ldap<->radius mappings from file /etc/freeradius/ldap.attrmap Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Debug: rlm_ldap: LDAP digestHA1 mapped to RADIUS Digest-HA1 Debug: rlm_ldap: LDAP userPassword mapped to RADIUS Cleartext-Password Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Debug: rlm_ldap: LDAP sambaLmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP sambaNtPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Debug: rlm_ldap: LDAP ntHash mapped to RADIUS NT-Hash Debug: rlm_ldap: LDAP lmHash mapped to RADIUS LM-Hash Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Debug: conns: 0x85c8988 Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_realm, checking if it's valid) Debug: Module: Linked to module rlm_realm Debug: Module: Instantiating suffix Debug: realm suffix { Debug: format = "suffix" Debug: delimiter = "@" Debug: ignore_default = no Debug: ignore_null = no Debug: } Debug: (Loaded rlm_files, checking if it's valid) Debug: Module: Linked to module rlm_files Debug: Module: Instantiating files Debug: files { Debug: usersfile = "/etc/freeradius/users" Debug: acctusersfile = "/etc/freeradius/acct_users" Debug: preproxy_usersfile = "/etc/freeradius/preproxy_users" Debug: compat = "no" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: (Loaded rlm_radutmp, checking if it's valid) Debug: Module: Linked to module rlm_radutmp Debug: Module: Instantiating radutmp Debug: radutmp { Debug: filename = "/var/log/freeradius/radutmp" Debug: username = "%{User-Name}" Debug: case_sensitive = yes Debug: check_with_nas = yes Debug: perm = 384 Debug: callerid = yes Debug: } Debug: Module: Checking post-auth {...} for more modules to load Debug: (Loaded rlm_attr_filter, checking if it's valid) Debug: Module: Linked to module rlm_attr_filter Debug: Module: Instantiating attr_filter.access_reject Debug: attr_filter attr_filter.access_reject { Debug: attrsfile = "/etc/freeradius/attrs.access_reject" Debug: key = "%{User-Name}" Debug: } Debug: } Debug: } Debug: server { Debug: modules { Debug: Module: Checking authenticate {...} for more modules to load Debug: Module: Checking authorize {...} for more modules to load Debug: (Loaded rlm_preprocess, checking if it's valid) Debug: Module: Linked to module rlm_preprocess Debug: Module: Instantiating preprocess Debug: preprocess { Debug: huntgroups = "/etc/freeradius/huntgroups" Debug: hints = "/etc/freeradius/hints" Debug: with_ascend_hack = no Debug: ascend_channels_per_line = 23 Debug: with_ntdomain_hack = no Debug: with_specialix_jetstream_hack = no Debug: with_cisco_vsa_hack = no Debug: with_alvarion_vsa_hack = no Debug: } Debug: Module: Checking preacct {...} for more modules to load Debug: (Loaded rlm_acct_unique, checking if it's valid) Debug: Module: Linked to module rlm_acct_unique Debug: Module: Instantiating acct_unique Debug: acct_unique { Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Debug: } Debug: Module: Checking accounting {...} for more modules to load Debug: (Loaded rlm_detail, checking if it's valid) Debug: Module: Linked to module rlm_detail Debug: Module: Instantiating detail Debug: detail { Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Debug: header = "%t" Debug: detailperm = 384 Debug: dirperm = 493 Debug: locking = no Debug: log_packet_header = no Debug: } Debug: Module: Instantiating attr_filter.accounting_response Debug: attr_filter attr_filter.accounting_response { Debug: attrsfile = "/etc/freeradius/attrs.accounting_response" Debug: key = "%{User-Name}" Debug: } Debug: Module: Checking session {...} for more modules to load Debug: Module: Checking post-auth {...} for more modules to load Debug: } Debug: } Debug: radiusd: #### Opening IP addresses and Ports #### Debug: listen { Debug: type = "auth" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: listen { Debug: type = "acct" Debug: ipaddr = * Debug: port = 0 Debug: } Debug: main { Debug: snmp = no Debug: smux_password = "" Debug: snmp_write_access = no Debug: } Debug: Listening on authentication address * port 1812 Debug: Listening on accounting address * port 1813 Debug: Listening on proxy address * port 1814 Debug: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1 port 58943, id=90, length=144 Service-Type = Framed-User Framed-Protocol = PPP User-Name = "light" MS-CHAP-Challenge = 0x0478587b0fbb0f95a407ca180b2f8a37 MS-CHAP2-Response = 0xd300647b6787cf9c9d95e042b5ba55d38d180000000000000000261560ec809d3c64ce fc0 34d7af5be715a3570723e5dbe2f Calling-Station-Id = "192.168.0.1" NAS-IP-Address = 0x0101 NAS-Port = 0 Debug: +- entering group authorize Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Debug: ++[preprocess] returns ok Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Debug: ++[chap] returns noop Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Debug: rlm_ldap: - authorize Debug: rlm_ldap: performing user authorization for light Debug: WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Debug: expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=light) Debug: expand: ou=vpn,dc=home -> ou=vpn,dc=home Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Debug: rlm_ldap: attempting LDAP reconnection Debug: rlm_ldap: (re)connect to localhost:389, authentication 0 Debug: rlm_ldap: bind as / to localhost:389 Debug: rlm_ldap: waiting for bind result ... Debug: rlm_ldap: Bind was successful Debug: rlm_ldap: performing search in ou=vpn,dc=home, with filter (uid=light) Debug: rlm_ldap: No default NMAS login sequence Debug: rlm_ldap: looking for check items in directory... Debug: rlm_ldap: looking for reply items in directory... Debug: WARNING: No "known good" password was found in LDAP. Are you sure that the user is configured correctly? Debug: rlm_ldap: user light authorized to use remote access Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Debug: ++[ldap] returns ok Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns ok Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Debug: rlm_realm: No '@' in User-Name = "light", looking up realm NULL Debug: rlm_realm: No such realm "NULL" Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Debug: ++[suffix] returns noop Debug: modsingle[authorize]: calling unix (rlm_unix) for request 0 Debug: modsingle[authorize]: returned from unix (rlm_unix) for request 0 Debug: ++[unix] returns notfound Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Debug: ++[files] returns noop Debug: modsingle[authorize]: calling expiration (rlm_expiration) for request 0 Debug: modsingle[authorize]: returned from expiration (rlm_expiration) for request 0 Debug: ++[expiration] returns noop Debug: modsingle[authorize]: calling logintime (rlm_logintime) for request 0 Debug: modsingle[authorize]: returned from logintime (rlm_logintime) for request 0 Debug: ++[logintime] returns noop Debug: modsingle[authorize]: calling pap (rlm_pap) for request 0 Debug: rlm_pap: WARNING! No "known good" password found for the user. Authentication may fail because of this. Debug: modsingle[authorize]: returned from pap (rlm_pap) for request 0
Debug: ++[pap] returns noop Debug: rad_check_password: Found Auth-Type mschap Debug: auth: type "MSCHAP" Debug: +- entering group MS-CHAP Debug: modsingle[authenticate]: calling mschap (rlm_mschap) for request 0 Debug: rlm_mschap: No Cleartext-Password configured. Cannot create LM-Password. Debug: rlm_mschap: No Cleartext-Password configured. Cannot create NT-Password. Debug: rlm_mschap: Told to do MS-CHAPv2 for light with NT-Password Debug: rlm_mschap: FAILED: No NT/LM-Password. Cannot perform authentication. Debug: rlm_mschap: FAILED: MS-CHAP2-Response is incorrect Debug: modsingle[authenticate]: returned from mschap (rlm_mschap) for request 0 Debug: ++[mschap] returns reject Debug: auth: Failed to validate the user. Auth: Login incorrect: [light/<via Auth-Type = mschap>] (from client localhost port 0 cli 192.168.0.1) Debug: Found Post-Auth-Type Reject Debug: +- entering group REJECT Debug: modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: expand: %{User-Name} -> light Debug: attr_filter: Matched entry DEFAULT at line 11 Debug: modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 0 Debug: ++[attr_filter.access_reject] returns updated Debug: Delaying reject of request 0 for 1 seconds Debug: Going to the next request Debug: Waking up in 0.9 seconds. Debug: Sending delayed reject for request 0 Sending Access-Reject of id 90 to 127.0.0.1 port 58943 Debug: Waking up in 4.9 seconds. Debug: Cleaning up request 0 ID 90 with timestamp +7 Debug: Ready to process requests.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
I am runnning 2.1.6 on Redhat Linux (Red Hat Enterprise Linux Server release 5.3 (Tikanga)). This server relays all records to an identical server radius-b and radius-c Similarly radius-b relays its records back to radius-a (except those from radius-a) radius-c is just for testing. All relaying appears to be working correctly. These server currently receiving accounting records only. radius-a seems to be getting the bulk of the radius records. Normally, it has a single process. Last night it spawned a bunch of children that seem to be loitering... radius-b and radius-c don't have more than a single radiusd process. Any idea what is going on? Why all the children? Do I need to be concerned? Is this normal?
From the detail log, is seems that the message rate increase to about 2000-2400/minute at that time for about 3 minutes, then dropped to <1000/min. [root@radius-a radius]# ps -aef | grep radiusd radiusd 5426 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 5738 21400 0 03:29 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8239 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8240 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8241 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8242 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8243 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8244 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 9029 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 9104 21400 0 03:29 ? 00:00:00 /usr/local/sbin/radiusd radiusd 14154 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 14426 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 15039 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 15040 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 16082 21400 0 03:36 ? 00:00:00 /usr/local/sbin/radiusd radiusd 17295 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd root 19242 20229 0 11:42 pts/0 00:00:00 grep radiusd radiusd 19974 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20670 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20673 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20674 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20675 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20679 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20680 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21207 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21208 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21209 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21300 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21301 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21400 1 0 Oct07 ? 00:02:40 /usr/local/sbin/radiusd radiusd 26543 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 26683 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 28411 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 29065 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 30648 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 30649 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 30893 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd
Thanks, -craig __________ Information from ESET Smart Security, version of virus signature database 4490 (20091008) __________ The message was checked by ESET Smart Security. http://www.eset.com
Update: strace suggests all the child processes are doing the same thing, [root@radius-a raddb]# strace -p 30893 Process 30893 attached - interrupt to quit futex(0x3acf752554, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> Hope this helps, -craig ----- Original Message ----- From: Craig Campbell To: FreeRadius users mailing list Sent: Thursday, October 08, 2009 12:07 PM Subject: over 30 radiusd processes I am runnning 2.1.6 on Redhat Linux (Red Hat Enterprise Linux Server release 5.3 (Tikanga)). This server relays all records to an identical server radius-b and radius-c Similarly radius-b relays its records back to radius-a (except those from radius-a) radius-c is just for testing. All relaying appears to be working correctly. These server currently receiving accounting records only. radius-a seems to be getting the bulk of the radius records. Normally, it has a single process. Last night it spawned a bunch of children that seem to be loitering... radius-b and radius-c don't have more than a single radiusd process. Any idea what is going on? Why all the children? Do I need to be concerned? Is this normal? From the detail log, is seems that the message rate increase to about 2000-2400/minute at that time for about 3 minutes, then dropped to <1000/min. [root@radius-a radius]# ps -aef | grep radiusd radiusd 5426 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 5738 21400 0 03:29 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8239 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8240 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8241 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8242 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8243 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 8244 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 9029 21400 0 03:32 ? 00:00:00 /usr/local/sbin/radiusd radiusd 9104 21400 0 03:29 ? 00:00:00 /usr/local/sbin/radiusd radiusd 14154 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 14426 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 15039 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 15040 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 16082 21400 0 03:36 ? 00:00:00 /usr/local/sbin/radiusd radiusd 17295 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd root 19242 20229 0 11:42 pts/0 00:00:00 grep radiusd radiusd 19974 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20670 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20673 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20674 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20675 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20679 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 20680 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21207 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21208 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21209 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21300 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21301 21400 0 03:33 ? 00:00:00 /usr/local/sbin/radiusd radiusd 21400 1 0 Oct07 ? 00:02:40 /usr/local/sbin/radiusd radiusd 26543 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 26683 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 28411 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 29065 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd radiusd 30648 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 30649 21400 0 03:34 ? 00:00:00 /usr/local/sbin/radiusd radiusd 30893 21400 0 03:31 ? 00:00:00 /usr/local/sbin/radiusd Thanks, -craig __________ Information from ESET Smart Security, version of virus signature database 4490 (20091008) __________ The message was checked by ESET Smart Security. http://www.eset.com __________ Information from ESET Smart Security, version of virus signature database 4490 (20091008) __________ The message was checked by ESET Smart Security. http://www.eset.com ------------------------------------------------------------------------------ - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html __________ Information from ESET Smart Security, version of virus signature database 4490 (20091008) __________ The message was checked by ESET Smart Security. http://www.eset.com __________ Information from ESET Smart Security, version of virus signature database 4490 (20091008) __________ The message was checked by ESET Smart Security. http://www.eset.com
Craig Campbell wrote:
radius-a seems to be getting the bulk of the radius records. Normally, it has a single process. Last night it spawned a bunch of children that seem to be loitering...
Are you forking shell scripts via "exec"?
radius-b and radius-c don't have more than a single radiusd process.
Any idea what is going on? Why all the children? Do I need to be concerned? Is this normal?
It's not normal. They're likely zombies that need to go away. The server normally cleans up any zombie children, but... Alan DeKok.
Yes, two(2) binaries and one (1) shell script are called via exec as follows from the file, - user (an authentication binary program - Exec-Program-Wait = "/usr/local/sbin/auth -- %{User-Name} %{User-Password} %{%{Called-Station-Id}:-Missing} %{%{NAS-IP-Address}:-Missing} %{%{Calling-Station-Id}:-Missing} %{%{NAS-Port-Type}:-Missing} %{Vendor-Specific}" ,) -acct_user (shell script - Exec-Program = "%{exec:/usr/local/sbin/acctstop.sh}", ) and -attr_rewrite module (a hex translation binary - replacewith = "%{exec:/usr/local/sbin/hexconvert -lX %{User-Name} }") Is this bad? Is there a better alternative? Thanks so much! -craig ----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Friday, October 09, 2009 4:17 PM Subject: Re: over 30 radiusd processes
Craig Campbell wrote:
radius-a seems to be getting the bulk of the radius records. Normally, it has a single process. Last night it spawned a bunch of children that seem to be loitering...
Are you forking shell scripts via "exec"?
radius-b and radius-c don't have more than a single radiusd process.
Any idea what is going on? Why all the children? Do I need to be concerned? Is this normal?
It's not normal. They're likely zombies that need to go away. The server normally cleans up any zombie children, but...
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4494 (20091009) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4494 (20091009) __________ The message was checked by ESET Smart Security. http://www.eset.com
Craig Campbell wrote:
Yes, two(2) binaries and one (1) shell script are called via exec as follows from the file,
Could you NOT CC me on messages to the list? I subscribe, and I read the messages. And fix your mailer. I saw a *large* number of duplicates.
- user (an authentication binary program - Exec-Program-Wait = "/usr/local/sbin/auth -- %{User-Name} %{User-Password} %{%{Called-Station-Id}:-Missing} %{%{NAS-IP-Address}:-Missing} %{%{Calling-Station-Id}:-Missing} %{%{NAS-Port-Type}:-Missing} %{Vendor-Specific}" ,)
-acct_user (shell script - Exec-Program = "%{exec:/usr/local/sbin/acctstop.sh}", ) and -attr_rewrite module (a hex translation binary - replacewith = "%{exec:/usr/local/sbin/hexconvert -lX %{User-Name} }")
Is this bad? Is there a better alternative?
Thanks so much! -craig
----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Friday, October 09, 2009 4:17 PM Subject: Re: over 30 radiusd processes
Craig Campbell wrote:
radius-a seems to be getting the bulk of the radius records. Normally, it has a single process. Last night it spawned a bunch of children that seem to be loitering...
Are you forking shell scripts via "exec"?
radius-b and radius-c don't have more than a single radiusd process.
Any idea what is going on? Why all the children? Do I need to be concerned? Is this normal?
It's not normal. They're likely zombies that need to go away. The server normally cleans up any zombie children, but...
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4494 (20091009) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4494 (20091009) __________
The message was checked by ESET Smart Security.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Up to 65 processes now.... Any ideas how to stop this from happening? Anyone? Thanks, -craig ----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Saturday, October 10, 2009 1:21 AM Subject: Re: over 30 radiusd processes
Craig Campbell wrote:
Yes, two(2) binaries and one (1) shell script are called via exec as follows from the file,
Could you NOT CC me on messages to the list? I subscribe, and I read the messages.
And fix your mailer. I saw a *large* number of duplicates.
- user (an authentication binary program - Exec-Program-Wait = "/usr/local/sbin/auth -- %{User-Name} %{User-Password} %{%{Called-Station-Id}:-Missing} %{%{NAS-IP-Address}:-Missing} %{%{Calling-Station-Id}:-Missing} %{%{NAS-Port-Type}:-Missing} %{Vendor-Specific}" ,)
-acct_user (shell script - Exec-Program = "%{exec:/usr/local/sbin/acctstop.sh}", ) and -attr_rewrite module (a hex translation binary - replacewith = "%{exec:/usr/local/sbin/hexconvert -lX %{User-Name} }")
Is this bad? Is there a better alternative?
Thanks so much! -craig
----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Friday, October 09, 2009 4:17 PM Subject: Re: over 30 radiusd processes
Craig Campbell wrote:
radius-a seems to be getting the bulk of the radius records. Normally, it has a single process. Last night it spawned a bunch of children that seem to be loitering...
Are you forking shell scripts via "exec"?
radius-b and radius-c don't have more than a single radiusd process.
Any idea what is going on? Why all the children? Do I need to be concerned? Is this normal?
It's not normal. They're likely zombies that need to go away. The server normally cleans up any zombie children, but...
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4494 (20091009) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4494 (20091009) __________
The message was checked by ESET Smart Security.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4494 (20091009) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4501 (20091012) __________ The message was checked by ESET Smart Security. http://www.eset.com
Freeradius 2.1.6 Running on Redhat AS5 Update 3 with mysql-devel rpms added to enable mysql support. Compiled with no options specified. (./configure ; make clean ; make ; make install) Thanks, -craig ----- Original Message ----- From: "Alan DeKok" <aland@deployingradius.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Tuesday, October 13, 2009 1:55 AM Subject: Re: over 30 radiusd processes
Craig Campbell wrote:
Up to 65 processes now....
Any ideas how to stop this from happening?
Which version are you running?
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4501 (20091012) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4502 (20091013) __________ The message was checked by ESET Smart Security. http://www.eset.com
Craig Campbell wrote:
Freeradius 2.1.6
Running on Redhat AS5 Update 3 with mysql-devel rpms added to enable mysql support.
Compiled with no options specified. (./configure ; make clean ; make ; make install)
I don't know.. all I know is it cleans up processes when I run them, and no one else seems to be running into this. Alan DeKok.
I had a same problem when one of our databases was terrible slow... Is there anything in radius.log ? Alan DeKok wrote:
Craig Campbell wrote:
Freeradius 2.1.6
Running on Redhat AS5 Update 3 with mysql-devel rpms added to enable mysql support.
Compiled with no options specified. (./configure ; make clean ; make ; make install)
I don't know.. all I know is it cleans up processes when I run them, and no one else seems to be running into this.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Nothing in the log except the normal startup. This server is only receiving accounting records currently. While the ps command doesn't show the time of these extra processes (over 24 hours old), in a previous event, I determined they seemed to coincide with a significant increase in radius traffic (from ~100/min to over 1000/min) I believe the NAS forces all users to log off (and they automatically log back in) in the middle of the night, and I suspect this is related. Also, the system provided is a Virtual Machine, which normally seems to have plenty of resources available. The mysql database is local to the same system, and is only used to keep accounting records of currently logged in users (radutmp replacement - a cron job flushed out completed records to prevent database growth). Alan suggested this might be related to shell scripts being run - as happens when acct STOP records are received. I'm trying to come up with a strategy to narrow down what might be happening. Under what circumstances does radiusd fork? Also, I THOUGH I'd heard somewhere that threads and fork did NOT interact well. I am also considering upgrading to 2.1.7 (but I just finished configuring 2.1.6 :( 2.1.7 wasn't released when I started this..) Thoughts? Thanks (everyone), -craig ----- Original Message ----- From: "Marinko Tarlac" <mangia81@gmail.com> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Wednesday, October 14, 2009 7:12 AM Subject: Re: over 30 radiusd processes
I had a same problem when one of our databases was terrible slow...
Is there anything in radius.log ?
Alan DeKok wrote:
Craig Campbell wrote:
Freeradius 2.1.6
Running on Redhat AS5 Update 3 with mysql-devel rpms added to enable mysql support.
Compiled with no options specified. (./configure ; make clean ; make ; make install)
I don't know.. all I know is it cleans up processes when I run them, and no one else seems to be running into this.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4506 (20091014) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4506 (20091014) __________ The message was checked by ESET Smart Security. http://www.eset.com
Craig Campbell wrote:
While the ps command doesn't show the time of these extra processes (over 24 hours old), in a previous event, I determined they seemed to coincide with a significant increase in radius traffic (from ~100/min to over 1000/min) I believe the NAS forces all users to log off (and they automatically log back in) in the middle of the night, and I suspect this is related.
Well, the server is *supposed* to clean up child processes.
Alan suggested this might be related to shell scripts being run - as happens when acct STOP records are received.
Yes. If you can replace the shell script with a Perl script and use rlm_perl, the issue will go away.
I'm trying to come up with a strategy to narrow down what might be happening.
The server isn't cleaning up child processes. For some reason, it's lost track of them.
Under what circumstances does radiusd fork? Also, I THOUGH I'd heard somewhere that threads and fork did NOT interact well.
It forks when you exec a program. Alan DeKok.
I've continued to try an investigate the root cause of this, and the last run behaved slightly differently - the parent process seems to have terminated, and there are more messages in the radius log. There were four (4) hung processes left over. I have attached the radius.log file below, as well as gdb sessions for the hung processes showing the results of the gd 'bt' and 'list' commands. It looks like Alan's initial idea that the hung processes are a result of running the acctstop.sh process are correct. I've tried looking at the code to see if anything 'leapt out' at me, but the logic is quite clever, and dissecting it from the middle is quite a challenge. I am hoping that the gdb output might prove helpful to someone already familiar with the logic flow. It seems I can reproduce this issue within 24 hours, so if there is any other information I could gather, please left me know. Thanks, -craig radiusd.log Fri Oct 16 11:15:56 2009 : Info: Exiting normally. Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Attempting to connect to radiusd@localhost:/radius Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server inner-tunnel Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server copy-acct-to-home-server Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server copy-acct-to-radius-c Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server <default> Fri Oct 16 11:16:22 2009 : Info: Ready to process requests. Fri Oct 16 17:29:12 2009 : Error: [sql] stop packet with zero session length. [user 'user35@realm4TL', nas '192.168.1.101'] Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session length. [user 'user22@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session length. [user 'user17@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session length. [user 'user38@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:20 2009 : Error: [sql] stop packet with zero session length. [user 'user7@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:20 2009 : Error: [sql] stop packet with zero session length. [user 'user52@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:20 2009 : Error: [sql] stop packet with zero session length. [user 'user34@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:20 2009 : Error: [sql] stop packet with zero session length. [user 'user26@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:20 2009 : Error: [sql] stop packet with zero session length. [user 'user77@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:20 2009 : Error: [sql] stop packet with zero session length. [user 'user19@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user50@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user6@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user59@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user70@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user58@realm4', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user88@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user5@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'username', nas '192.168.1.101'] Sat Oct 17 02:00:21 2009 : Error: [sql] stop packet with zero session length. [user 'user93@realm2', nas '192.168.1.101'] Sat Oct 17 02:00:22 2009 : Error: [sql] stop packet with zero session length. [user 'user87@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:22 2009 : Error: [sql] stop packet with zero session length. [user 'user48@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:22 2009 : Error: [sql] stop packet with zero session length. [user 'user37@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:22 2009 : Error: [sql] stop packet with zero session length. [user 'user31@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:22 2009 : Error: [sql] stop packet with zero session length. [user 'user68@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:22 2009 : Error: [sql] stop packet with zero session length. [user 'user69@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:23 2009 : Error: [sql] stop packet with zero session length. [user 'user92@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Info: rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0 Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user4@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user67@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user46@realm5', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user14@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user21@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user58@realm4', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user75@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user32@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user74@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user47@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user56@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user36@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user '-f', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user29@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user63@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:24 2009 : Error: [sql] stop packet with zero session length. [user 'user89@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:25 2009 : Error: [sql] stop packet with zero session length. [user 'user23@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:25 2009 : Error: [sql] stop packet with zero session length. [user 'user60@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:26 2009 : Error: [sql] stop packet with zero session length. [user 'user18@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:26 2009 : Error: [sql] stop packet with zero session length. [user 'user8@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:26 2009 : Error: [sql] stop packet with zero session length. [user 'user90@realm6', nas '192.168.1.101'] Sat Oct 17 02:00:26 2009 : Error: [sql] stop packet with zero session length. [user 'user65@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:28 2009 : Error: [sql] stop packet with zero session length. [user 'user55@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:28 2009 : Error: [sql] stop packet with zero session length. [user 'user76@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:29 2009 : Error: [sql] stop packet with zero session length. [user 'user82@realm5', nas '192.168.1.101'] Sat Oct 17 02:00:29 2009 : Error: [sql] stop packet with zero session length. [user 'user53@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:30 2009 : Error: [sql] stop packet with zero session length. [user 'user45@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:30 2009 : Error: [sql] stop packet with zero session length. [user 'user16@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:30 2009 : Error: [sql] stop packet with zero session length. [user 'user43@hotmail.com', nas '192.168.1.101'] Sat Oct 17 02:00:30 2009 : Error: [sql] stop packet with zero session length. [user 'user12@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:31 2009 : Error: [sql] stop packet with zero session length. [user 'user1@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:31 2009 : Error: [sql] stop packet with zero session length. [user 'user73@realm6', nas '192.168.1.101'] Sat Oct 17 02:00:32 2009 : Error: [sql] stop packet with zero session length. [user 'user39@realm5', nas '192.168.1.101'] Sat Oct 17 02:00:33 2009 : Error: [sql] stop packet with zero session length. [user 'user57@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:33 2009 : Error: [sql] stop packet with zero session length. [user 'user58@realm4', nas '192.168.1.101'] Sat Oct 17 02:00:34 2009 : Error: [sql] stop packet with zero session length. [user 'user66@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:34 2009 : Error: [sql] stop packet with zero session length. [user 'user26@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:35 2009 : Error: [sql] stop packet with zero session length. [user 'user17@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:36 2009 : Error: [sql] stop packet with zero session length. [user 'user77@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:36 2009 : Error: [sql] stop packet with zero session length. [user 'user52@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:36 2009 : Error: [sql] stop packet with zero session length. [user 'user34@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:37 2009 : Error: [sql] stop packet with zero session length. [user 'user70@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:37 2009 : Error: [sql] stop packet with zero session length. [user 'user50@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:37 2009 : Error: [sql] stop packet with zero session length. [user 'user6@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:38 2009 : Error: [sql] stop packet with zero session length. [user 'user68@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:39 2009 : Error: [sql] stop packet with zero session length. [user 'username', nas '192.168.1.101'] Sat Oct 17 02:00:40 2009 : Error: [sql] stop packet with zero session length. [user '-f', nas '192.168.1.101'] Sat Oct 17 02:00:40 2009 : Error: [sql] stop packet with zero session length. [user 'user36@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:40 2009 : Error: [sql] stop packet with zero session length. [user 'user4@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:43 2009 : Error: [sql] stop packet with zero session length. [user 'user19@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:43 2009 : Error: [sql] stop packet with zero session length. [user 'user31@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:44 2009 : Error: [sql] stop packet with zero session length. [user 'user22@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:44 2009 : Error: [sql] stop packet with zero session length. [user 'user29@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:44 2009 : Error: [sql] stop packet with zero session length. [user 'user38@realm3', nas '192.168.1.101'] Sat Oct 17 02:00:45 2009 : Error: [sql] stop packet with zero session length. [user 'user62@realm1', nas '192.168.1.101'] Sat Oct 17 02:01:25 2009 : Error: WARNING: Unresponsive child for request 165616, in module sql component accounting Sat Oct 17 02:01:51 2009 : Error: WARNING: Unresponsive child for request 165736, in module sql component accounting Sat Oct 17 02:01:56 2009 : Error: WARNING: Unresponsive child for request 165745, in module sql component accounting Sat Oct 17 02:02:38 2009 : Error: WARNING: Unresponsive child for request 165826, in module sql component accounting Sat Oct 17 02:03:07 2009 : Error: WARNING: Unresponsive child for request 165856, in module sql component accounting Sat Oct 17 02:04:08 2009 : Error: WARNING: Unresponsive child for request 165946, in module sql component accounting Sat Oct 17 02:05:23 2009 : Error: WARNING: Unresponsive child for request 166006, in module sql component accounting Sat Oct 17 02:06:18 2009 : Error: WARNING: Unresponsive child for request 166066, in module sql component accounting Sat Oct 17 02:07:05 2009 : Error: WARNING: Unresponsive child for request 166111, in module sql component accounting Sat Oct 17 02:08:54 2009 : Error: WARNING: Unresponsive child for request 166261, in module sql component accounting Sat Oct 17 02:10:08 2009 : Error: WARNING: Unresponsive child for request 166321, in module sql component accounting Sat Oct 17 02:12:00 2009 : Error: Received conflicting packet from client BRAS_101 port 50125 - ID: 237 due to unfinished request 1 65745. Giving up on old request. Sat Oct 17 02:13:03 2009 : Error: WARNING: Unresponsive child for request 166546, in module sql component accounting Sat Oct 17 02:18:43 2009 : Error: Received conflicting packet from client BRAS_101 port 50125 - ID: 174 due to unfinished request 1 66321. Giving up on old request. Sat Oct 17 02:21:22 2009 : Error: Received conflicting packet from client BRAS_101 port 50125 - ID: 249 due to unfinished request 1 66546. Giving up on old request. Sat Oct 17 03:19:38 2009 : Error: WARNING: Unresponsive child for request 172846, in module sql component accounting Sat Oct 17 03:20:47 2009 : Error: WARNING: Unresponsive child for request 173071, in module sql component accounting Sat Oct 17 03:21:47 2009 : Error: WARNING: Unresponsive child for request 173188, in module sql component accounting Sat Oct 17 03:22:20 2009 : Error: WARNING: Unresponsive child for request 173251, in module sql component accounting Sat Oct 17 03:22:57 2009 : Error: WARNING: Unresponsive child for request 173311, in module sql component accounting Sat Oct 17 03:23:23 2009 : Error: WARNING: Unresponsive child for request 173371, in module sql component accounting Sat Oct 17 03:25:30 2009 : Error: WARNING: Unresponsive child for request 173611, in module sql component accounting Sat Oct 17 03:27:00 2009 : Error: WARNING: Unresponsive child for request 173776, in module sql component accounting Sat Oct 17 03:27:25 2009 : Error: WARNING: Unresponsive child for request 173836, in module sql component accounting Sat Oct 17 03:28:18 2009 : Error: WARNING: Unresponsive child for request 173940, in module sql component accounting Sat Oct 17 03:29:01 2009 : Error: WARNING: Unresponsive child for request 174001, in module sql component accounting Sat Oct 17 03:29:41 2009 : Error: WARNING: Unresponsive child for request 174076, in module sql component accounting Sat Oct 17 03:30:06 2009 : Error: WARNING: Unresponsive child for request 174135, in module sql component accounting Sat Oct 17 03:31:53 2009 : Error: WARNING: Unresponsive child for request 174492, in module sql component accounting Sat Oct 17 03:32:13 2009 : Error: WARNING: Unresponsive child for request 174571, in module sql component accounting Sat Oct 17 03:32:43 2009 : Error: WARNING: Unresponsive child for request 174703, in module sql component accounting Sat Oct 17 03:34:20 2009 : Error: WARNING: Unresponsive child for request 175407, in module sql component accounting Sat Oct 17 03:36:08 2009 : Error: WARNING: Unresponsive child for request 176535, in module sql component accounting Sat Oct 17 03:37:36 2009 : Error: WARNING: Unresponsive child for request 177306, in module sql component accounting Sat Oct 17 03:38:24 2009 : Error: WARNING: Unresponsive child for request 177569, in module sql component accounting Sat Oct 17 03:38:58 2009 : Error: WARNING: Unresponsive child for request 177691, in module sql component accounting Sat Oct 17 03:40:03 2009 : Error: WARNING: Unresponsive child for request 177886, in module sql component accounting Sat Oct 17 03:40:07 2009 : Error: WARNING: Unresponsive child for request 177895, in module sql component accounting Sat Oct 17 03:41:08 2009 : Error: WARNING: Unresponsive child for request 178006, in module sql component accounting Sat Oct 17 03:44:39 2009 : Error: WARNING: Unresponsive child for request 178455, in module sql component accounting Sat Oct 17 03:45:52 2009 : Error: WARNING: Unresponsive child for request 178679, in module sql component accounting Sat Oct 17 03:46:19 2009 : Error: WARNING: Unresponsive child for request 178755, in module sql component accounting Sat Oct 17 03:47:57 2009 : Error: WARNING: Unresponsive child for request 178996, in module sql component accounting Sat Oct 17 03:48:20 2009 : Error: WARNING: Unresponsive child for request 179040, in module sql component accounting Sat Oct 17 03:48:35 2009 : Error: WARNING: Unresponsive child for request 179086, in module sql component accounting Sat Oct 17 03:49:35 2009 : Error: WARNING: Unresponsive child for request 179206, in module sql component accounting Sat Oct 17 03:50:34 2009 : Error: WARNING: Unresponsive child for request 179355, in module sql component accounting Sat Oct 17 03:51:53 2009 : Error: WARNING: Unresponsive child for request 179536, in module sql component accounting Sat Oct 17 03:52:45 2009 : Error: WARNING: Unresponsive child for request 179656, in module sql component accounting Sat Oct 17 03:53:55 2009 : Error: WARNING: Unresponsive child for request 179821, in module sql component accounting Sat Oct 17 03:54:18 2009 : Error: WARNING: Unresponsive child for request 179894, in module sql component accounting Sat Oct 17 03:55:27 2009 : Error: WARNING: Unresponsive child for request 180076, in module sql component accounting Sat Oct 17 03:56:20 2009 : Error: WARNING: Unresponsive child for request 180181, in module sql component accounting Sat Oct 17 03:57:51 2009 : Error: WARNING: Unresponsive child for request 180344, in module sql component accounting Sat Oct 17 03:58:27 2009 : Error: WARNING: Unresponsive child for request 180421, in module sql component accounting Sat Oct 17 03:59:46 2009 : Error: WARNING: Unresponsive child for request 180571, in module sql component accounting Sat Oct 17 04:00:25 2009 : Error: WARNING: Unresponsive child for request 180646, in module sql component accounting Sat Oct 17 04:00:57 2009 : Error: WARNING: Unresponsive child for request 180706, in module sql component accounting Sat Oct 17 04:02:53 2009 : Error: WARNING: Unresponsive child for request 180884, in module sql component accounting Sat Oct 17 04:03:46 2009 : Error: WARNING: Unresponsive child for request 180976, in module sql component accounting Sat Oct 17 04:04:14 2009 : Error: WARNING: Unresponsive child for request 181014, in module sql component accounting Sat Oct 17 04:06:38 2009 : Error: WARNING: Unresponsive child for request 181169, in module sql component accounting Sat Oct 17 04:11:51 2009 : Error: Received conflicting packet from client BRAS_101 port 50125 - ID: 214 due to unfinished request 1 80976. Giving up on old request. Sat Oct 17 04:20:09 2009 : Error: WARNING: Unresponsive child for request 182701, in module sql component accounting Sat Oct 17 04:25:24 2009 : Error: WARNING: Unresponsive child for request 183204, in module sql component accounting Sat Oct 17 04:28:27 2009 : Error: WARNING: Unresponsive child for request 183430, in module sql component accounting Sat Oct 17 04:36:18 2009 : Error: WARNING: Unresponsive child for request 184270, in module sql component accounting Sat Oct 17 04:37:30 2009 : Error: WARNING: Unresponsive child for request 184396, in module sql component accounting Sat Oct 17 04:38:20 2009 : Error: WARNING: Unresponsive child for request 184456, in module sql component accounting Sat Oct 17 04:46:28 2009 : Error: WARNING: Unresponsive child for request 185131, in module sql component accounting Sat Oct 17 04:46:33 2009 : Error: WARNING: Unresponsive child for request 185140, in module sql component accounting Sat Oct 17 04:51:55 2009 : Error: WARNING: Unresponsive child for request 185536, in module sql component accounting Sat Oct 17 04:55:24 2009 : Error: WARNING: Unresponsive child for request 185785, in module sql component accounting Sat Oct 17 05:00:32 2009 : Error: Received conflicting packet from client BRAS_101 port 50125 - ID: 201 due to unfinished request 1 85536. Giving up on old request. Sat Oct 17 05:10:44 2009 : Error: WARNING: Unresponsive child for request 187088, in module sql component accounting Sat Oct 17 05:19:02 2009 : Error: Received conflicting packet from client BRAS_101 port 50125 - ID: 208 due to unfinished request 1 87088. Giving up on old request. Sat Oct 17 06:11:37 2009 : Info: Exiting normally. [root@radius-a ~]# gdb process 13073 GNU gdb Fedora (6.8-27.el5) Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu"... process: No such file or directory. Attaching to process 13073 Reading symbols from /usr/local/sbin/radiusd...done. Reading symbols from /usr/local/lib/libfreeradius-radius-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-radius-2.1.7.so Reading symbols from /lib64/libnsl.so.1...done. Loaded symbols for /lib64/libnsl.so.1 Reading symbols from /lib64/libresolv.so.2...done. Loaded symbols for /lib64/libresolv.so.2 Reading symbols from /lib64/libpthread.so.0...done. [Thread debugging using libthread_db enabled] [New Thread 0x430f1940 (LWP 13073)] Loaded symbols for /lib64/libpthread.so.0 Reading symbols from /lib64/libcrypt.so.1...done. Loaded symbols for /lib64/libcrypt.so.1 Reading symbols from /usr/local/lib/libltdl.so.3...done. Loaded symbols for /usr/local/lib/libltdl.so.3 Reading symbols from /lib64/libssl.so.6...done. Loaded symbols for /lib64/libssl.so.6 Reading symbols from /lib64/libcrypto.so.6...done. Loaded symbols for /lib64/libcrypto.so.6 Reading symbols from /lib64/libc.so.6...done. Loaded symbols for /lib64/libc.so.6 Reading symbols from /lib64/ld-linux-x86-64.so.2...done. Loaded symbols for /lib64/ld-linux-x86-64.so.2 Reading symbols from /lib64/libdl.so.2...done. Loaded symbols for /lib64/libdl.so.2 Reading symbols from /usr/lib64/libgssapi_krb5.so.2...done. Loaded symbols for /usr/lib64/libgssapi_krb5.so.2 Reading symbols from /usr/lib64/libkrb5.so.3...done. Loaded symbols for /usr/lib64/libkrb5.so.3 Reading symbols from /lib64/libcom_err.so.2...done. Loaded symbols for /lib64/libcom_err.so.2 Reading symbols from /usr/lib64/libk5crypto.so.3...done. Loaded symbols for /usr/lib64/libk5crypto.so.3 Reading symbols from /usr/lib64/libz.so.1...done. Loaded symbols for /usr/lib64/libz.so.1 Reading symbols from /usr/lib64/libkrb5support.so.0...done. Loaded symbols for /usr/lib64/libkrb5support.so.0 Reading symbols from /lib64/libkeyutils.so.1...done. Loaded symbols for /lib64/libkeyutils.so.1 Reading symbols from /lib64/libselinux.so.1...done. Loaded symbols for /lib64/libselinux.so.1 Reading symbols from /lib64/libsepol.so.1...done. Loaded symbols for /lib64/libsepol.so.1 Reading symbols from /lib64/libnss_files.so.2...done. Loaded symbols for /lib64/libnss_files.so.2 Reading symbols from /usr/local/lib/rlm_exec-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_exec-2.1.7.so Reading symbols from /usr/local/lib/rlm_expr-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expr-2.1.7.so Reading symbols from /usr/local/lib/rlm_expiration-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expiration-2.1.7.so Reading symbols from /usr/local/lib/rlm_logintime-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_logintime-2.1.7.so Reading symbols from /usr/local/lib/rlm_pap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_pap-2.1.7.so Reading symbols from /usr/local/lib/rlm_chap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_chap-2.1.7.so Reading symbols from /usr/local/lib/rlm_mschap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_mschap-2.1.7.so Reading symbols from /usr/local/lib/rlm_unix-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_unix-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap-2.1.7.so Reading symbols from /usr/local/lib/libfreeradius-eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-eap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_md5-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_md5-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_leap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_leap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_gtc-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_gtc-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_tls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_tls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_ttls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_ttls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_peap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_peap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_mschapv2-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_mschapv2-2.1.7.so Reading symbols from /usr/local/lib/rlm_realm-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_realm-2.1.7.so Reading symbols from /usr/local/lib/rlm_files-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_files-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql_mysql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql_mysql-2.1.7.so Reading symbols from /usr/lib64/mysql/libmysqlclient_r.so.15...done. Loaded symbols for /usr/lib64/mysql/libmysqlclient_r.so.15 Reading symbols from /lib64/libm.so.6...done. Loaded symbols for /lib64/libm.so.6 Reading symbols from /usr/local/lib/rlm_attr_filter-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_filter-2.1.7.so Reading symbols from /usr/local/lib/rlm_preprocess-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_preprocess-2.1.7.so Reading symbols from /usr/local/lib/rlm_always-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_always-2.1.7.so Reading symbols from /usr/local/lib/rlm_attr_rewrite-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_rewrite-2.1.7.so Reading symbols from /usr/local/lib/rlm_acct_unique-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_acct_unique-2.1.7.so Reading symbols from /usr/local/lib/rlm_detail-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_detail-2.1.7.so Reading symbols from /usr/local/lib/rlm_radutmp-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_radutmp-2.1.7.so 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 (gdb) bt #0 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x0000003acf48c75d in _L_lock_1685 () from /lib64/libc.so.6 #2 0x0000003acf48c4a7 in __tz_convert () from /lib64/libc.so.6 #3 0x00002b794fa6e39f in vp_prints_value (out=0x430ef6c0 "", outlen=1008, vp=<value optimized out>, delimitst=<value optimized out>) at print.c:267 #4 0x000000000040dbb5 in radius_exec_program (cmd=0x2aaab4001180 "/usr/local/sbin/acctstop.sh", request=0x2aaab4009500, exec_wait=0, user_msg=0x0, msg_len=254, input_pairs=0x2aaab40028d0, output_pairs=0x0, shell_escape=1) at exec.c:330 #5 0x00002b79500b9141 in exec_xlat (instance=0xe8d5d70, request=0x2aaab4009500, fmt=0x2aaab4001180 "/usr/local/sbin/acctstop.sh", out=0x430f0110 "", outlen=254, func=<value optimized out>) at rlm_exec.c:138 #6 0x000000000041eb2c in radius_xlat (out=<value optimized out>, outlen=254, fmt=0x2aaab4012c58 "%{exec:/usr/local/sbin/acctstop.sh}", request=0x2aaab4009500, func=0x41dee0 <xlat_copy>) at xlat.c:911 #7 0x000000000041d5a4 in pairxlatmove (req=0x2aaab4009500, to=0x2aaab40096b8, from=0x430f03d0) at valuepair.c:587 #8 0x00002b79524f7fc8 in file_common (inst=<value optimized out>, request=0x2aaab4009500, filename=0x2b79524f8753 "acct_users", ht=<value optimized out>, request_pairs=0x2aaab4008e40, reply_pairs=0x2aaab40096b8) at rlm_files.c:472 #9 0x00000000004199d1 in modcall (component=2, c=<value optimized out>, request=0x2aaab4009500) at modcall.c:292 #10 0x0000000000416f9d in indexed_modcall (comp=2, idx=0, request=0x2aaab4009500) at modules.c:691 #11 0x0000000000407eae in rad_accounting (request=0x2aaab4009500) at acct.c:57 #12 0x0000000000422c58 in radius_handle_request (request=0x2aaab4009500, fun=0x407e70 <rad_accounting>) at event.c:3693 #13 0x000000000041c5c6 in request_handler_thread (arg=<value optimized out>) at threads.c:492 #14 0x0000003ad0006367 in start_thread () from /lib64/libpthread.so.0 #15 0x0000003acf4d30ad in clone () from /lib64/libc.so.6 (gdb) (gdb) list 83 static void sig_fatal (int); 84 #ifdef SIGHUP 85 static void sig_hup (int); 86 #endif 87 88 /* 89 * The main guy. 90 */ 91 int main(int argc, char *argv[]) 92 { [root@radius-a ~]# gdb process 22325 GNU gdb Fedora (6.8-27.el5) Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu"... process: No such file or directory. Attaching to process 22325 Reading symbols from /usr/local/sbin/radiusd...done. Reading symbols from /usr/local/lib/libfreeradius-radius-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-radius-2.1.7.so Reading symbols from /lib64/libnsl.so.1...done. Loaded symbols for /lib64/libnsl.so.1 Reading symbols from /lib64/libresolv.so.2...done. Loaded symbols for /lib64/libresolv.so.2 Reading symbols from /lib64/libpthread.so.0...done. [Thread debugging using libthread_db enabled] [New Thread 0x41cef940 (LWP 22325)] Loaded symbols for /lib64/libpthread.so.0 Reading symbols from /lib64/libcrypt.so.1...done. Loaded symbols for /lib64/libcrypt.so.1 Reading symbols from /usr/local/lib/libltdl.so.3...done. Loaded symbols for /usr/local/lib/libltdl.so.3 Reading symbols from /lib64/libssl.so.6...done. Loaded symbols for /lib64/libssl.so.6 Reading symbols from /lib64/libcrypto.so.6...done. Loaded symbols for /lib64/libcrypto.so.6 Reading symbols from /lib64/libc.so.6...done. Loaded symbols for /lib64/libc.so.6 Reading symbols from /lib64/ld-linux-x86-64.so.2...done. Loaded symbols for /lib64/ld-linux-x86-64.so.2 Reading symbols from /lib64/libdl.so.2...done. Loaded symbols for /lib64/libdl.so.2 Reading symbols from /usr/lib64/libgssapi_krb5.so.2...done. Loaded symbols for /usr/lib64/libgssapi_krb5.so.2 Reading symbols from /usr/lib64/libkrb5.so.3...done. Loaded symbols for /usr/lib64/libkrb5.so.3 Reading symbols from /lib64/libcom_err.so.2...done. Loaded symbols for /lib64/libcom_err.so.2 Reading symbols from /usr/lib64/libk5crypto.so.3...done. Loaded symbols for /usr/lib64/libk5crypto.so.3 Reading symbols from /usr/lib64/libz.so.1...done. Loaded symbols for /usr/lib64/libz.so.1 Reading symbols from /usr/lib64/libkrb5support.so.0...done. Loaded symbols for /usr/lib64/libkrb5support.so.0 Reading symbols from /lib64/libkeyutils.so.1...done. Loaded symbols for /lib64/libkeyutils.so.1 Reading symbols from /lib64/libselinux.so.1...done. Loaded symbols for /lib64/libselinux.so.1 Reading symbols from /lib64/libsepol.so.1...done. Loaded symbols for /lib64/libsepol.so.1 Reading symbols from /lib64/libnss_files.so.2...done. Loaded symbols for /lib64/libnss_files.so.2 Reading symbols from /usr/local/lib/rlm_exec-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_exec-2.1.7.so Reading symbols from /usr/local/lib/rlm_expr-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expr-2.1.7.so Reading symbols from /usr/local/lib/rlm_expiration-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expiration-2.1.7.so Reading symbols from /usr/local/lib/rlm_logintime-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_logintime-2.1.7.so Reading symbols from /usr/local/lib/rlm_pap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_pap-2.1.7.so Reading symbols from /usr/local/lib/rlm_chap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_chap-2.1.7.so Reading symbols from /usr/local/lib/rlm_mschap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_mschap-2.1.7.so Reading symbols from /usr/local/lib/rlm_unix-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_unix-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap-2.1.7.so Reading symbols from /usr/local/lib/libfreeradius-eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-eap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_md5-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_md5-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_leap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_leap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_gtc-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_gtc-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_tls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_tls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_ttls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_ttls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_peap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_peap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_mschapv2-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_mschapv2-2.1.7.so Reading symbols from /usr/local/lib/rlm_realm-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_realm-2.1.7.so Reading symbols from /usr/local/lib/rlm_files-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_files-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql_mysql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql_mysql-2.1.7.so Reading symbols from /usr/lib64/mysql/libmysqlclient_r.so.15...done. Loaded symbols for /usr/lib64/mysql/libmysqlclient_r.so.15 Reading symbols from /lib64/libm.so.6...done. Loaded symbols for /lib64/libm.so.6 Reading symbols from /usr/local/lib/rlm_attr_filter-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_filter-2.1.7.so Reading symbols from /usr/local/lib/rlm_preprocess-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_preprocess-2.1.7.so Reading symbols from /usr/local/lib/rlm_always-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_always-2.1.7.so Reading symbols from /usr/local/lib/rlm_attr_rewrite-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_rewrite-2.1.7.so Reading symbols from /usr/local/lib/rlm_acct_unique-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_acct_unique-2.1.7.so Reading symbols from /usr/local/lib/rlm_detail-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_detail-2.1.7.so Reading symbols from /usr/local/lib/rlm_radutmp-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_radutmp-2.1.7.so 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 (gdb) bt #0 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x0000003acf48c75d in _L_lock_1685 () from /lib64/libc.so.6 #2 0x0000003acf48c4a7 in __tz_convert () from /lib64/libc.so.6 #3 0x00002b794fa6e39f in vp_prints_value (out=0x41ced6c0 "", outlen=1008, vp=<value optimized out>, delimitst=<value optimized out>) at print.c:267 #4 0x000000000040dbb5 in radius_exec_program (cmd=0xea10e30 "/usr/local/sbin/acctstop.sh", request=0x2aaab4001f40, exec_wait=0, user_msg=0x0, msg_len=254, input_pairs=0xea0e600, output_pairs=0x0, shell_escape=1) at exec.c:330 #5 0x00002b79500b9141 in exec_xlat (instance=0xe8d5d70, request=0x2aaab4001f40, fmt=0xea10e30 "/usr/local/sbin/acctstop.sh", out=0x41cee110 "", outlen=254, func=<value optimized out>) at rlm_exec.c:138 #6 0x000000000041eb2c in radius_xlat (out=<value optimized out>, outlen=254, fmt=0xea10be8 "%{exec:/usr/local/sbin/acctstop.sh}", request=0x2aaab4001f40, func=0x41dee0 <xlat_copy>) at xlat.c:911 #7 0x000000000041d5a4 in pairxlatmove (req=0x2aaab4001f40, to=0x2aaab40020f8, from=0x41cee3d0) at valuepair.c:587 #8 0x00002b79524f7fc8 in file_common (inst=<value optimized out>, request=0x2aaab4001f40, filename=0x2b79524f8753 "acct_users", ht=<value optimized out>, request_pairs=0xea084e0, reply_pairs=0x2aaab40020f8) at rlm_files.c:472 #9 0x00000000004199d1 in modcall (component=2, c=<value optimized out>, request=0x2aaab4001f40) at modcall.c:292 #10 0x0000000000416f9d in indexed_modcall (comp=2, idx=0, request=0x2aaab4001f40) at modules.c:691 #11 0x0000000000407eae in rad_accounting (request=0x2aaab4001f40) at acct.c:57 #12 0x0000000000422c58 in radius_handle_request (request=0x2aaab4001f40, fun=0x407e70 <rad_accounting>) at event.c:3693 #13 0x000000000041c5c6 in request_handler_thread (arg=<value optimized out>) at threads.c:492 #14 0x0000003ad0006367 in start_thread () from /lib64/libpthread.so.0 #15 0x0000003acf4d30ad in clone () from /lib64/libc.so.6 (gdb) list 83 static void sig_fatal (int); 84 #ifdef SIGHUP 85 static void sig_hup (int); 86 #endif 87 88 /* 89 * The main guy. 90 */ 91 int main(int argc, char *argv[]) 92 { (gdb) [root@radius-a ~]# gdb process 21201 GNU gdb Fedora (6.8-27.el5) Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu"... process: No such file or directory. Attaching to process 21201 Reading symbols from /usr/local/sbin/radiusd...done. Reading symbols from /usr/local/lib/libfreeradius-radius-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-radius-2.1.7.so Reading symbols from /lib64/libnsl.so.1...done. Loaded symbols for /lib64/libnsl.so.1 Reading symbols from /lib64/libresolv.so.2...done. Loaded symbols for /lib64/libresolv.so.2 Reading symbols from /lib64/libpthread.so.0...done. [Thread debugging using libthread_db enabled] [New Thread 0x412ee940 (LWP 21201)] Loaded symbols for /lib64/libpthread.so.0 Reading symbols from /lib64/libcrypt.so.1...done. Loaded symbols for /lib64/libcrypt.so.1 Reading symbols from /usr/local/lib/libltdl.so.3...done. Loaded symbols for /usr/local/lib/libltdl.so.3 Reading symbols from /lib64/libssl.so.6...done. Loaded symbols for /lib64/libssl.so.6 Reading symbols from /lib64/libcrypto.so.6...done. Loaded symbols for /lib64/libcrypto.so.6 Reading symbols from /lib64/libc.so.6...done. Loaded symbols for /lib64/libc.so.6 Reading symbols from /lib64/ld-linux-x86-64.so.2...done. Loaded symbols for /lib64/ld-linux-x86-64.so.2 Reading symbols from /lib64/libdl.so.2...done. Loaded symbols for /lib64/libdl.so.2 Reading symbols from /usr/lib64/libgssapi_krb5.so.2...done. Loaded symbols for /usr/lib64/libgssapi_krb5.so.2 Reading symbols from /usr/lib64/libkrb5.so.3...done. Loaded symbols for /usr/lib64/libkrb5.so.3 Reading symbols from /lib64/libcom_err.so.2...done. Loaded symbols for /lib64/libcom_err.so.2 Reading symbols from /usr/lib64/libk5crypto.so.3...done. Loaded symbols for /usr/lib64/libk5crypto.so.3 Reading symbols from /usr/lib64/libz.so.1...done. Loaded symbols for /usr/lib64/libz.so.1 Reading symbols from /usr/lib64/libkrb5support.so.0...done. Loaded symbols for /usr/lib64/libkrb5support.so.0 Reading symbols from /lib64/libkeyutils.so.1...done. Loaded symbols for /lib64/libkeyutils.so.1 Reading symbols from /lib64/libselinux.so.1...done. Loaded symbols for /lib64/libselinux.so.1 Reading symbols from /lib64/libsepol.so.1...done. Loaded symbols for /lib64/libsepol.so.1 Reading symbols from /lib64/libnss_files.so.2...done. Loaded symbols for /lib64/libnss_files.so.2 Reading symbols from /usr/local/lib/rlm_exec-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_exec-2.1.7.so Reading symbols from /usr/local/lib/rlm_expr-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expr-2.1.7.so Reading symbols from /usr/local/lib/rlm_expiration-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expiration-2.1.7.so Reading symbols from /usr/local/lib/rlm_logintime-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_logintime-2.1.7.so Reading symbols from /usr/local/lib/rlm_pap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_pap-2.1.7.so Reading symbols from /usr/local/lib/rlm_chap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_chap-2.1.7.so Reading symbols from /usr/local/lib/rlm_mschap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_mschap-2.1.7.so Reading symbols from /usr/local/lib/rlm_unix-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_unix-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap-2.1.7.so Reading symbols from /usr/local/lib/libfreeradius-eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-eap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_md5-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_md5-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_leap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_leap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_gtc-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_gtc-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_tls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_tls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_ttls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_ttls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_peap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_peap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_mschapv2-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_mschapv2-2.1.7.so Reading symbols from /usr/local/lib/rlm_realm-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_realm-2.1.7.so Reading symbols from /usr/local/lib/rlm_files-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_files-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql_mysql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql_mysql-2.1.7.so Reading symbols from /usr/lib64/mysql/libmysqlclient_r.so.15...done. Loaded symbols for /usr/lib64/mysql/libmysqlclient_r.so.15 Reading symbols from /lib64/libm.so.6...done. Loaded symbols for /lib64/libm.so.6 Reading symbols from /usr/local/lib/rlm_attr_filter-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_filter-2.1.7.so Reading symbols from /usr/local/lib/rlm_preprocess-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_preprocess-2.1.7.so Reading symbols from /usr/local/lib/rlm_always-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_always-2.1.7.so Reading symbols from /usr/local/lib/rlm_attr_rewrite-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_rewrite-2.1.7.so Reading symbols from /usr/local/lib/rlm_acct_unique-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_acct_unique-2.1.7.so Reading symbols from /usr/local/lib/rlm_detail-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_detail-2.1.7.so Reading symbols from /usr/local/lib/rlm_radutmp-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_radutmp-2.1.7.so 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 (gdb) bt #0 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x0000003acf48c75d in _L_lock_1685 () from /lib64/libc.so.6 #2 0x0000003acf48c4a7 in __tz_convert () from /lib64/libc.so.6 #3 0x00002b794fa6e39f in vp_prints_value (out=0x412ec6c0 "", outlen=1008, vp=<value optimized out>, delimitst=<value optimized out>) at print.c:267 #4 0x000000000040dbb5 in radius_exec_program (cmd=0xe967550 "/usr/local/sbin/acctstop.sh", request=0x2aaab401e9d0, exec_wait=0, user_msg=0x0, msg_len=254, input_pairs=0xea1a0f0, output_pairs=0x0, shell_escape=1) at exec.c:330 #5 0x00002b79500b9141 in exec_xlat (instance=0xe8d5d70, request=0x2aaab401e9d0, fmt=0xe967550 "/usr/local/sbin/acctstop.sh", out=0x412ed110 "", outlen=254, func=<value optimized out>) at rlm_exec.c:138 #6 0x000000000041eb2c in radius_xlat (out=<value optimized out>, outlen=254, fmt=0xea1bf88 "%{exec:/usr/local/sbin/acctstop.sh}", request=0x2aaab401e9d0, func=0x41dee0 <xlat_copy>) at xlat.c:911 #7 0x000000000041d5a4 in pairxlatmove (req=0x2aaab401e9d0, to=0x2aaab401eb88, from=0x412ed3d0) at valuepair.c:587 #8 0x00002b79524f7fc8 in file_common (inst=<value optimized out>, request=0x2aaab401e9d0, filename=0x2b79524f8753 "acct_users", ht=<value optimized out>, request_pairs=0xea19e70, reply_pairs=0x2aaab401eb88) at rlm_files.c:472 #9 0x00000000004199d1 in modcall (component=2, c=<value optimized out>, request=0x2aaab401e9d0) at modcall.c:292 #10 0x0000000000416f9d in indexed_modcall (comp=2, idx=0, request=0x2aaab401e9d0) at modules.c:691 #11 0x0000000000407eae in rad_accounting (request=0x2aaab401e9d0) at acct.c:57 #12 0x0000000000422c58 in radius_handle_request (request=0x2aaab401e9d0, fun=0x407e70 <rad_accounting>) at event.c:3693 #13 0x000000000041c5c6 in request_handler_thread (arg=<value optimized out>) at threads.c:492 #14 0x0000003ad0006367 in start_thread () from /lib64/libpthread.so.0 #15 0x0000003acf4d30ad in clone () from /lib64/libc.so.6 (gdb) list 83 static void sig_fatal (int); 84 #ifdef SIGHUP 85 static void sig_hup (int); 86 #endif 87 88 /* 89 * The main guy. 90 */ 91 int main(int argc, char *argv[]) 92 { (gdb) [root@radius-a ~]# gdb process 21202 GNU gdb Fedora (6.8-27.el5) Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu"... process: No such file or directory. Attaching to process 21202 Reading symbols from /usr/local/sbin/radiusd...done. Reading symbols from /usr/local/lib/libfreeradius-radius-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-radius-2.1.7.so Reading symbols from /lib64/libnsl.so.1...done. Loaded symbols for /lib64/libnsl.so.1 Reading symbols from /lib64/libresolv.so.2...done. Loaded symbols for /lib64/libresolv.so.2 Reading symbols from /lib64/libpthread.so.0...done. [Thread debugging using libthread_db enabled] [New Thread 0x458f5940 (LWP 21202)] Loaded symbols for /lib64/libpthread.so.0 Reading symbols from /lib64/libcrypt.so.1...done. Loaded symbols for /lib64/libcrypt.so.1 Reading symbols from /usr/local/lib/libltdl.so.3...done. Loaded symbols for /usr/local/lib/libltdl.so.3 Reading symbols from /lib64/libssl.so.6...done. Loaded symbols for /lib64/libssl.so.6 Reading symbols from /lib64/libcrypto.so.6...done. Loaded symbols for /lib64/libcrypto.so.6 Reading symbols from /lib64/libc.so.6...done. Loaded symbols for /lib64/libc.so.6 Reading symbols from /lib64/ld-linux-x86-64.so.2...done. Loaded symbols for /lib64/ld-linux-x86-64.so.2 Reading symbols from /lib64/libdl.so.2...done. Loaded symbols for /lib64/libdl.so.2 Reading symbols from /usr/lib64/libgssapi_krb5.so.2...done. Loaded symbols for /usr/lib64/libgssapi_krb5.so.2 Reading symbols from /usr/lib64/libkrb5.so.3...done. Loaded symbols for /usr/lib64/libkrb5.so.3 Reading symbols from /lib64/libcom_err.so.2...done. Loaded symbols for /lib64/libcom_err.so.2 Reading symbols from /usr/lib64/libk5crypto.so.3...done. Loaded symbols for /usr/lib64/libk5crypto.so.3 Reading symbols from /usr/lib64/libz.so.1...done. Loaded symbols for /usr/lib64/libz.so.1 Reading symbols from /usr/lib64/libkrb5support.so.0...done. Loaded symbols for /usr/lib64/libkrb5support.so.0 Reading symbols from /lib64/libkeyutils.so.1...done. Loaded symbols for /lib64/libkeyutils.so.1 Reading symbols from /lib64/libselinux.so.1...done. Loaded symbols for /lib64/libselinux.so.1 Reading symbols from /lib64/libsepol.so.1...done. Loaded symbols for /lib64/libsepol.so.1 Reading symbols from /lib64/libnss_files.so.2...done. Loaded symbols for /lib64/libnss_files.so.2 Reading symbols from /usr/local/lib/rlm_exec-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_exec-2.1.7.so Reading symbols from /usr/local/lib/rlm_expr-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expr-2.1.7.so Reading symbols from /usr/local/lib/rlm_expiration-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_expiration-2.1.7.so Reading symbols from /usr/local/lib/rlm_logintime-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_logintime-2.1.7.so Reading symbols from /usr/local/lib/rlm_pap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_pap-2.1.7.so Reading symbols from /usr/local/lib/rlm_chap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_chap-2.1.7.so Reading symbols from /usr/local/lib/rlm_mschap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_mschap-2.1.7.so Reading symbols from /usr/local/lib/rlm_unix-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_unix-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap-2.1.7.so Reading symbols from /usr/local/lib/libfreeradius-eap-2.1.7.so...done. Loaded symbols for /usr/local/lib/libfreeradius-eap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_md5-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_md5-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_leap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_leap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_gtc-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_gtc-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_tls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_tls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_ttls-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_ttls-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_peap-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_peap-2.1.7.so Reading symbols from /usr/local/lib/rlm_eap_mschapv2-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_eap_mschapv2-2.1.7.so Reading symbols from /usr/local/lib/rlm_realm-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_realm-2.1.7.so Reading symbols from /usr/local/lib/rlm_files-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_files-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql-2.1.7.so Reading symbols from /usr/local/lib/rlm_sql_mysql-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_sql_mysql-2.1.7.so Reading symbols from /usr/lib64/mysql/libmysqlclient_r.so.15...done. Loaded symbols for /usr/lib64/mysql/libmysqlclient_r.so.15 Reading symbols from /lib64/libm.so.6...done. Loaded symbols for /lib64/libm.so.6 Reading symbols from /usr/local/lib/rlm_attr_filter-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_filter-2.1.7.so Reading symbols from /usr/local/lib/rlm_preprocess-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_preprocess-2.1.7.so Reading symbols from /usr/local/lib/rlm_always-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_always-2.1.7.so Reading symbols from /usr/local/lib/rlm_attr_rewrite-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_attr_rewrite-2.1.7.so Reading symbols from /usr/local/lib/rlm_acct_unique-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_acct_unique-2.1.7.so Reading symbols from /usr/local/lib/rlm_detail-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_detail-2.1.7.so Reading symbols from /usr/local/lib/rlm_radutmp-2.1.7.so...done. Loaded symbols for /usr/local/lib/rlm_radutmp-2.1.7.so 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 (gdb) bt #0 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x0000003acf48c75d in _L_lock_1685 () from /lib64/libc.so.6 #2 0x0000003acf48c4a7 in __tz_convert () from /lib64/libc.so.6 #3 0x00002b794fa6e39f in vp_prints_value (out=0x458f36c0 "", outlen=1008, vp=<value optimized out>, delimitst=<value optimized out>) at print.c:267 #4 0x000000000040dbb5 in radius_exec_program (cmd=0x2aaab401df60 "/usr/local/sbin/acctstop.sh", request=0x2aaab400fde0, exec_wait=0, user_msg=0x0, msg_len=254, input_pairs=0x2aaab40271b0, output_pairs=0x0, shell_escape=1) at exec.c:330 #5 0x00002b79500b9141 in exec_xlat (instance=0xe8d5d70, request=0x2aaab400fde0, fmt=0x2aaab401df60 "/usr/local/sbin/acctstop.sh", out=0x458f4110 "", outlen=254, func=<value optimized out>) at rlm_exec.c:138 #6 0x000000000041eb2c in radius_xlat (out=<value optimized out>, outlen=254, fmt=0x2aaab401d508 "%{exec:/usr/local/sbin/acctstop.sh}", request=0x2aaab400fde0, func=0x41dee0 <xlat_copy>) at xlat.c:911 #7 0x000000000041d5a4 in pairxlatmove (req=0x2aaab400fde0, to=0x2aaab4011dd8, from=0x458f43d0) at valuepair.c:587 #8 0x00002b79524f7fc8 in file_common (inst=<value optimized out>, request=0x2aaab400fde0, filename=0x2b79524f8753 "acct_users", ht=<value optimized out>, request_pairs=0x2aaab4019d70, reply_pairs=0x2aaab4011dd8) at rlm_files.c:472 #9 0x00000000004199d1 in modcall (component=2, c=<value optimized out>, request=0x2aaab400fde0) at modcall.c:292 #10 0x0000000000416f9d in indexed_modcall (comp=2, idx=0, request=0x2aaab400fde0) at modules.c:691 #11 0x0000000000407eae in rad_accounting (request=0x2aaab400fde0) at acct.c:57 #12 0x0000000000422c58 in radius_handle_request (request=0x2aaab400fde0, fun=0x407e70 <rad_accounting>) at event.c:3693 #13 0x000000000041c5c6 in request_handler_thread (arg=<value optimized out>) at threads.c:492 #14 0x0000003ad0006367 in start_thread () from /lib64/libpthread.so.0 #15 0x0000003acf4d30ad in clone () from /lib64/libc.so.6 (gdb) list 83 static void sig_fatal (int); 84 #ifdef SIGHUP 85 static void sig_hup (int); 86 #endif 87 88 /* 89 * The main guy. 90 */ 91 int main(int argc, char *argv[]) 92 { (gdb) __________ Information from ESET Smart Security, version of virus signature database 4519 (20091018) __________ The message was checked by ESET Smart Security. http://www.eset.com
I've continued to try an investigate the root cause of this, and the last run behaved slightly differently - the parent process seems to have terminated, and there are more messages in the radius log.
There were four (4) hung processes left over.
I have attached the radius.log file below, as well as gdb sessions for the hung processes showing the results of the gd 'bt' and 'list' commands.
It looks like Alan's initial idea that the hung processes are a result of running the acctstop.sh process are correct. I've tried looking at the code to see if anything 'leapt out' at me, but the logic is quite clever, and dissecting it from the middle is quite a challenge.
I am hoping that the gdb output might prove helpful to someone already familiar with the logic flow.
It seems I can reproduce this issue within 24 hours, so if there is any other information I could gather, please left me know.
Thanks, -craig
radiusd.log
Fri Oct 16 11:15:56 2009 : Info: Exiting normally. Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Attempting to connect to radiusd@localhost:/radius Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server inner-tunnel Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server copy-acct-to-home-server Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server copy-acct-to-radius-c Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server <default> Fri Oct 16 11:16:22 2009 : Info: Ready to process requests. Fri Oct 16 17:29:12 2009 : Error: [sql] stop packet with zero session length. [user 'user35@realm4TL', nas '192.168.1.101'] Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session length. [user 'user22@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session length. [user 'user17@realm1', nas '192.168.1.101'] etc.
/* * If stop but zero session length AND no previous * session found, drop it as in invalid packet * This is to fix CISCO's aaa from filling our * table with bogus crap */ Your NAS is broken. Fix it so it sends proper accounting packets. Ivan Kalik Kalik Informatika ISP
I think you may be 'jumping the gun' a wee bit. The system currently has over 13,000 active sessions. There were some odd accounting packets, but the vast majority were valid. These could be configuration errors or hack attempts (investigating). Questions: 1) Could bad accounting packets cause the radiusd process to EXIT? 2) Could bad accounting packets result in hung child processes (as seen in the gdb output after the radius log file)? Thanks, -craig ----- Original Message ----- From: "Ivan Kalik" <tnt@kalik.net> To: "FreeRadius users mailing list" <freeradius-users@lists.freeradius.org> Sent: Sunday, October 18, 2009 10:56 AM Subject: Re: over 30 radiusd processes - more information
I've continued to try an investigate the root cause of this, and the last run behaved slightly differently - the parent process seems to have terminated, and there are more messages in the radius log.
There were four (4) hung processes left over.
I have attached the radius.log file below, as well as gdb sessions for the hung processes showing the results of the gd 'bt' and 'list' commands.
It looks like Alan's initial idea that the hung processes are a result of running the acctstop.sh process are correct. I've tried looking at the code to see if anything 'leapt out' at me, but the logic is quite clever, and dissecting it from the middle is quite a challenge.
I am hoping that the gdb output might prove helpful to someone already familiar with the logic flow.
It seems I can reproduce this issue within 24 hours, so if there is any other information I could gather, please left me know.
Thanks, -craig
radiusd.log
Fri Oct 16 11:15:56 2009 : Info: Exiting normally. Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Fri Oct 16 11:16:22 2009 : Info: rlm_sql (sql): Attempting to connect to radiusd@localhost:/radius Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Fri Oct 16 11:16:22 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server inner-tunnel Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server copy-acct-to-home-server Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server copy-acct-to-radius-c Fri Oct 16 11:16:22 2009 : Info: Loaded virtual server <default> Fri Oct 16 11:16:22 2009 : Info: Ready to process requests. Fri Oct 16 17:29:12 2009 : Error: [sql] stop packet with zero session length. [user 'user35@realm4TL', nas '192.168.1.101'] Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session length. [user 'user22@realm1', nas '192.168.1.101'] Sat Oct 17 02:00:18 2009 : Error: [sql] stop packet with zero session length. [user 'user17@realm1', nas '192.168.1.101'] etc.
/* * If stop but zero session length AND no previous * session found, drop it as in invalid packet * This is to fix CISCO's aaa from filling our * table with bogus crap */
Your NAS is broken. Fix it so it sends proper accounting packets.
Ivan Kalik Kalik Informatika ISP
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
__________ Information from ESET Smart Security, version of virus signature database 4519 (20091018) __________
The message was checked by ESET Smart Security.
__________ Information from ESET Smart Security, version of virus signature database 4519 (20091018) __________ The message was checked by ESET Smart Security. http://www.eset.com
I think you may be 'jumping the gun' a wee bit.
The system currently has over 13,000 active sessions.
There were some odd accounting packets, but the vast majority were valid. These could be configuration errors or hack attempts (investigating).
Something broke at 2am. Before that you had a single malformed packet but after 2am there were dozens.
Questions:
1) Could bad accounting packets cause the radiusd process to EXIT?
I don't think so, but I can't answer why did that happen.
2) Could bad accounting packets result in hung child processes (as seen in the gdb output after the radius log file)?
You should look into the detail file and see what is wrong with the packets that were stuck (or did the queries fail for some reason), like: WARNING: Unresponsive child for request 165616, in module sql component accounting etc. Ivan Kalik Kalik Informatika ISP
Hi,
1) Could bad accounting packets cause the radiusd process to EXIT? 2) Could bad accounting packets result in hung child processes (as seen in the gdb output after the radius log file)?
I'd say yes. we ensure that bad packets dont hit our accounting servers eg accounting { # call SQL accouting function only if session-time is not zero if (Acct-Session-Time != 0) { sql } else { ok } } alan
Craig Campbell wrote:
I have attached the radius.log file below, as well as gdb sessions for the hung processes showing the results of the gd 'bt' and 'list' commands.
The log is interesting.
Sat Oct 17 02:01:25 2009 : Error: WARNING: Unresponsive child for request 165616, in module sql component accounting
It looks like the SQL module is being blocked somehow. Why?
(gdb) bt #0 0x0000003acf4dee6e in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x0000003acf48c75d in _L_lock_1685 () from /lib64/libc.so.6 #2 0x0000003acf48c4a7 in __tz_convert () from /lib64/libc.so.6 #3 0x00002b794fa6e39f in vp_prints_value (out=0x41ced6c0 "", outlen=1008, vp=<value optimized out>, delimitst=<value optimized out>) at print.c:267
Hmm... OK. It's a pthread lock / fork issue. I think the solution is to print the "env" variables *before* forking. I'll see what I can do. Alan DeKok.
participants (10)
-
Alan Buxey -
Alan DeKok -
Craig Campbell -
Edgard NDOUNA -
Fajar A. Nugraha -
Ivan Kalik -
Marinko Tarlac -
nf-vale -
tede -
Vincenzo Agosti