Error: rlm_eap: Failed to store handler
Hi, im new on the freeradius world but very curious. Sorry but my english is not very good. I have a working Freedius 1.0.5 server since year 2005 and i want to improve it, migrating a Freeradius 2.1.1-6 version, the latest version i have found for my Sles10 Sp2 server. This server its allowed to authenticate users by EAP-PEAP Mschapv2 and EAP-LEAP against Files and Ldap. In the new server moved all users in user's file to mysql server. All users in mysql are stored with Cleartext-Password. When i run server on debug mode for doing tests the server works without problems, and validate's users using both types of EAP and both Authorization types (Ldap and Mysql). But when i run as daemon and i introduce it in production validating about 2000 of users, freeradius 2.1.1-6 crashes in a few minutes and shows this error "Error: rlm_eap: Failed to store handler". I have only one server called default on sites-enabled configured like this. (The accounting is configured in another virtual server and works fine ) - Default Server - listen { ipaddr = * port = 1832 type = auth } authorize { preprocess eap { ok = return } sql ldap } # Authentication authenticate { Auth-Type MS-CHAP { mschap } # Allow EAP authentication. eap } session { sql } # Post-Authentication post-auth { Post-Auth-Type REJECT { attr_filter.access_reject sql } } pre-proxy { } post-proxy { eap } And Eap.conf is configured like this: eap { default_eap_type = peap timer_expire = 60 ignore_unknown_eap_types = yes cisco_accounting_username_bug = no max_sessions = 300 # Cisco LEAP leap { } ## EAP-TLS tls { certdir = ${confdir}/certs cadir = ${confdir}/certs private_key_password = secret private_key_file = ${certdir}/cert-srv.pem certificate_file = ${certdir}/cert-srv.pem CA_file = ${cadir}/cacert.pem dh_file = ${certdir}/dh random_file = ${certdir}/random fragment_size = 1024 include_length = yes cipher_list = "DEFAULT" make_cert_command = "${certdir}/bootstrap" cache { enable = no lifetime = 24 # hours max_entries = 255 } } peap { default_eap_type = mschapv2 copy_request_to_tunnel = yes use_tunneled_reply = yes proxy_tunneled_request_as_eap = no } mschapv2 { } } The debug log shows this. rad_recv: Access-Request packet from host 10.50.31.201 port 1645, id=48, length=120 User-Name = "25" Framed-MTU = 1400 Called-Station-Id = "000d.ed77.db21" Calling-Station-Id = "000b.6b1e.7177" Message-Authenticator = 0xf1247640d8918729e0c58f0f88dc5a8a EAP-Message = 0x02010007013235 NAS-Port-Type = Virtual NAS-Port = 358 NAS-IP-Address = 10.50.31.201 NAS-Identifier = "sar76010001" Mon Jul 27 17:16:25 2009 : Info: +- entering group authorize {...} Mon Jul 27 17:16:25 2009 : Info: ++[preprocess] returns ok Mon Jul 27 17:16:25 2009 : Info: [eap] EAP packet type response id 1 length 7 Mon Jul 27 17:16:25 2009 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Jul 27 17:16:25 2009 : Info: ++[eap] returns updated Mon Jul 27 17:16:25 2009 : Info: [sql] expand: %{User-Name} -> 25 Mon Jul 27 17:16:25 2009 : Info: [sql] sql_set_user escaped user --> '25' Mon Jul 27 17:16:25 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 6 Mon Jul 27 17:16:25 2009 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = '25' ORDER BY id Mon Jul 27 17:16:25 2009 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '25' ORDER BY priority Mon Jul 27 17:16:25 2009 : Debug: rlm_sql (sql): Released sql socket id: 6 Mon Jul 27 17:16:25 2009 : Info: [sql] User 25 not found Mon Jul 27 17:16:25 2009 : Info: ++[sql] returns notfound Mon Jul 27 17:16:25 2009 : Info: [ldap] performing user authorization for 25 Mon Jul 27 17:16:25 2009 : Info: [ldap] WARNING: Deprecated conditional expansion ":-". See "man unlang" for details Mon Jul 27 17:16:25 2009 : Info: [ldap] expand: (uid=%{Stripped-User-Name:-%{User-Name}}) -> (uid=25) Mon Jul 27 17:16:25 2009 : Info: [ldap] expand: o=eroskiusers -> o=eroskiusers Mon Jul 27 17:16:25 2009 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Mon Jul 27 17:16:25 2009 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Mon Jul 27 17:16:25 2009 : Debug: rlm_ldap: performing search in o=eroskiusers, with filter (uid=25) Mon Jul 27 17:16:25 2009 : Debug: rlm_ldap: object not found or got ambiguous search result Mon Jul 27 17:16:25 2009 : Info: [ldap] search failed Mon Jul 27 17:16:25 2009 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Mon Jul 27 17:16:25 2009 : Info: ++[ldap] returns notfound Mon Jul 27 17:16:25 2009 : Info: Found Auth-Type = EAP Mon Jul 27 17:16:25 2009 : Info: +- entering group authenticate {...} Mon Jul 27 17:16:25 2009 : Info: [eap] EAP Identity Mon Jul 27 17:16:25 2009 : Info: [eap] processing type tls Mon Jul 27 17:16:25 2009 : Info: [tls] Initiate Mon Jul 27 17:16:25 2009 : Info: [tls] Start returned 1 Mon Jul 27 17:16:25 2009 : Error: rlm_eap: Failed to store handler Mon Jul 27 17:16:25 2009 : Info: ++[eap] returns fail Mon Jul 27 17:16:25 2009 : Info: Failed to authenticate the user. Mon Jul 27 17:16:25 2009 : Auth: Login incorrect (rlm_ldap: User not found): [25/<via Auth-Type = EAP>] (from client wifiap_arenal port 358 cli 000b.6b1e.7177) Mon Jul 27 17:16:25 2009 : Info: Using Post-Auth-Type Reject Mon Jul 27 17:16:25 2009 : Info: +- entering group REJECT {...} Mon Jul 27 17:16:25 2009 : Info: [attr_filter.access_reject] expand: %{User-Name} -> 25 Mon Jul 27 17:16:25 2009 : Debug: attr_filter: Matched entry DEFAULT at line 11 Mon Jul 27 17:16:25 2009 : Info: ++[attr_filter.access_reject] returns updated Mon Jul 27 17:16:25 2009 : Info: [sql] expand: %{User-Name} -> 25 Mon Jul 27 17:16:25 2009 : Info: [sql] sql_set_user escaped user --> '25' Mon Jul 27 17:16:25 2009 : Info: [sql] expand: %{User-Password} -> Mon Jul 27 17:16:25 2009 : Info: [sql] expand: %{Chap-Password} -> Mon Jul 27 17:16:25 2009 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '25', '', 'Access-Reject', '2009-07-27 17:16:25') Mon Jul 27 17:16:25 2009 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '25', '', 'Access-Reject', '2009-07-27 17:16:25') Mon Jul 27 17:16:25 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 5 Mon Jul 27 17:16:25 2009 : Debug: rlm_sql (sql): Released sql socket id: 5 Mon Jul 27 17:16:25 2009 : Info: ++[sql] returns ok Mon Jul 27 17:16:25 2009 : Info: Delaying reject of request 1045 for 1 seconds Mon Jul 27 17:16:25 2009 : Debug: Going to the next request Mon Jul 27 17:16:25 2009 : Info: Cleaning up request 994 ID 190 with timestamp +39 Mon Jul 27 17:16:25 2009 : Info: Sending delayed reject for request 1040 I looked to machine resources and CPU is 90% idle and has 1Gb of free ram when crashes so i dont think that could be a memory or cpu load problem. Anyone can help me, what im a doing wrong?. The configuration is very similar to the freeradius 1.0.5 server that works well. Thanks for all.
freeradius 2.1.1-6 crashes in a few minutes and shows this error "Error: rlm_eap: Failed to store handler".
There is documentation that describes what to do if FreeRadius crashes. Look in the file doc/bugs in the distribution and it gives specific instructions for using gdb to produce information about the crash. Also, is "2.1.1-6" really the version printed by the "radiusd -v" command?
Sorry but maybe i have not explained my problem very well, freeradius doesn't falls down, when i say that crashes i mean that doesn't validate more users, i get some login incorrect that should be correct if the server will work fine. Server sitel receive some acess-request and process them but send access-rejects instead of acces-accept because of this error. Some access requests are well pocessed. I wil take a look to the doc you tell me. Yes, the version of Freeradius i installed is 2.1.1-6 and the log is shown when i make radiusd -XXX I have installed from the rpm os this page http://download.opensuse.org/repositories/network:/aaa/SLE_10_SP2/i586/ Thanks! 2009/7/27 Garber, Neal <Neal.Garber@energyeast.com
freeradius 2.1.1-6 crashes in a few minutes and shows this error "Error: rlm_eap: Failed to store handler".
There is documentation that describes what to do if FreeRadius crashes. Look in the file doc/bugs in the distribution and it gives specific instructions for using gdb to produce information about the crash. Also, is "2.1.1-6" really the version printed by the "radiusd -v" command?
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Rokkhan wrote:
I have a working Freedius 1.0.5 server since year 2005 and i want to improve it, migrating a Freeradius 2.1.1-6 version, the latest version i have found for my Sles10 Sp2 server.
See the freeradius.org web page. It has RPMs of the newer versions for suse.
When i run server on debug mode for doing tests the server works without problems, and validate's users using both types of EAP and both Authorization types (Ldap and Mysql). But when i run as daemon and i introduce it in production validating about 2000 of users, freeradius 2.1.1-6 crashes in a few minutes and shows this error "Error: rlm_eap: Failed to store handler".
That's a bad error. I haven't seen it in a while, so I would suggest upgrading to 2.1.6. Alan DeKok.
Ok, I'll try to update 2.1.6. I have not found newer rpm packages than i installed in my server on freeradius.org, because when I go to the download section and I select Binary packages for Suse, it sends me to the page where i took from packages the first time (http://download.opensuse.org/repositories/network:/aaa/) and there is no newer version than 2.1.1-6 But i will ask some help from my friends and I'll try to install from the tar.gz. By the way, now sometimes i get this error (Error: rlm_eap: No EAP session matching the State variable) from the server that maybe could be related. rad_recv: Access-Request packet from host 193.4.42.201 port 1645, id=241, length=403 User-Name = "36005405865132200096315165226168360027502200066623658TDP00290005" Framed-MTU = 1400 Called-Station-Id = "001e.7aa8.e7a0" Calling-Station-Id = "000b.6b1f.5ac4" Service-Type = Login-User Message-Authenticator = 0x0f1edc0510387abdb71af318e243543b EAP-Message = 0x020500cc1900160301008610000082008043d5b97a98332e4f8370833ee0b6e9e528c305d999e378ab3ec157582089354df3f49c859da9b21592bf7861fa0c9976e33f25265f6fd4616e06450da6462a4ca59d5e2f225f0b7fffa5302d6c5cc1a1b389745992b881e4a4eb8e468c9750a532f108984aabac56b5148a669cc5d6c4fde9d80b909dc96438b651c55d71e0ef14030100010116030100300df0a239eafc874ff2eaaba0be58c0e9f9e9bcf69fbce7673e4104fb16e476279efc864fdbde012e197579c033e2ccf5 NAS-Port-Type = Wireless-802.11 NAS-Port = 55874 State = 0xa65781dda5529866f068234f09c4ea04 NAS-IP-Address = 193.4.42.201 NAS-Identifier = "sar00290001" Tue Jul 28 12:54:26 2009 : Info: +- entering group authorize {...} Tue Jul 28 12:54:26 2009 : Info: ++[preprocess] returns ok Tue Jul 28 12:54:26 2009 : Info: [eap] EAP packet type response id 5 length 204 Tue Jul 28 12:54:26 2009 : Info: [eap] Continuing tunnel setup. Tue Jul 28 12:54:26 2009 : Info: ++[eap] returns ok Tue Jul 28 12:54:26 2009 : Info: Found Auth-Type = EAP Tue Jul 28 12:54:26 2009 : Info: +- entering group authenticate {...} Tue Jul 28 12:54:26 2009 : Error: rlm_eap: No EAP session matching the State variable. Tue Jul 28 12:54:26 2009 : Info: [eap] Either EAP-request timed out OR EAP-response to an unknown EAP-request Tue Jul 28 12:54:26 2009 : Info: [eap] Failed in handler Tue Jul 28 12:54:26 2009 : Info: ++[eap] returns invalid Tue Jul 28 12:54:26 2009 : Info: Failed to authenticate the user. Tue Jul 28 12:54:26 2009 : Auth: Login incorrect: [36005405865132200096315165226168360027502200066623658TDP00290005/<via Auth-Type = EAP>] (from client wifiap_sanjuan port 55874 cli 000b.6b1f.5ac4) Tue Jul 28 12:54:26 2009 : Info: Using Post-Auth-Type Reject Tue Jul 28 12:54:26 2009 : Info: +- entering group REJECT {...} Tue Jul 28 12:54:26 2009 : Info: [attr_filter.access_reject] expand: %{User-Name} -> 36005405865132200096315165226168360027502200066623658TDP00290005 Tue Jul 28 12:54:26 2009 : Debug: attr_filter: Matched entry DEFAULT at line 11 Tue Jul 28 12:54:26 2009 : Info: ++[attr_filter.access_reject] returns updated Tue Jul 28 12:54:26 2009 : Info: [sql] expand: %{User-Name} -> 36005405865132200096315165226168360027502200066623658TDP00290005 Tue Jul 28 12:54:26 2009 : Info: [sql] sql_set_user escaped user --> '36005405865132200096315165226168360027502200066623658TDP00290005' Tue Jul 28 12:54:26 2009 : Info: [sql] expand: %{User-Password} -> Tue Jul 28 12:54:26 2009 : Info: [sql] expand: %{Chap-Password} -> Tue Jul 28 12:54:26 2009 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '36005405865132200096315165226168360027502200066623658TDP00290005', '', 'Access-Reject', '2009-07-28 12:54:26') Tue Jul 28 12:54:26 2009 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '36005405865132200096315165226168360027502200066623658TDP00290005', '', 'Access-Reject', '2009-07-28 12:54:26') Tue Jul 28 12:54:26 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 11 Tue Jul 28 12:54:26 2009 : Debug: rlm_sql (sql): Released sql socket id: 11 Tue Jul 28 12:54:26 2009 : Info: ++[sql] returns ok Tue Jul 28 12:54:26 2009 : Info: Delaying reject of request 2 for 1 seconds Tue Jul 28 12:54:26 2009 : Debug: Going to the next request Tue Jul 28 12:54:26 2009 : Debug: Waking up in 0.9 seconds. 2009/7/28 Alan DeKok <aland@deployingradius.com>:
Rokkhan wrote:
I have a working Freedius 1.0.5 server since year 2005 and i want to improve it, migrating a Freeradius 2.1.1-6 version, the latest version i have found for my Sles10 Sp2 server.
See the freeradius.org web page. It has RPMs of the newer versions for suse.
When i run server on debug mode for doing tests the server works without problems, and validate's users using both types of EAP and both Authorization types (Ldap and Mysql). But when i run as daemon and i introduce it in production validating about 2000 of users, freeradius 2.1.1-6 crashes in a few minutes and shows this error "Error: rlm_eap: Failed to store handler".
That's a bad error. I haven't seen it in a while, so I would suggest upgrading to 2.1.6.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Thanks for all, I installed freeradius 2.1.6 and it seems that eap works correctly, Thanks! 2009/7/28 Rokkhan <rokkhan@gmail.com>:
Ok, I'll try to update 2.1.6. I have not found newer rpm packages than i installed in my server on freeradius.org, because when I go to the download section and I select Binary packages for Suse, it sends me to the page where i took from packages the first time (http://download.opensuse.org/repositories/network:/aaa/) and there is no newer version than 2.1.1-6 But i will ask some help from my friends and I'll try to install from the tar.gz.
By the way, now sometimes i get this error (Error: rlm_eap: No EAP session matching the State variable) from the server that maybe could be related.
rad_recv: Access-Request packet from host 193.4.42.201 port 1645, id=241, length=403 User-Name = "36005405865132200096315165226168360027502200066623658TDP00290005" Framed-MTU = 1400 Called-Station-Id = "001e.7aa8.e7a0" Calling-Station-Id = "000b.6b1f.5ac4" Service-Type = Login-User Message-Authenticator = 0x0f1edc0510387abdb71af318e243543b EAP-Message = 0x020500cc1900160301008610000082008043d5b97a98332e4f8370833ee0b6e9e528c305d999e378ab3ec157582089354df3f49c859da9b21592bf7861fa0c9976e33f25265f6fd4616e06450da6462a4ca59d5e2f225f0b7fffa5302d6c5cc1a1b389745992b881e4a4eb8e468c9750a532f108984aabac56b5148a669cc5d6c4fde9d80b909dc96438b651c55d71e0ef14030100010116030100300df0a239eafc874ff2eaaba0be58c0e9f9e9bcf69fbce7673e4104fb16e476279efc864fdbde012e197579c033e2ccf5 NAS-Port-Type = Wireless-802.11 NAS-Port = 55874 State = 0xa65781dda5529866f068234f09c4ea04 NAS-IP-Address = 193.4.42.201 NAS-Identifier = "sar00290001" Tue Jul 28 12:54:26 2009 : Info: +- entering group authorize {...} Tue Jul 28 12:54:26 2009 : Info: ++[preprocess] returns ok Tue Jul 28 12:54:26 2009 : Info: [eap] EAP packet type response id 5 length 204 Tue Jul 28 12:54:26 2009 : Info: [eap] Continuing tunnel setup. Tue Jul 28 12:54:26 2009 : Info: ++[eap] returns ok Tue Jul 28 12:54:26 2009 : Info: Found Auth-Type = EAP Tue Jul 28 12:54:26 2009 : Info: +- entering group authenticate {...} Tue Jul 28 12:54:26 2009 : Error: rlm_eap: No EAP session matching the State variable. Tue Jul 28 12:54:26 2009 : Info: [eap] Either EAP-request timed out OR EAP-response to an unknown EAP-request Tue Jul 28 12:54:26 2009 : Info: [eap] Failed in handler Tue Jul 28 12:54:26 2009 : Info: ++[eap] returns invalid Tue Jul 28 12:54:26 2009 : Info: Failed to authenticate the user. Tue Jul 28 12:54:26 2009 : Auth: Login incorrect: [36005405865132200096315165226168360027502200066623658TDP00290005/<via Auth-Type = EAP>] (from client wifiap_sanjuan port 55874 cli 000b.6b1f.5ac4) Tue Jul 28 12:54:26 2009 : Info: Using Post-Auth-Type Reject Tue Jul 28 12:54:26 2009 : Info: +- entering group REJECT {...} Tue Jul 28 12:54:26 2009 : Info: [attr_filter.access_reject] expand: %{User-Name} -> 36005405865132200096315165226168360027502200066623658TDP00290005 Tue Jul 28 12:54:26 2009 : Debug: attr_filter: Matched entry DEFAULT at line 11 Tue Jul 28 12:54:26 2009 : Info: ++[attr_filter.access_reject] returns updated Tue Jul 28 12:54:26 2009 : Info: [sql] expand: %{User-Name} -> 36005405865132200096315165226168360027502200066623658TDP00290005 Tue Jul 28 12:54:26 2009 : Info: [sql] sql_set_user escaped user --> '36005405865132200096315165226168360027502200066623658TDP00290005' Tue Jul 28 12:54:26 2009 : Info: [sql] expand: %{User-Password} -> Tue Jul 28 12:54:26 2009 : Info: [sql] expand: %{Chap-Password} -> Tue Jul 28 12:54:26 2009 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '36005405865132200096315165226168360027502200066623658TDP00290005', '', 'Access-Reject', '2009-07-28 12:54:26') Tue Jul 28 12:54:26 2009 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '36005405865132200096315165226168360027502200066623658TDP00290005', '', 'Access-Reject', '2009-07-28 12:54:26') Tue Jul 28 12:54:26 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 11 Tue Jul 28 12:54:26 2009 : Debug: rlm_sql (sql): Released sql socket id: 11 Tue Jul 28 12:54:26 2009 : Info: ++[sql] returns ok Tue Jul 28 12:54:26 2009 : Info: Delaying reject of request 2 for 1 seconds Tue Jul 28 12:54:26 2009 : Debug: Going to the next request Tue Jul 28 12:54:26 2009 : Debug: Waking up in 0.9 seconds.
2009/7/28 Alan DeKok <aland@deployingradius.com>:
Rokkhan wrote:
I have a working Freedius 1.0.5 server since year 2005 and i want to improve it, migrating a Freeradius 2.1.1-6 version, the latest version i have found for my Sles10 Sp2 server.
See the freeradius.org web page. It has RPMs of the newer versions for suse.
When i run server on debug mode for doing tests the server works without problems, and validate's users using both types of EAP and both Authorization types (Ldap and Mysql). But when i run as daemon and i introduce it in production validating about 2000 of users, freeradius 2.1.1-6 crashes in a few minutes and shows this error "Error: rlm_eap: Failed to store handler".
That's a bad error. I haven't seen it in a while, so I would suggest upgrading to 2.1.6.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (3)
-
Alan DeKok -
Garber, Neal -
Rokkhan