Problem with 2.1.10 hanging
David Mitchell
mitchell at ucar.edu
Thu Aug 26 15:56:21 CEST 2010
My 2.1.10 server I got compiled has a problem where it hangs after a few
hours. I'm not sure if it's related to the number of requests it's
processed or not. It's happened three times so far. Restarting the
server always gets it working again. Using tcpdump I can confirm that
it's receiving requests from the NAS but not processing them. Using
strace I can see that it's stuck on a futex:
write(1, "Wed Aug 25 16:13:45 2010 : Info: "..., 70) = 70
futex(0x827fe88, FUTEX_WAIT_PRIVATE, 2, NULL
The server is doing nothing more than EAP-TLS authentication for some
wireless AP's. Debug from the config loading and the last few packets
are below.
Alan, let me know if you'd rather have this type of thread on the
Developer list instead of the User list. Thanks,
-David Mitchell
Wed Aug 25 14:29:47 2010 : Info: FreeRADIUS Version 2.1.10, for host
i686-pc-linux-gnu, built on Aug 25 2010 at 07:46:58
Wed Aug 25 14:29:47 2010 : Info: Copyright (C) 1999-2009 The FreeRADIUS
server project and contributors.
Wed Aug 25 14:29:47 2010 : Info: There is NO warranty; not even for
MERCHANTABILITY or FITNESS FOR A
Wed Aug 25 14:29:47 2010 : Info: PARTICULAR PURPOSE.
Wed Aug 25 14:29:47 2010 : Info: You may redistribute copies of
FreeRADIUS under the terms of the
Wed Aug 25 14:29:47 2010 : Info: GNU General Public License v2.
Wed Aug 25 14:29:47 2010 : Info: Starting - reading configuration files ...
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/radiusd.conf
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/proxy.conf
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/clients.conf
Wed Aug 25 14:29:47 2010 : Debug: including files in directory
/usr/local/etc/raddb/modules/
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/cui
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/exec
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/mac2ip
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/pam
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/unix
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/logintime
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/etc_group
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/inner-eap
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/ippool
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/sqlcounter_expire_on_login
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/expr
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/wimax
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/echo
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/linelog
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/always
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/preprocess
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/expiration
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/pap
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/attr_filter
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/checkval
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/chap
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/smsotp
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail.example.com
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/otp
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/passwd
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/attr_rewrite
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/ntlm_auth
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/perl
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/smbpasswd
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/acct_unique
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/ldap
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/sql_log
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/mschap
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/digest
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/krb5
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/files
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/sradutmp
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/detail.log
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/mac2vlan
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/radutmp
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/realm
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/counter
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/modules/policy
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/eap.conf
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/policy.conf
Wed Aug 25 14:29:47 2010 : Debug: including files in directory
/usr/local/etc/raddb/sites-enabled/
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
Wed Aug 25 14:29:47 2010 : Debug: including configuration file
/usr/local/etc/raddb/sites-enabled/default
Wed Aug 25 14:29:47 2010 : Debug: main {
Wed Aug 25 14:29:47 2010 : Debug: allow_core_dumps = no
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: including dictionary file
/usr/local/etc/raddb/dictionary
Wed Aug 25 14:29:47 2010 : Debug: main {
Wed Aug 25 14:29:47 2010 : Debug: prefix = "/usr/local"
Wed Aug 25 14:29:47 2010 : Debug: localstatedir = "/usr/local/var"
Wed Aug 25 14:29:47 2010 : Debug: logdir = "/usr/local/var/log/radius"
Wed Aug 25 14:29:47 2010 : Debug: libdir = "/usr/local/lib"
Wed Aug 25 14:29:47 2010 : Debug: radacctdir =
"/usr/local/var/log/radius/radacct"
Wed Aug 25 14:29:47 2010 : Debug: hostname_lookups = no
Wed Aug 25 14:29:47 2010 : Debug: max_request_time = 30
Wed Aug 25 14:29:47 2010 : Debug: cleanup_delay = 5
Wed Aug 25 14:29:47 2010 : Debug: max_requests = 1024
Wed Aug 25 14:29:47 2010 : Debug: pidfile =
"/usr/local/var/run/radiusd/radiusd.pid"
Wed Aug 25 14:29:47 2010 : Debug: checkrad = "/usr/local/sbin/checkrad"
Wed Aug 25 14:29:47 2010 : Debug: debug_level = 0
Wed Aug 25 14:29:47 2010 : Debug: proxy_requests = yes
Wed Aug 25 14:29:47 2010 : Debug: log {
Wed Aug 25 14:29:47 2010 : Debug: stripped_names = no
Wed Aug 25 14:29:47 2010 : Debug: auth = no
Wed Aug 25 14:29:47 2010 : Debug: auth_badpass = no
Wed Aug 25 14:29:47 2010 : Debug: auth_goodpass = no
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: security {
Wed Aug 25 14:29:47 2010 : Debug: max_attributes = 200
Wed Aug 25 14:29:47 2010 : Debug: reject_delay = 1
Wed Aug 25 14:29:47 2010 : Debug: status_server = yes
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: radiusd: #### Loading Realms and Home
Servers ####
Wed Aug 25 14:29:47 2010 : Debug: proxy server {
Wed Aug 25 14:29:47 2010 : Debug: retry_delay = 5
Wed Aug 25 14:29:47 2010 : Debug: retry_count = 3
Wed Aug 25 14:29:47 2010 : Debug: default_fallback = no
Wed Aug 25 14:29:47 2010 : Debug: dead_time = 120
Wed Aug 25 14:29:47 2010 : Debug: wake_all_if_all_dead = no
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: home_server localhost {
Wed Aug 25 14:29:47 2010 : Debug: ipaddr = 127.0.0.1
Wed Aug 25 14:29:47 2010 : Debug: port = 1812
Wed Aug 25 14:29:47 2010 : Debug: type = "auth"
Wed Aug 25 14:29:47 2010 : Debug: secret = "testing123"
Wed Aug 25 14:29:47 2010 : Debug: response_window = 20
Wed Aug 25 14:29:47 2010 : Debug: max_outstanding = 65536
Wed Aug 25 14:29:47 2010 : Debug: require_message_authenticator = no
Wed Aug 25 14:29:47 2010 : Debug: zombie_period = 40
Wed Aug 25 14:29:47 2010 : Debug: status_check = "status-server"
Wed Aug 25 14:29:47 2010 : Debug: ping_interval = 30
Wed Aug 25 14:29:47 2010 : Debug: check_interval = 30
Wed Aug 25 14:29:47 2010 : Debug: num_answers_to_alive = 3
Wed Aug 25 14:29:47 2010 : Debug: num_pings_to_alive = 3
Wed Aug 25 14:29:47 2010 : Debug: revive_interval = 120
Wed Aug 25 14:29:47 2010 : Debug: status_check_timeout = 4
Wed Aug 25 14:29:47 2010 : Debug: irt = 2
Wed Aug 25 14:29:47 2010 : Debug: mrt = 16
Wed Aug 25 14:29:47 2010 : Debug: mrc = 5
Wed Aug 25 14:29:47 2010 : Debug: mrd = 30
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: home_server_pool my_auth_failover {
Wed Aug 25 14:29:47 2010 : Debug: type = fail-over
Wed Aug 25 14:29:47 2010 : Debug: home_server = localhost
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: realm example.com {
Wed Aug 25 14:29:47 2010 : Debug: auth_pool = my_auth_failover
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: realm LOCAL {
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: realm ~.+$ {
Wed Aug 25 14:29:47 2010 : Debug: authhost = LOCAL
Wed Aug 25 14:29:47 2010 : Debug: accthost = LOCAL
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: radiusd: #### Loading Clients ####
Wed Aug 25 14:29:47 2010 : Debug: client localhost {
Wed Aug 25 14:29:47 2010 : Debug: ipaddr = 127.0.0.1
Wed Aug 25 14:29:47 2010 : Debug: require_message_authenticator = no
Wed Aug 25 14:29:47 2010 : Debug: secret = "testing123"
Wed Aug 25 14:29:47 2010 : Debug: nastype = "other"
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: client 10.201.0.0/16 {
Wed Aug 25 14:29:47 2010 : Debug: require_message_authenticator = no
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: radiusd: #### Instantiating modules ####
Wed Aug 25 14:29:47 2010 : Debug: instantiate {
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_expr, checking if it's
valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_expr
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module "expr"
from file /usr/local/etc/raddb/modules/expr
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: radiusd: #### Loading Virtual Servers ####
Wed Aug 25 14:29:47 2010 : Debug: server inner-tunnel { # from file
/usr/local/etc/raddb/sites-enabled/inner-tunnel
Wed Aug 25 14:29:47 2010 : Debug: modules {
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking authenticate {...}
for more modules to load
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_eap, checking if it's
valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_eap
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module "eap"
from file /usr/local/etc/raddb/eap.conf
Wed Aug 25 14:29:47 2010 : Debug: eap {
Wed Aug 25 14:29:47 2010 : Debug: default_eap_type = "tls"
Wed Aug 25 14:29:47 2010 : Debug: timer_expire = 60
Wed Aug 25 14:29:47 2010 : Debug: ignore_unknown_eap_types = no
Wed Aug 25 14:29:47 2010 : Debug: cisco_accounting_username_bug = no
Wed Aug 25 14:29:47 2010 : Debug: max_sessions = 4096
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to sub-module rlm_eap_tls
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating eap-tls
Wed Aug 25 14:29:47 2010 : Debug: tls {
Wed Aug 25 14:29:47 2010 : Debug: rsa_key_exchange = no
Wed Aug 25 14:29:47 2010 : Debug: dh_key_exchange = yes
Wed Aug 25 14:29:47 2010 : Debug: rsa_key_length = 512
Wed Aug 25 14:29:47 2010 : Debug: dh_key_length = 512
Wed Aug 25 14:29:47 2010 : Debug: verify_depth = 3
Wed Aug 25 14:29:47 2010 : Debug: CA_path = "/usr/local/etc/raddb/netsca/"
Wed Aug 25 14:29:47 2010 : Debug: pem_file_type = yes
Wed Aug 25 14:29:47 2010 : Debug: private_key_file =
"/usr/local/etc/raddb/real_certs/freessl.key"
Wed Aug 25 14:29:47 2010 : Debug: certificate_file =
"/usr/local/etc/raddb/real_certs/freessl.crt"
Wed Aug 25 14:29:47 2010 : Debug: CA_file =
"/usr/local/etc/raddb/netsca/cacert.pem"
Wed Aug 25 14:29:47 2010 : Debug: dh_file = "/usr/local/etc/raddb/certs/dh"
Wed Aug 25 14:29:47 2010 : Debug: random_file =
"/usr/local/etc/raddb/certs/random"
Wed Aug 25 14:29:47 2010 : Debug: fragment_size = 1024
Wed Aug 25 14:29:47 2010 : Debug: include_length = yes
Wed Aug 25 14:29:47 2010 : Debug: check_crl = no
Wed Aug 25 14:29:47 2010 : Debug: check_cert_cn =
"%{%{Stripped-User-Name}:-%{User-Name}}@%{Calling-Station-Id}"
Wed Aug 25 14:29:47 2010 : Debug: cipher_list = "DEFAULT"
Wed Aug 25 14:29:47 2010 : Debug: cache {
Wed Aug 25 14:29:47 2010 : Debug: enable = yes
Wed Aug 25 14:29:47 2010 : Debug: lifetime = 24
Wed Aug 25 14:29:47 2010 : Debug: max_entries = 255
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking authorize {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_realm, checking if
it's valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_realm
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module "suffix"
from file /usr/local/etc/raddb/modules/realm
Wed Aug 25 14:29:47 2010 : Debug: realm suffix {
Wed Aug 25 14:29:47 2010 : Debug: format = "suffix"
Wed Aug 25 14:29:47 2010 : Debug: delimiter = "@"
Wed Aug 25 14:29:47 2010 : Debug: ignore_default = no
Wed Aug 25 14:29:47 2010 : Debug: ignore_null = no
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_files, checking if
it's valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_files
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module "files"
from file /usr/local/etc/raddb/modules/files
Wed Aug 25 14:29:47 2010 : Debug: files {
Wed Aug 25 14:29:47 2010 : Debug: usersfile = "/usr/local/etc/raddb/users"
Wed Aug 25 14:29:47 2010 : Debug: acctusersfile =
"/usr/local/etc/raddb/acct_users"
Wed Aug 25 14:29:47 2010 : Debug: preproxy_usersfile =
"/usr/local/etc/raddb/preproxy_users"
Wed Aug 25 14:29:47 2010 : Debug: compat = "no"
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking post-proxy {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking post-auth {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_attr_filter, checking
if it's valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_attr_filter
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module
"attr_filter.access_reject" from file /usr/local/etc/raddb/modules/attr_f
ilter
Wed Aug 25 14:29:47 2010 : Debug: attr_filter attr_filter.access_reject {
Wed Aug 25 14:29:47 2010 : Debug: attrsfile =
"/usr/local/etc/raddb/attrs.access_reject"
Wed Aug 25 14:29:47 2010 : Debug: key = "%{User-Name}"
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: } # modules
Wed Aug 25 14:29:47 2010 : Debug: } # server
Wed Aug 25 14:29:47 2010 : Debug: server { # from file
/usr/local/etc/raddb/radiusd.conf
Wed Aug 25 14:29:47 2010 : Debug: modules {
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking authenticate {...}
for more modules to load
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking authorize {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_preprocess, checking
if it's valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_preprocess
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module
"preprocess" from file /usr/local/etc/raddb/modules/preprocess
Wed Aug 25 14:29:47 2010 : Debug: preprocess {
Wed Aug 25 14:29:47 2010 : Debug: huntgroups =
"/usr/local/etc/raddb/huntgroups"
Wed Aug 25 14:29:47 2010 : Debug: hints = "/usr/local/etc/raddb/hints"
Wed Aug 25 14:29:47 2010 : Debug: with_ascend_hack = no
Wed Aug 25 14:29:47 2010 : Debug: ascend_channels_per_line = 23
Wed Aug 25 14:29:47 2010 : Debug: with_ntdomain_hack = no
Wed Aug 25 14:29:47 2010 : Debug: with_specialix_jetstream_hack = no
Wed Aug 25 14:29:47 2010 : Debug: with_cisco_vsa_hack = no
Wed Aug 25 14:29:47 2010 : Debug: with_alvarion_vsa_hack = no
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking preacct {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_acct_unique, checking
if it's valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_acct_unique
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module
"acct_unique" from file /usr/local/etc/raddb/modules/acct_unique
Wed Aug 25 14:29:47 2010 : Debug: acct_unique {
Wed Aug 25 14:29:47 2010 : Debug: key = "User-Name, Acct-Session-Id,
NAS-IP-Address, Client-IP-Address, NAS-Port"
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking accounting {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_detail, checking if
it's valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_detail
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module "detail"
from file /usr/local/etc/raddb/modules/detail
Wed Aug 25 14:29:47 2010 : Debug: detail {
Wed Aug 25 14:29:47 2010 : Debug: detailfile =
"/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Wed Aug 25 14:29:47 2010 : Debug: header = "%t"
Wed Aug 25 14:29:47 2010 : Debug: detailperm = 384
Wed Aug 25 14:29:47 2010 : Debug: dirperm = 493
Wed Aug 25 14:29:47 2010 : Debug: locking = no
Wed Aug 25 14:29:47 2010 : Debug: log_packet_header = no
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: (Loaded rlm_linelog, checking if
it's valid)
Wed Aug 25 14:29:47 2010 : Debug: Module: Linked to module rlm_linelog
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module
"linelog" from file /usr/local/etc/raddb/modules/linelog
Wed Aug 25 14:29:47 2010 : Debug: linelog {
Wed Aug 25 14:29:47 2010 : Debug: filename = "syslog"
Wed Aug 25 14:29:47 2010 : Debug: format = "This is a log message for
%{User-Name}"
Wed Aug 25 14:29:47 2010 : Debug: reference =
"Accounting-Request.%{%{Acct-Status-Type}:-unknown}"
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Module: Instantiating module
"attr_filter.accounting_response" from file /usr/local/etc/raddb/modules/
attr_filter
Wed Aug 25 14:29:47 2010 : Debug: attr_filter
attr_filter.accounting_response {
Wed Aug 25 14:29:47 2010 : Debug: attrsfile =
"/usr/local/etc/raddb/attrs.accounting_response"
Wed Aug 25 14:29:47 2010 : Debug: key = "%{User-Name}"
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking post-proxy {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: Module: Checking post-auth {...} for
more modules to load
Wed Aug 25 14:29:47 2010 : Debug: } # modules
Wed Aug 25 14:29:47 2010 : Debug: } # server
Wed Aug 25 14:29:47 2010 : Debug: radiusd: #### Opening IP addresses and
Ports ####
Wed Aug 25 14:29:47 2010 : Debug: listen {
Wed Aug 25 14:29:47 2010 : Debug: type = "auth"
Wed Aug 25 14:29:47 2010 : Debug: ipaddr = *
Wed Aug 25 14:29:47 2010 : Debug: port = 0
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: listen {
Wed Aug 25 14:29:47 2010 : Debug: type = "acct"
Wed Aug 25 14:29:47 2010 : Debug: ipaddr = *
Wed Aug 25 14:29:47 2010 : Debug: port = 0
Wed Aug 25 14:29:47 2010 : Debug: }
Wed Aug 25 14:29:47 2010 : Debug: Listening on authentication address *
port 1812
Wed Aug 25 14:29:47 2010 : Debug: Listening on accounting address * port
1813
Wed Aug 25 14:29:47 2010 : Debug: Listening on proxy address * port 1814
Wed Aug 25 14:29:47 2010 : Info: Ready to process requests.
[snipped out the requests which worked fine over the next two hours]
Wed Aug 25 16:09:35 2010 : Info: Cleaning up request 160 ID 30 with
timestamp +5988
Wed Aug 25 16:09:35 2010 : Debug: Going to the next request
Wed Aug 25 16:09:35 2010 : Info: Ready to process requests.
rad_recv: Accounting-Request packet from host 10.201.3.20 port 1646,
id=99, length=350
Acct-Session-Id = "0000090E"
Called-Station-Id = "0019.2fad.e842"
Calling-Station-Id = "6033.4bec.2fcf"
Cisco-AVPair = "ssid=UCAR_Testing"
Cisco-AVPair = "vlan-id=56"
Cisco-AVPair = "nas-location=FL2-1025-W1-3B"
WISPr-Location-Name = "FL2-1025-W1-3B"
Cisco-AVPair = "auth-algo-type=eap-tls"
User-Name = "dr"
Acct-Authentic = RADIUS
Cisco-AVPair = "connect-progress=Call Up"
Acct-Session-Time = 5921
Acct-Input-Octets = 156430
Acct-Output-Octets = 249244
Acct-Input-Packets = 2026
Acct-Output-Packets = 531
Acct-Terminate-Cause = Lost-Carrier
Cisco-AVPair = "disc-cause-ext=No Reason"
Acct-Status-Type = Stop
NAS-Port-Type = Wireless-802.11
Cisco-NAS-Port = "2525"
NAS-Port = 2525
Service-Type = Framed-User
NAS-IP-Address = 10.201.3.20
Acct-Delay-Time = 0
Wed Aug 25 16:13:31 2010 : Info: # Executing section preacct from file
/usr/local/etc/raddb/sites-enabled/default
Wed Aug 25 16:13:31 2010 : Info: +- entering group preacct {...}
Wed Aug 25 16:13:31 2010 : Info: ++[preprocess] returns ok
Wed Aug 25 16:13:31 2010 : Info: [acct_unique] Hashing 'NAS-Port =
2525,Client-IP-Address = 10.201.3.20,NAS-IP-Address =
10.201.3.20,Acct-Session-Id = "0000090E",User-Name = "dr"'
Wed Aug 25 16:13:31 2010 : Info: [acct_unique] Acct-Unique-Session-ID =
"df515e6f587debd0".
Wed Aug 25 16:13:31 2010 : Info: ++[acct_unique] returns ok
Wed Aug 25 16:13:31 2010 : Info: [suffix] No '@' in User-Name = "dr",
looking up realm NULL
Wed Aug 25 16:13:31 2010 : Info: [suffix] Found realm "~.+$"
Wed Aug 25 16:13:31 2010 : Info: [suffix] Adding Stripped-User-Name = "dr"
Wed Aug 25 16:13:31 2010 : Info: [suffix] Adding Realm = "(null)"
Wed Aug 25 16:13:31 2010 : Info: [suffix] Accounting realm is LOCAL.
Wed Aug 25 16:13:31 2010 : Info: ++[suffix] returns ok
Wed Aug 25 16:13:31 2010 : Info: ++[files] returns noop
Wed Aug 25 16:13:31 2010 : Info: # Executing section accounting from
file /usr/local/etc/raddb/sites-enabled/default
Wed Aug 25 16:13:31 2010 : Info: +- entering group accounting {...}
Wed Aug 25 16:13:31 2010 : Info: [detail] expand:
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d ->
/usr/local/var/log/radius/radacct/10.201.3.20/detail-20100825
Wed Aug 25 16:13:31 2010 : Info: [detail]
/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d
expands to /usr/local/var/log/radius/radacct/10.201.3.20/detail-20100825
Wed Aug 25 16:13:31 2010 : Info: [detail] expand: %t -> Wed Aug 25
16:13:31 2010
Wed Aug 25 16:13:31 2010 : Info: ++[detail] returns ok
Wed Aug 25 16:13:31 2010 : Info: [linelog] expand: %{Acct-Status-Type}
-> Stop
Wed Aug 25 16:13:31 2010 : Info: [linelog] expand:
Accounting-Request.%{%{Acct-Status-Type}:-unknown} ->
Accounting-Request.Stop
Wed Aug 25 16:13:31 2010 : Info: [linelog] expand: Disconnect: User:
%{User-Name} client: %{Calling-Station-Id} location:
%{WISPr-Location-Name} %{Acct-Session-Time} seconds) %{Cisco-AVPair[*]}
-> Disconnect: User: dr client: 6033.4bec.2fcf location: FL2-1025-W1-3B
5921 seconds) ssid=UCAR_Testing vlan-id=56 nas-location=FL2-1025-W1-3B
auth-algo-type=eap-tls connect-progress=Call Up disc-cause-ext=No Reason
Wed Aug 25 16:13:31 2010 : Info: ++[linelog] returns ok
Wed Aug 25 16:13:31 2010 : Info: [attr_filter.accounting_response]
expand: %{User-Name} -> dr
Wed Aug 25 16:13:31 2010 : Debug: attr_filter: Matched entry DEFAULT at
line 12
Wed Aug 25 16:13:31 2010 : Info: ++[attr_filter.accounting_response]
returns updated
Sending Accounting-Response of id 99 to 10.201.3.20 port 1646
Wed Aug 25 16:13:31 2010 : Info: Finished request 161.
Wed Aug 25 16:13:31 2010 : Info: Cleaning up request 161 ID 99 with
timestamp +6224
Wed Aug 25 16:13:31 2010 : Debug: Going to the next request
Wed Aug 25 16:13:31 2010 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.201.3.20 port 1645, id=38,
length=113
User-Name = "dr"
Framed-MTU = 1400
Called-Station-Id = "0019.2fad.e842"
Calling-Station-Id = "6033.4bec.2fcf"
Service-Type = Login-User
Message-Authenticator = 0xe3d979f8510f330f6317fb72f85aebab
EAP-Message = 0x02010007016472
NAS-Port-Type = Wireless-802.11
NAS-Port = 2541
NAS-IP-Address = 10.201.3.20
Wed Aug 25 16:13:45 2010 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
Wed Aug 25 16:13:45 2010 : Info: +- entering group authorize {...}
Wed Aug 25 16:13:45 2010 : Info: ++[preprocess] returns ok
Wed Aug 25 16:13:45 2010 : Info: [suffix] No '@' in User-Name = "dr",
looking up realm NULL
Wed Aug 25 16:13:45 2010 : Info: [suffix] Found realm "~.+$"
Wed Aug 25 16:13:45 2010 : Info: [suffix] Adding Stripped-User-Name = "dr"
Wed Aug 25 16:13:45 2010 : Info: [suffix] Adding Realm = "(null)"
Wed Aug 25 16:13:45 2010 : Info: [suffix] Authentication realm is LOCAL.
Wed Aug 25 16:13:45 2010 : Info: ++[suffix] returns ok
Wed Aug 25 16:13:45 2010 : Info: [eap] EAP packet type response id 1
length 7
Wed Aug 25 16:13:45 2010 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Aug 25 16:13:45 2010 : Info: ++[eap] returns updated
Wed Aug 25 16:13:45 2010 : Info: ++[files] returns noop
Wed Aug 25 16:13:45 2010 : Info: Found Auth-Type = EAP
Wed Aug 25 16:13:45 2010 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Wed Aug 25 16:13:45 2010 : Info: +- entering group authenticate {...}
Wed Aug 25 16:13:45 2010 : Info: [eap] EAP Identity
Wed Aug 25 16:13:45 2010 : Info: [eap] processing type tls
Wed Aug 25 16:13:45 2010 : Info: [tls] Requiring client certificate
Wed Aug 25 16:13:45 2010 : Info: [tls] Initiate
Wed Aug 25 16:13:45 2010 : Info: [tls] Start returned 1
Wed Aug 25 16:13:45 2010 : Info: ++[eap] returns handled
Sending Access-Challenge of id 38 to 10.201.3.20 port 1645
EAP-Message = 0x010200060d20
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xe6627b07e660765c75bc1addc8889678
Wed Aug 25 16:13:45 2010 : Info: Finished request 162.
Wed Aug 25 16:13:45 2010 : Debug: Going to the next request
Wed Aug 25 16:13:45 2010 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 10.201.3.20 port 1645, id=39,
length=260
User-Name = "dr"
Framed-MTU = 1400
Called-Station-Id = "0019.2fad.e842"
Calling-Station-Id = "6033.4bec.2fcf"
Service-Type = Login-User
Message-Authenticator = 0x4d215817e622a3a7ab5c6f483561b0ed
EAP-Message =
0x020200880d800000007e16030100790100007503014c759581740e0d806afeadec59a6803d40ede34d8b43f860bb312ff791aabf9a00003ac00ac009c007c008c013c014c011c012c004c005c002c003c00ec00fc00cc00d002f000500040035000a0009000300080033003900160015001401000012000a00080006001700180019000b00020100
NAS-Port-Type = Wireless-802.11
NAS-Port = 2541
State = 0xe6627b07e660765c75bc1addc8889678
NAS-IP-Address = 10.201.3.20
Wed Aug 25 16:13:45 2010 : Info: # Executing section authorize from file
/usr/local/etc/raddb/sites-enabled/default
Wed Aug 25 16:13:45 2010 : Info: +- entering group authorize {...}
Wed Aug 25 16:13:45 2010 : Info: ++[preprocess] returns ok
Wed Aug 25 16:13:45 2010 : Info: [suffix] No '@' in User-Name = "dr",
looking up realm NULL
Wed Aug 25 16:13:45 2010 : Info: [suffix] Found realm "~.+$"
Wed Aug 25 16:13:45 2010 : Info: [suffix] Adding Stripped-User-Name = "dr"
Wed Aug 25 16:13:45 2010 : Info: [suffix] Adding Realm = "(null)"
Wed Aug 25 16:13:45 2010 : Info: [suffix] Authentication realm is LOCAL.
Wed Aug 25 16:13:45 2010 : Info: ++[suffix] returns ok
Wed Aug 25 16:13:45 2010 : Info: [eap] EAP packet type response id 2
length 136
Wed Aug 25 16:13:45 2010 : Info: [eap] No EAP Start, assuming it's an
on-going EAP conversation
Wed Aug 25 16:13:45 2010 : Info: ++[eap] returns updated
Wed Aug 25 16:13:45 2010 : Info: ++[files] returns noop
Wed Aug 25 16:13:45 2010 : Info: Found Auth-Type = EAP
Wed Aug 25 16:13:45 2010 : Info: # Executing group from file
/usr/local/etc/raddb/sites-enabled/default
Wed Aug 25 16:13:45 2010 : Info: +- entering group authenticate {...}
cisl-dmtest:/usr/local/sbin#
--
-----------------------------------------------------------------
| David Mitchell (mitchell at ucar.edu) Network Engineer IV |
| Tel: (303) 497-1845 National Center for |
| FAX: (303) 497-1818 Atmospheric Research |
-----------------------------------------------------------------
More information about the Freeradius-Users
mailing list