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@ucar.edu) Network Engineer IV | | Tel: (303) 497-1845 National Center for | | FAX: (303) 497-1818 Atmospheric Research | -----------------------------------------------------------------