Error: rlm_eap: Failed to store handler
Rokkhan
rokkhan at gmail.com
Mon Jul 27 21:52:22 CEST 2009
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.
More information about the Freeradius-Users
mailing list