Thank you for your advise Alan. I have changed DEFAULT configuration, but the problem is persisting :(. Debug output: [radiusd@tdrad1 acct-test-orig]$ ./run-debug.sh Mon Aug 17 09:43:09 2015 : Debug: Server was built with: Mon Aug 17 09:43:09 2015 : Debug: accounting : yes Mon Aug 17 09:43:09 2015 : Debug: authentication : yes Mon Aug 17 09:43:09 2015 : Debug: ascend-binary-attributes : yes Mon Aug 17 09:43:09 2015 : Debug: coa : yes Mon Aug 17 09:43:09 2015 : Debug: control-socket : yes Mon Aug 17 09:43:09 2015 : Debug: detail : yes Mon Aug 17 09:43:09 2015 : Debug: dhcp : yes Mon Aug 17 09:43:09 2015 : Debug: dynamic-clients : yes Mon Aug 17 09:43:09 2015 : Debug: osfc2 : no Mon Aug 17 09:43:09 2015 : Debug: proxy : yes Mon Aug 17 09:43:09 2015 : Debug: regex-pcre : no Mon Aug 17 09:43:09 2015 : Debug: regex-posix : yes Mon Aug 17 09:43:09 2015 : Debug: regex-posix-extended : yes Mon Aug 17 09:43:09 2015 : Debug: session-management : yes Mon Aug 17 09:43:09 2015 : Debug: stats : yes Mon Aug 17 09:43:09 2015 : Debug: tcp : yes Mon Aug 17 09:43:09 2015 : Debug: threads : yes Mon Aug 17 09:43:09 2015 : Debug: tls : yes Mon Aug 17 09:43:09 2015 : Debug: unlang : yes Mon Aug 17 09:43:09 2015 : Debug: vmps : yes Mon Aug 17 09:43:09 2015 : Debug: developer : yes Mon Aug 17 09:43:09 2015 : Debug: Server core libs: Mon Aug 17 09:43:09 2015 : Debug: freeradius-server : 3.0.10 Mon Aug 17 09:43:09 2015 : Debug: talloc : 2.0.* Mon Aug 17 09:43:09 2015 : Debug: ssl : 0.9.8b release Mon Aug 17 09:43:09 2015 : Debug: Endianess: Mon Aug 17 09:43:09 2015 : Debug: little Mon Aug 17 09:43:09 2015 : Debug: Compilation flags: Mon Aug 17 09:43:09 2015 : Info: Copyright (C) 1999-2015 The FreeRADIUS server project and contributors Mon Aug 17 09:43:09 2015 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Mon Aug 17 09:43:09 2015 : Info: PARTICULAR PURPOSE Mon Aug 17 09:43:09 2015 : Info: You may redistribute copies of FreeRADIUS under the terms of the Mon Aug 17 09:43:09 2015 : Info: GNU General Public License Mon Aug 17 09:43:09 2015 : Info: For more information about these matters, see the file named COPYRIGHT Mon Aug 17 09:43:09 2015 : Info: Starting - reading configuration files ... Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.dhcp Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.vqp Mon Aug 17 09:43:09 2015 : Debug: including dictionary file /app/radius/conf/acct-test-orig/dictionary Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/radiusd.conf Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/templates.conf Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/proxy.conf Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/clients.conf Mon Aug 17 09:43:09 2015 : Debug: including files in directory /app/radius/conf/acct-test-orig/mods-enabled/ Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/files Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/expr Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/preprocess Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/chap Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/perl Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/mods-enabled/pap Mon Aug 17 09:43:09 2015 : Debug: including files in directory /app/radius/conf/acct-test-orig/policy.d/ Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/abfab-tr Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/debug Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/control Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/eap Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/canonicalization Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/dhcp Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/accounting Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/cui Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (no == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (${policy.cui_require_operator_name} == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: OPTIMIZING (no == yes) --> FALSE Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/operator-name Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/policy.d/filter Mon Aug 17 09:43:09 2015 : Debug: including files in directory /app/radius/conf/acct-test-orig/sites-enabled/ Mon Aug 17 09:43:09 2015 : Debug: including configuration file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:09 2015 : Debug: main { Mon Aug 17 09:43:09 2015 : Debug: name = "acct-test-orig" Mon Aug 17 09:43:09 2015 : Debug: prefix = "/app/radius/freeradius-3.0.9" Mon Aug 17 09:43:09 2015 : Debug: localstatedir = "/app_log/radius/acct-test-orig/" Mon Aug 17 09:43:09 2015 : Debug: sbindir = "/app/radius/freeradius-3.0.9/sbin" Mon Aug 17 09:43:09 2015 : Debug: logdir = "/app_log/radius/acct-test-orig/" Mon Aug 17 09:43:09 2015 : Debug: run_dir = "/app_log/radius/acct-test-orig/" Mon Aug 17 09:43:09 2015 : Debug: libdir = "/app/radius/freeradius-3.0.9/lib" Mon Aug 17 09:43:09 2015 : Debug: radacctdir = "/app_log/radius/acct-test-orig//radacct" Mon Aug 17 09:43:09 2015 : Debug: panic_action = "gdb -silent -x /app/radius/freeradius-3.0.9/../raddb/acct-test-orig/panic.gdb %e %p 2>&1 | tee /app_log/radius/acct-test-orig//gdb-acct-test-orig-%p.log" Mon Aug 17 09:43:09 2015 : Debug: hostname_lookups = no Mon Aug 17 09:43:09 2015 : Debug: max_request_time = 5 Mon Aug 17 09:43:09 2015 : Debug: cleanup_delay = 2 Mon Aug 17 09:43:09 2015 : Debug: max_requests = 25600 Mon Aug 17 09:43:09 2015 : Debug: pidfile = "/app_log/radius/acct-test-orig//radius.pid" Mon Aug 17 09:43:09 2015 : Debug: checkrad = "/app/radius/freeradius-3.0.9/sbin/checkrad" Mon Aug 17 09:43:09 2015 : Debug: debug_level = 0 Mon Aug 17 09:43:09 2015 : Debug: proxy_requests = yes Mon Aug 17 09:43:09 2015 : Debug: log { Mon Aug 17 09:43:09 2015 : Debug: stripped_names = no Mon Aug 17 09:43:09 2015 : Debug: auth = no Mon Aug 17 09:43:09 2015 : Debug: auth_badpass = no Mon Aug 17 09:43:09 2015 : Debug: auth_goodpass = no Mon Aug 17 09:43:09 2015 : Debug: colourise = yes Mon Aug 17 09:43:09 2015 : Debug: msg_denied = "You are already logged in - access denied" Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[272]: The item 'destination' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[289]: The item 'file' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[335]: The item 'syslog_facility' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: resources { Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: security { Mon Aug 17 09:43:09 2015 : Debug: max_attributes = 200 Mon Aug 17 09:43:09 2015 : Debug: reject_delay = 0.000000 Mon Aug 17 09:43:09 2015 : Debug: status_server = yes Mon Aug 17 09:43:09 2015 : Debug: allow_vulnerable_openssl = "yes" Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[451]: The item 'allow_core_dumps' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[67]: The item 'confdir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[69]: The item 'certdir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[70]: The item 'cadir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[72]: The item 'loader_dir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[74]: The item 'notification_dir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[78]: The item 'db_dir' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Warning: /app/radius/conf/acct-test-orig/radiusd.conf[144]: The item 'correct_escapes' is defined, but is unused by the configuration Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Loading Realms and Home Servers #### Mon Aug 17 09:43:09 2015 : Debug: proxy server { Mon Aug 17 09:43:09 2015 : Debug: retry_delay = 5 Mon Aug 17 09:43:09 2015 : Debug: retry_count = 3 Mon Aug 17 09:43:09 2015 : Debug: default_fallback = no Mon Aug 17 09:43:09 2015 : Debug: dead_time = 120 Mon Aug 17 09:43:09 2015 : Debug: wake_all_if_all_dead = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: home_server localhostA { Mon Aug 17 09:43:09 2015 : Debug: ipaddr = 127.0.0.1 Mon Aug 17 09:43:09 2015 : Debug: port = 60813 Mon Aug 17 09:43:09 2015 : Debug: type = "acct" Mon Aug 17 09:43:09 2015 : Debug: secret = "test123test" Mon Aug 17 09:43:09 2015 : Debug: response_window = 20.000000 Mon Aug 17 09:43:09 2015 : Debug: response_timeouts = 1 Mon Aug 17 09:43:09 2015 : Debug: max_outstanding = 65536 Mon Aug 17 09:43:09 2015 : Debug: zombie_period = 40 Mon Aug 17 09:43:09 2015 : Debug: status_check = "status-server" Mon Aug 17 09:43:09 2015 : Debug: ping_interval = 30 Mon Aug 17 09:43:09 2015 : Debug: check_interval = 30 Mon Aug 17 09:43:09 2015 : Debug: check_timeout = 4 Mon Aug 17 09:43:09 2015 : Debug: num_answers_to_alive = 3 Mon Aug 17 09:43:09 2015 : Debug: revive_interval = 120 Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: max_requests = 0 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 0 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: coa { Mon Aug 17 09:43:09 2015 : Debug: irt = 2 Mon Aug 17 09:43:09 2015 : Debug: mrt = 16 Mon Aug 17 09:43:09 2015 : Debug: mrc = 5 Mon Aug 17 09:43:09 2015 : Debug: mrd = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Warning: WARNING: Ignoring "response_window = 20.000000", forcing to "response_window = 5.000000" Mon Aug 17 09:43:09 2015 : Debug: home_server_pool my_acct_failover { Mon Aug 17 09:43:09 2015 : Debug: type = fail-over Mon Aug 17 09:43:09 2015 : Debug: home_server = localhostA Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: realm testproxy.sk { Mon Aug 17 09:43:09 2015 : Debug: acct_pool = my_acct_failover Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: realm LOCAL { Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Loading Clients #### Mon Aug 17 09:43:09 2015 : Debug: client localhost { Mon Aug 17 09:43:09 2015 : Debug: ipaddr = 127.0.0.1 Mon Aug 17 09:43:09 2015 : Debug: require_message_authenticator = no Mon Aug 17 09:43:09 2015 : Debug: secret = "test123test" Mon Aug 17 09:43:09 2015 : Debug: nas_type = "other" Mon Aug 17 09:43:09 2015 : Debug: proto = "*" Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Adding client 127.0.0.1/32 (127.0.0.1) to prefix tree 32 Mon Aug 17 09:43:09 2015 : Debug: client localhost_ipv6 { Mon Aug 17 09:43:09 2015 : Debug: ipv6addr = ::1 Mon Aug 17 09:43:09 2015 : Debug: require_message_authenticator = no Mon Aug 17 09:43:09 2015 : Debug: secret = "testing123" Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Adding client ::1/128 (::1) to prefix tree 128 Mon Aug 17 09:43:09 2015 : Info: Debugger not attached Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Instantiating modules #### Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_files.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_files, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_files Mon Aug 17 09:43:09 2015 : Debug: # Loading module "files" from file /app/radius/conf/acct-test-orig/mods-enabled/files Mon Aug 17 09:43:09 2015 : Debug: files { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/files/authorize" Mon Aug 17 09:43:09 2015 : Debug: acctusersfile = "/app/radius/conf/acct-test-orig/mods-config/files/accounting" Mon Aug 17 09:43:09 2015 : Debug: preproxy_usersfile = "/app/radius/conf/acct-test-orig/mods-config/files/pre-proxy" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_expr.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_expr, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_expr Mon Aug 17 09:43:09 2015 : Debug: # Loading module "expr" from file /app/radius/conf/acct-test-orig/mods-enabled/expr Mon Aug 17 09:43:09 2015 : Debug: expr { Mon Aug 17 09:43:09 2015 : Debug: safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôœùûüaÿÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔŒÙÛÜŸ" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_preprocess.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_preprocess, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_preprocess Mon Aug 17 09:43:09 2015 : Debug: # Loading module "preprocess" from file /app/radius/conf/acct-test-orig/mods-enabled/preprocess Mon Aug 17 09:43:09 2015 : Debug: preprocess { Mon Aug 17 09:43:09 2015 : Debug: huntgroups = "/app/radius/conf/acct-test-orig/mods-config/preprocess/huntgroups" Mon Aug 17 09:43:09 2015 : Debug: hints = "/app/radius/conf/acct-test-orig/mods-config/preprocess/hints" Mon Aug 17 09:43:09 2015 : Debug: with_ascend_hack = no Mon Aug 17 09:43:09 2015 : Debug: ascend_channels_per_line = 23 Mon Aug 17 09:43:09 2015 : Debug: with_ntdomain_hack = no Mon Aug 17 09:43:09 2015 : Debug: with_specialix_jetstream_hack = no Mon Aug 17 09:43:09 2015 : Debug: with_cisco_vsa_hack = no Mon Aug 17 09:43:09 2015 : Debug: with_alvarion_vsa_hack = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_chap.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_chap, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_chap Mon Aug 17 09:43:09 2015 : Debug: # Loading module "chap" from file /app/radius/conf/acct-test-orig/mods-enabled/chap Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_attr_filter.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_attr_filter, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_attr_filter Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.post-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.post-proxy { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/post-proxy" Mon Aug 17 09:43:09 2015 : Debug: key = "%{Realm}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.pre-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.pre-proxy { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/pre-proxy" Mon Aug 17 09:43:09 2015 : Debug: key = "%{Realm}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.access_reject" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.access_reject { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/access_reject" Mon Aug 17 09:43:09 2015 : Debug: key = "%{User-Name}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.access_challenge" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.access_challenge { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/access_challenge" Mon Aug 17 09:43:09 2015 : Debug: key = "%{User-Name}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "attr_filter.accounting_response" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: attr_filter attr_filter.accounting_response { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/attr_filter/accounting_response" Mon Aug 17 09:43:09 2015 : Debug: key = "%{User-Name}" Mon Aug 17 09:43:09 2015 : Debug: relaxed = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_always.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_always, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_always Mon Aug 17 09:43:09 2015 : Debug: # Loading module "reject" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always reject { Mon Aug 17 09:43:09 2015 : Debug: rcode = "reject" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "fail" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always fail { Mon Aug 17 09:43:09 2015 : Debug: rcode = "fail" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "ok" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always ok { Mon Aug 17 09:43:09 2015 : Debug: rcode = "ok" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "handled" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always handled { Mon Aug 17 09:43:09 2015 : Debug: rcode = "handled" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "invalid" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always invalid { Mon Aug 17 09:43:09 2015 : Debug: rcode = "invalid" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "userlock" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always userlock { Mon Aug 17 09:43:09 2015 : Debug: rcode = "userlock" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "notfound" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always notfound { Mon Aug 17 09:43:09 2015 : Debug: rcode = "notfound" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "noop" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always noop { Mon Aug 17 09:43:09 2015 : Debug: rcode = "noop" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "updated" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: always updated { Mon Aug 17 09:43:09 2015 : Debug: rcode = "updated" Mon Aug 17 09:43:09 2015 : Debug: simulcount = 0 Mon Aug 17 09:43:09 2015 : Debug: mpp = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_perl.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_perl, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_perl Mon Aug 17 09:43:09 2015 : Debug: # Loading module "perl" from file /app/radius/conf/acct-test-orig/mods-enabled/perl Mon Aug 17 09:43:09 2015 : Debug: perl { Mon Aug 17 09:43:09 2015 : Debug: filename = "/app/radius/conf/acct-test-orig/mods-config/perl/example.pl" Mon Aug 17 09:43:09 2015 : Debug: func_authorize = "authorize" Mon Aug 17 09:43:09 2015 : Debug: func_authenticate = "authenticate" Mon Aug 17 09:43:09 2015 : Debug: func_post_auth = "post_auth" Mon Aug 17 09:43:09 2015 : Debug: func_accounting = "accounting" Mon Aug 17 09:43:09 2015 : Debug: func_preacct = "preacct" Mon Aug 17 09:43:09 2015 : Debug: func_checksimul = "checksimul" Mon Aug 17 09:43:09 2015 : Debug: func_detach = "detach" Mon Aug 17 09:43:09 2015 : Debug: func_xlat = "xlat" Mon Aug 17 09:43:09 2015 : Debug: func_pre_proxy = "pre_proxy" Mon Aug 17 09:43:09 2015 : Debug: func_post_proxy = "post_proxy" Mon Aug 17 09:43:09 2015 : Debug: func_recv_coa = "recv_coa" Mon Aug 17 09:43:09 2015 : Debug: func_send_coa = "send_coa" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_realm.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_realm, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_realm Mon Aug 17 09:43:09 2015 : Debug: # Loading module "IPASS" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm IPASS { Mon Aug 17 09:43:09 2015 : Debug: format = "prefix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "/" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "suffix" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm suffix { Mon Aug 17 09:43:09 2015 : Debug: format = "suffix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "@" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "realmpercent" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm realmpercent { Mon Aug 17 09:43:09 2015 : Debug: format = "suffix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "%" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: # Loading module "ntdomain" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: realm ntdomain { Mon Aug 17 09:43:09 2015 : Debug: format = "prefix" Mon Aug 17 09:43:09 2015 : Debug: delimiter = "\\" Mon Aug 17 09:43:09 2015 : Debug: ignore_default = no Mon Aug 17 09:43:09 2015 : Debug: ignore_null = no Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/rlm_pap.so" Mon Aug 17 09:43:09 2015 : Debug: Loaded rlm_pap, checking if it's valid Mon Aug 17 09:43:09 2015 : Debug: # Loaded module rlm_pap Mon Aug 17 09:43:09 2015 : Debug: # Loading module "pap" from file /app/radius/conf/acct-test-orig/mods-enabled/pap Mon Aug 17 09:43:09 2015 : Debug: pap { Mon Aug 17 09:43:09 2015 : Debug: normalise = yes Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: instantiate { Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "perl" from file /app/radius/conf/acct-test-orig/mods-enabled/perl Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: modules { Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "files" from file /app/radius/conf/acct-test-orig/mods-enabled/files Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/files/authorize Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/files/accounting Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/files/pre-proxy Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "preprocess" from file /app/radius/conf/acct-test-orig/mods-enabled/preprocess Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/preprocess/huntgroups Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/preprocess/hints Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.post-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/post-proxy Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/pre-proxy Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.access_reject" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/access_reject Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.access_challenge" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/access_challenge Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "attr_filter.accounting_response" from file /app/radius/conf/acct-test-orig/mods-enabled/attr_filter Mon Aug 17 09:43:09 2015 : Debug: reading pairlist file /app/radius/conf/acct-test-orig/mods-config/attr_filter/accounting_response Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "reject" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "fail" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "ok" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "handled" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "invalid" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "userlock" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "notfound" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "noop" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "updated" from file /app/radius/conf/acct-test-orig/mods-enabled/always Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "IPASS" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "suffix" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "realmpercent" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "ntdomain" from file /app/radius/conf/acct-test-orig/mods-enabled/realm Mon Aug 17 09:43:09 2015 : Debug: # Instantiating module "pap" from file /app/radius/conf/acct-test-orig/mods-enabled/pap Mon Aug 17 09:43:09 2015 : Debug: } # modules Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Loading Virtual Servers #### Mon Aug 17 09:43:09 2015 : Debug: server { # from file /app/radius/conf/acct-test-orig/radiusd.conf Mon Aug 17 09:43:09 2015 : Debug: } # server Mon Aug 17 09:43:09 2015 : Debug: server default { # from file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:09 2015 : Debug: authenticate { Mon Aug 17 09:43:09 2015 : Debug: group { Mon Aug 17 09:43:09 2015 : Debug: pap Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: group { Mon Aug 17 09:43:09 2015 : Debug: chap Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } # authenticate Mon Aug 17 09:43:09 2015 : Debug: authorize { Mon Aug 17 09:43:09 2015 : Debug: policy filter_username { Mon Aug 17 09:43:09 2015 : Debug: if (!&User-Name) { Mon Aug 17 09:43:09 2015 : Debug: noop Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ / /) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Username contains whitespace' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /@.*@/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Multiple @ in username' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /\.\./) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Username contains ..s' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /@/ && !&User-Name =~ /@(.+)\.(.+)$/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Realm does not have at least one dot separator' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /\.$/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Realm ends with a dot' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: if (&User-Name =~ /@\./) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply:Reply-Message += 'Rejected: Realm begins with a dot' Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: preprocess Mon Aug 17 09:43:09 2015 : Debug: chap Mon Aug 17 09:43:09 2015 : Debug: suffix Mon Aug 17 09:43:09 2015 : Debug: files Mon Aug 17 09:43:09 2015 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Mon Aug 17 09:43:09 2015 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Mon Aug 17 09:43:09 2015 : Debug: pap Mon Aug 17 09:43:09 2015 : Debug: } # authorize Mon Aug 17 09:43:09 2015 : Debug: preacct { Mon Aug 17 09:43:09 2015 : Debug: preprocess Mon Aug 17 09:43:09 2015 : Debug: policy acct_unique { Mon Aug 17 09:43:09 2015 : Debug: if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/) { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: else { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}" Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: suffix Mon Aug 17 09:43:09 2015 : Debug: files Mon Aug 17 09:43:09 2015 : Debug: } # preacct Mon Aug 17 09:43:09 2015 : Debug: accounting { Mon Aug 17 09:43:09 2015 : Debug: attr_filter.accounting_response Mon Aug 17 09:43:09 2015 : Debug: } # accounting Mon Aug 17 09:43:09 2015 : Debug: post-auth { Mon Aug 17 09:43:09 2015 : Debug: update { Mon Aug 17 09:43:09 2015 : Debug: &reply[*] += &session-state[*] Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: group { Mon Aug 17 09:43:09 2015 : Debug: attr_filter.access_reject Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } # post-auth Mon Aug 17 09:43:09 2015 : Debug: } # server default Mon Aug 17 09:43:09 2015 : Debug: Created signal pipe. Read end FD 5, write end FD 6 Mon Aug 17 09:43:09 2015 : Debug: radiusd: #### Opening IP addresses and Ports #### Mon Aug 17 09:43:09 2015 : Debug: Loading library using absolute path "/app/radius/freeradius-3.0.9/lib/proto_acct.so" Mon Aug 17 09:43:09 2015 : Debug: Failed with error: /app/radius/freeradius-3.0.9/lib/proto_acct.so: cannot open shared object file: No such file or directory Mon Aug 17 09:43:09 2015 : Debug: Library file not found Mon Aug 17 09:43:09 2015 : Debug: Loading library using linker search path(s) Mon Aug 17 09:43:09 2015 : Debug: Defaults : /lib:/usr/lib Mon Aug 17 09:43:09 2015 : Debug: Failed with error: proto_acct.so: cannot open shared object file: No such file or directory Mon Aug 17 09:43:09 2015 : Debug: listen { Mon Aug 17 09:43:09 2015 : Debug: type = "acct" Mon Aug 17 09:43:09 2015 : Debug: ipaddr = * Mon Aug 17 09:43:09 2015 : Debug: port = 10813 Mon Aug 17 09:43:09 2015 : Debug: limit { Mon Aug 17 09:43:09 2015 : Debug: max_connections = 16 Mon Aug 17 09:43:09 2015 : Debug: lifetime = 0 Mon Aug 17 09:43:09 2015 : Debug: idle_timeout = 30 Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: } Mon Aug 17 09:43:09 2015 : Debug: Listening on acct address * port 10813 bound to server default Mon Aug 17 09:43:09 2015 : Debug: Opening new proxy socket 'proxy address * port 0' Mon Aug 17 09:43:09 2015 : Debug: Listening on proxy address * port 34833 Mon Aug 17 09:43:09 2015 : Info: Ready to process requests Socket: 7 Proto: 0 Src IP: 127.0.0.1 port: 43842 Dst IP: 127.0.0.1 port: 10813 Code: 4 Id: 94 Length: 219 Vector: ec9b6b7be6d6df3ec7718bfcbccce9cd Data: 01 1a 6d 6f 6e 2d 7a 64 72 6f 6a 65 31 40 74 65 73 74 70 72 6f 78 79 2e 73 6b 04 06 d5 97 d8 c9 20 17 67 67 73 6e 2d 30 31 2d 62 62 31 2e 6f 72 61 6e 67 65 2e 73 6b 3d 06 00 00 00 05 28 06 00 00 00 01 1e 0c 70 72 6f 78 79 2e 63 6f 72 70 1f 0e 34 32 31 39 30 35 30 36 36 30 30 31 2c 12 64 35 39 37 64 39 31 35 32 33 39 32 30 38 34 30 32 12 64 35 39 37 64 39 31 35 31 31 63 32 38 30 32 34 33 06 00 00 00 01 08 06 ac 17 44 0b 06 06 00 00 00 02 07 06 00 00 00 07 2d 06 00 00 00 01 e2 06 00 00 00 08 e0 0a 32 01 91 04 60 09 98 f8 e3 0c 3c 44 35 3e 3c 39 37 3e d9 15 e1 06 23 92 08 40 e4 06 d5 97 fc 18 Mon Aug 17 09:43:12 2015 : Debug: (0) Received Accounting-Request Id 94 from 127.0.0.1:43842 to 127.0.0.1:10813 length 219 Mon Aug 17 09:43:12 2015 : Debug: (0) User-Name = " mon-zdroje1@testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-IP-Address = 213.151.216.201 Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Identifier = " ggsn-01-bb1.orange.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Port-Type = Virtual Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Status-Type = Start Mon Aug 17 09:43:12 2015 : Debug: (0) Called-Station-Id = "proxy.corp" Mon Aug 17 09:43:12 2015 : Debug: (0) Calling-Station-Id = "421905066001" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Session-Id = "d597d91523920840" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Multi-Session-Id = "d597d91511c28024" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Link-Count = 1 Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-IP-Address = 172.23.68.11 Mon Aug 17 09:43:12 2015 : Debug: (0) Service-Type = Framed-User Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-Protocol = GPRS-PDP-Context Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Authentic = RADIUS Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-PRI-Number-Type = 8 Mon Aug 17 09:43:12 2015 : Debug: (0) Attr-224 = 0x32019104600998f8 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Dial-Number = "<D5><97>\331\025" Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Metric = 596772928 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Route-IP = 3583507480 Mon Aug 17 09:43:12 2015 : Debug: (0) # Executing section preacct from file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:12 2015 : Debug: (0) preacct { Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: calling preprocess (rlm_preprocess) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: returned from preprocess (rlm_preprocess) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [preprocess] = ok Mon Aug 17 09:43:12 2015 : Debug: (0) policy acct_unique { Mon Aug 17 09:43:12 2015 : Debug: (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) { Mon Aug 17 09:43:12 2015 : Debug: (0) EXPAND TMPL XLAT STRUCT Mon Aug 17 09:43:12 2015 : Debug: (0) EXPAND %{string:Class} Mon Aug 17 09:43:12 2015 : Debug: (0) --> Mon Aug 17 09:43:12 2015 : Debug: No matches Mon Aug 17 09:43:12 2015 : Debug: (0) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE Mon Aug 17 09:43:12 2015 : Debug: (0) else { Mon Aug 17 09:43:12 2015 : Debug: (0) update request { Mon Aug 17 09:43:12 2015 : Debug: (0) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} Mon Aug 17 09:43:12 2015 : Debug: (0) --> 772f7c0824d05fe594797a68d34c3161 Mon Aug 17 09:43:12 2015 : Debug: (0) &Acct-Unique-Session-Id := 772f7c0824d05fe594797a68d34c3161 Mon Aug 17 09:43:12 2015 : Debug: (0) } # update request = noop Mon Aug 17 09:43:12 2015 : Debug: (0) } # else = noop Mon Aug 17 09:43:12 2015 : Debug: (0) } # policy acct_unique = noop Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: calling suffix (rlm_realm) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Checking for suffix after "@" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Looking up realm "testproxy.sk" for User-Name = "mon-zdroje1@testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Found realm "testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Adding Stripped-User-Name = "mon-zdroje1" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Adding Realm = "testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Proxying request from user mon-zdroje1 to realm testproxy.sk Mon Aug 17 09:43:12 2015 : Debug: (0) suffix: Preparing to proxy accounting request to realm "testproxy.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: returned from suffix (rlm_realm) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [suffix] = updated Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: calling files (rlm_files) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[preacct]: returned from files (rlm_files) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [files] = noop Mon Aug 17 09:43:12 2015 : Debug: (0) } # preacct = updated Mon Aug 17 09:43:12 2015 : Debug: (0) # Executing section accounting from file /app/radius/conf/acct-test-orig/sites-enabled/default Mon Aug 17 09:43:12 2015 : Debug: (0) accounting { Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[accounting]: calling attr_filter.accounting_response (rlm_attr_filter) for request 0 Mon Aug 17 09:43:12 2015 : Debug: %{User-Name} Mon Aug 17 09:43:12 2015 : Debug: Parsed xlat tree: Mon Aug 17 09:43:12 2015 : Debug: attribute --> User-Name Mon Aug 17 09:43:12 2015 : Debug: (0) attr_filter.accounting_response: EXPAND %{User-Name} Mon Aug 17 09:43:12 2015 : Debug: (0) attr_filter.accounting_response: --> mon-zdroje1@testproxy.sk Mon Aug 17 09:43:12 2015 : Debug: (0) attr_filter.accounting_response: Matched entry DEFAULT at line 12 Mon Aug 17 09:43:12 2015 : Debug: (0) modsingle[accounting]: returned from attr_filter.accounting_response (rlm_attr_filter) for request 0 Mon Aug 17 09:43:12 2015 : Debug: (0) [attr_filter.accounting_response] = updated Mon Aug 17 09:43:12 2015 : Debug: (0) } # accounting = updated Mon Aug 17 09:43:12 2015 : Debug: (0) Empty pre-proxy section. Using default return values. Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: Trying to allocate ID (0/2) Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: Trying to open a new listener to the home server Mon Aug 17 09:43:12 2015 : Debug: Opening new proxy socket 'proxy address * port 0' Mon Aug 17 09:43:12 2015 : Debug: Listening on proxy address * port 36571 Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: Trying to allocate ID (1/2) Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: request is now in proxy hash Mon Aug 17 09:43:12 2015 : Debug: (0) proxy: allocating destination 127.0.0.1 port 60813 - Id 178 Mon Aug 17 09:43:12 2015 : Debug: (0) Proxying request to home server 127.0.0.1 port 60813 timeout 5.000000 01 0d 6d 6f 6e 2d 7a 64 72 6f 6a 65 31 04 06 d5 97 d8 c9 20 17 67 67 73 6e 2d 30 31 2d 62 62 31 2e 6f 72 61 6e 67 65 2e 73 6b 3d 06 00 00 00 05 28 06 00 00 00 01 1e 0c 70 72 6f 78 79 2e 63 6f 72 70 1f 0e 34 32 31 39 30 35 30 36 36 30 30 31 2c 12 64 35 39 37 64 39 31 35 32 33 39 32 30 38 34 30 32 12 64 35 39 37 64 39 31 35 31 31 63 32 38 30 32 34 33 06 00 00 00 01 08 06 ac 17 44 0b 06 06 00 00 00 02 07 06 00 00 00 07 2d 06 00 00 00 01 e2 06 00 00 00 08 e0 0a 32 01 91 04 60 09 98 f8 e3 0c 3c 44 35 3e 3c 39 37 3e d9 15 e1 06 23 92 08 40 e4 06 d5 97 fc 18 37 06 55 d1 90 90 21 04 39 34 Mon Aug 17 09:43:12 2015 : Debug: (0) Sent Accounting-Request Id 178 from 0.0.0.0:36571 to 127.0.0.1:60813 length 216 Mon Aug 17 09:43:12 2015 : Debug: (0) User-Name = "mon-zdroje1" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-IP-Address = 213.151.216.201 Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Identifier = " ggsn-01-bb1.orange.sk" Mon Aug 17 09:43:12 2015 : Debug: (0) NAS-Port-Type = Virtual Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Status-Type = Start Mon Aug 17 09:43:12 2015 : Debug: (0) Called-Station-Id = "proxy.corp" Mon Aug 17 09:43:12 2015 : Debug: (0) Calling-Station-Id = "421905066001" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Session-Id = "d597d91523920840" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Multi-Session-Id = "d597d91511c28024" Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Link-Count = 1 Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-IP-Address = 172.23.68.11 Mon Aug 17 09:43:12 2015 : Debug: (0) Service-Type = Framed-User Mon Aug 17 09:43:12 2015 : Debug: (0) Framed-Protocol = GPRS-PDP-Context Mon Aug 17 09:43:12 2015 : Debug: (0) Acct-Authentic = RADIUS Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-PRI-Number-Type = 8 Mon Aug 17 09:43:12 2015 : Debug: (0) Attr-224 = 0x32019104600998f8 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Dial-Number = "<D5><97>\331\025" Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Metric = 596772928 Mon Aug 17 09:43:12 2015 : Debug: (0) X-Ascend-Route-IP = 3583507480 Mon Aug 17 09:43:12 2015 : Debug: (0) Event-Timestamp = "Aug 17 2015 09:43:12 CEST" Mon Aug 17 09:43:12 2015 : Debug: (0) Proxy-State = 0x3934 Socket: 9 Proto: 17 Src IP: 0.0.0.0 port: 36571 Dst IP: 127.0.0.1 port: 60813 Code: 4 Id: 178 Length: 216 Vector: e74bb5b5237ba0490154d63d7a44838d Data: 01 0d 6d 6f 6e 2d 7a 64 72 6f 6a 65 31 04 06 d5 97 d8 c9 20 17 67 67 73 6e 2d 30 31 2d 62 62 31 2e 6f 72 61 6e 67 65 2e 73 6b 3d 06 00 00 00 05 28 06 00 00 00 01 1e 0c 70 72 6f 78 79 2e 63 6f 72 70 1f 0e 34 32 31 39 30 35 30 36 36 30 30 31 2c 12 64 35 39 37 64 39 31 35 32 33 39 32 30 38 34 30 32 12 64 35 39 37 64 39 31 35 31 31 63 32 38 30 32 34 33 06 00 00 00 01 08 06 ac 17 44 0b 06 06 00 00 00 02 07 06 00 00 00 07 2d 06 00 00 00 01 e2 06 00 00 00 08 e0 0a 32 01 91 04 60 09 98 f8 e3 0c 3c 44 35 3e 3c 39 37 3e d9 15 e1 06 23 92 08 40 e4 06 d5 97 fc 18 37 06 55 d1 90 90 21 04 39 34 Mon Aug 17 09:43:12 2015 : Debug: Waking up in 0.3 seconds. Mon Aug 17 09:43:12 2015 : Debug: (0) Expecting proxy response no later than 4.669935 seconds from now Mon Aug 17 09:43:12 2015 : Debug: Waking up in 4.6 seconds. Mon Aug 17 09:43:17 2015 : Debug: (0) No proxy response, giving up on request and marking it done Mon Aug 17 09:43:17 2015 : Proxy: Marking home server 127.0.0.1 port 60813 as zombie (it has not responded in 5.000000 seconds). Mon Aug 17 09:43:17 2015 : Debug: (1) proxy: Trying to allocate ID (0/2) Mon Aug 17 09:43:17 2015 : Debug: (1) proxy: request is now in proxy hash Mon Aug 17 09:43:17 2015 : Debug: (1) proxy: allocating destination 127.0.0.1 port 60813 - Id 18 Mon Aug 17 09:43:17 2015 : Debug: PING: Waiting 4 seconds for response to ping Mon Aug 17 09:43:17 2015 : Debug: (1) Sent Status-Server Id 18 from 0.0.0.0:36571 to 127.0.0.1:60813 length 0 Mon Aug 17 09:43:17 2015 : Debug: (1) Message-Authenticator := 0x00 Mon Aug 17 09:43:17 2015 : Debug: (1) NAS-Identifier := "Status Check 0. Are you alive?" 50 12 ... 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 30 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Socket: 9 Proto: 0 Src IP: 0.0.0.0 port: 36571 Dst IP: 127.0.0.1 port: 60813 Code: 12 Id: 18 Length: 70 Vector: b4d8e37ec22a79bbb564a512370cfe23 Data: 50 12 f2 95 eb a2 33 84 d7 05 6c aa 0e fc d8 70 ce 4f 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 30 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Mon Aug 17 09:43:17 2015 : Debug: PING: Next status packet in 30 seconds Mon Aug 17 09:43:17 2015 : ERROR: (0) Failing proxied request for user "mon-zdroje1", due to lack of any response from home server 127.0.0.1 port 60813 Mon Aug 17 09:43:17 2015 : Debug: (0) Clearing existing &reply: attributes Mon Aug 17 09:43:17 2015 : Debug: (0) Found Post-Proxy-Type Fail-Accounting Mon Aug 17 09:43:17 2015 : Debug: (0) proxy: request is no longer in proxy hash Mon Aug 17 09:43:17 2015 : Debug: (0) Post-Proxy-Type sub-section not found. Ignoring. Mon Aug 17 09:43:17 2015 : Debug: (0) Not sending reply to client. Mon Aug 17 09:43:17 2015 : Debug: (0) Finished request Mon Aug 17 09:43:17 2015 : Debug: (0) <done>: Cleaning up request packet ID 94 with timestamp +3 Mon Aug 17 09:43:17 2015 : Debug: Waking up in 3.9 seconds. Mon Aug 17 09:43:21 2015 : Error: No response to status check 1 ID 18 for home server 127.0.0.1 port 60813 Mon Aug 17 09:43:21 2015 : Debug: (1) proxy: request is no longer in proxy hash Mon Aug 17 09:43:21 2015 : Debug: Waking up in 24.4 seconds. Mon Aug 17 09:43:46 2015 : Debug: (2) proxy: Trying to allocate ID (0/2) Mon Aug 17 09:43:46 2015 : Debug: (2) proxy: request is now in proxy hash Mon Aug 17 09:43:46 2015 : Debug: (2) proxy: allocating destination 127.0.0.1 port 60813 - Id 14 Mon Aug 17 09:43:46 2015 : Debug: PING: Waiting 4 seconds for response to ping Mon Aug 17 09:43:46 2015 : Debug: (2) Sent Status-Server Id 14 from 0.0.0.0:36571 to 127.0.0.1:60813 length 0 Mon Aug 17 09:43:46 2015 : Debug: (2) Message-Authenticator := 0x00 Mon Aug 17 09:43:46 2015 : Debug: (2) NAS-Identifier := "Status Check 1. Are you alive?" 50 12 ... 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Socket: 9 Proto: 0 Src IP: 0.0.0.0 port: 36571 Dst IP: 127.0.0.1 port: 60813 Code: 12 Id: 14 Length: 70 Vector: e05c638156153316b44d2765df2dc725 Data: 50 12 46 03 4a 15 13 fb 56 93 22 9f c1 46 0c 18 66 cc 20 20 53 74 61 74 75 73 20 43 68 65 63 6b 20 31 2e 20 41 72 65 20 79 6f 75 20 61 6c 69 76 65 3f Mon Aug 17 09:43:46 2015 : Debug: PING: Next status packet in 30 seconds Mon Aug 17 09:43:46 2015 : Debug: Waking up in 3.9 seconds. Socket: 9 Proto: 0 Src IP: 127.0.0.1 port: 60813 Dst IP: 127.0.0.1 port: 36571 Code: 5 Id: 14 Length: 20 Vector: c7c21077ac5bc7ab2bb6b2ca152354ed Mon Aug 17 09:43:46 2015 : Proxy: No outstanding request was found for Accounting-Response packet from host 127.0.0.1 port 60813 - ID 14 Mon Aug 17 09:43:46 2015 : Debug: Waking up in 3.9 seconds. Mon Aug 17 09:43:50 2015 : Error: No response to status check 2 ID 14 for home server 127.0.0.1 port 60813 Mon Aug 17 09:43:50 2015 : Debug: (2) proxy: request is no longer in proxy hash Mon Aug 17 09:43:50 2015 : Debug: Waking up in 27.7 seconds. Debug output (3rd party instance): [radiusd@tdrad1 proxy-test-A]$ ./run-debug.sh Copyright (C) 1999-2015 The FreeRADIUS server project and contributors There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License For more information about these matters, see the file named COPYRIGHT Starting - reading configuration files ... including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.dhcp including dictionary file /app/radius/freeradius-3.0.9/share/freeradius/dictionary.vqp including dictionary file /app/radius/conf/proxy-test-A/dictionary including configuration file /app/radius/conf/proxy-test-A/radiusd.conf including configuration file /app/radius/conf/proxy-test-A/templates.conf including configuration file /app/radius/conf/proxy-test-A/proxy.conf including configuration file /app/radius/conf/proxy-test-A/clients.conf including files in directory /app/radius/conf/proxy-test-A/mods-enabled/ including configuration file /app/radius/conf/proxy-test-A/mods-enabled/files including configuration file /app/radius/conf/proxy-test-A/mods-enabled/expr including configuration file /app/radius/conf/proxy-test-A/mods-enabled/preprocess including configuration file /app/radius/conf/proxy-test-A/mods-enabled/chap including configuration file /app/radius/conf/proxy-test-A/mods-enabled/always including configuration file /app/radius/conf/proxy-test-A/mods-enabled/linelog including configuration file /app/radius/conf/proxy-test-A/mods-enabled/realm including configuration file /app/radius/conf/proxy-test-A/mods-enabled/pap including files in directory /app/radius/conf/proxy-test-A/policy-enabled/ including configuration file /app/radius/conf/proxy-test-A/policy-enabled/debug including configuration file /app/radius/conf/proxy-test-A/policy-enabled/huntgroup including configuration file /app/radius/conf/proxy-test-A/policy-enabled/lns including configuration file /app/radius/conf/proxy-test-A/policy-enabled/username including configuration file /app/radius/conf/proxy-test-A/policy-enabled/nas including configuration file /app/radius/conf/proxy-test-A/policy-enabled/bdsl including configuration file /app/radius/conf/proxy-test-A/policy-enabled/SkyToll including configuration file /app/radius/conf/proxy-test-A/policy-enabled/filter including files in directory /app/radius/conf/proxy-test-A/sites-enabled/ including configuration file /app/radius/conf/proxy-test-A/sites-enabled/default main { name = "proxy-test-A" prefix = "/app/radius/freeradius-3.0.9" localstatedir = "/app_log/radius/proxy-test-A/" sbindir = "/app/radius/freeradius-3.0.9/sbin" logdir = "/app_log/radius/proxy-test-A/" run_dir = "/app_log/radius/proxy-test-A/" libdir = "/app/radius/freeradius-3.0.9/lib" radacctdir = "/app_log/radius/proxy-test-A//radacct" panic_action = "gdb -silent -x /app/radius/freeradius-3.0.9/../raddb/proxy-test-A/panic.gdb %e %p 2>&1 | tee /app_log/radius/proxy-test-A//gdb-proxy-test-A-%p.log" hostname_lookups = no max_request_time = 5 cleanup_delay = 2 max_requests = 25600 pidfile = "/app_log/radius/proxy-test-A//radius.pid" checkrad = "/app/radius/freeradius-3.0.9/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = no auth_badpass = no auth_goodpass = no colourise = yes msg_denied = "You are already logged in - access denied" } resources { } security { max_attributes = 200 reject_delay = 0.000000 status_server = yes allow_vulnerable_openssl = "yes" } } radiusd: #### Loading Realms and Home Servers #### proxy server { retry_delay = 5 retry_count = 3 default_fallback = no dead_time = 120 wake_all_if_all_dead = no } realm LOCAL { authhost = LOCAL accthost = LOCAL } realm NULL { authhost = LOCAL accthost = LOCAL } realm DEFAULT { authhost = LOCAL accthost = LOCAL } radiusd: #### Loading Clients #### client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> nas_type = "other" proto = "*" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } Debugger not attached radiusd: #### Instantiating modules #### # Loaded module rlm_files # Loading module "files" from file /app/radius/conf/proxy-test-A/mods-enabled/files files { filename = "/app/radius/conf/proxy-test-A/mods-config/files/authorize" usersfile = "/app/radius/conf/proxy-test-A/mods-config/files/authorize" acctusersfile = "/app/radius/conf/proxy-test-A/mods-config/files/accounting" preproxy_usersfile = "/app/radius/conf/proxy-test-A/mods-config/files/pre-proxy" } # Loaded module rlm_expr # Loading module "expr" from file /app/radius/conf/proxy-test-A/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /��������������������������������������a����������������������������������������" } # Loaded module rlm_preprocess # Loading module "preprocess" from file /app/radius/conf/proxy-test-A/mods-enabled/preprocess preprocess { with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no with_alvarion_vsa_hack = no } # Loaded module rlm_chap # Loading module "chap" from file /app/radius/conf/proxy-test-A/mods-enabled/chap # Loaded module rlm_always # Loading module "reject" from file /app/radius/conf/proxy-test-A/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Loading module "fail" from file /app/radius/conf/proxy-test-A/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Loading module "ok" from file /app/radius/conf/proxy-test-A/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Loading module "handled" from file /app/radius/conf/proxy-test-A/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Loading module "invalid" from file /app/radius/conf/proxy-test-A/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Loading module "userlock" from file /app/radius/conf/proxy-test-A/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Loading module "notfound" from file /app/radius/conf/proxy-test-A/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Loading module "noop" from file /app/radius/conf/proxy-test-A/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Loading module "updated" from file /app/radius/conf/proxy-test-A/mods-enabled/always always updated { rcode = "updated" simulcount = 0 mpp = no } # Loaded module rlm_linelog # Loading module "linelog" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog { filename = "/app_log/radius/proxy-test-A//linelog" escape_filenames = no syslog_severity = "info" permissions = 384 format = "This is a log message for %{User-Name}" reference = "messages.%{%{Packet-Type}:-default}" } # Loading module "log_request" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog log_request { filename = "/app_log/radius/proxy-test-A/radius.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info: REQUEST(%{User-Name}): %{pairs:request:}" } # Loading module "log_control" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog log_control { filename = "/app_log/radius/proxy-test-A/radius.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info: CONTROL(%{User-Name}): %{pairs:control:}" } # Loading module "log_reply" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog linelog log_reply { filename = "/app_log/radius/proxy-test-A/radius.log" escape_filenames = no syslog_severity = "info" permissions = 384 format = "%t : Info REPLY(%{User-Name}): %{pairs:reply:}" } # Loaded module rlm_realm # Loading module "suffix" from file /app/radius/conf/proxy-test-A/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } # Loaded module rlm_pap # Loading module "pap" from file /app/radius/conf/proxy-test-A/mods-enabled/pap pap { normalise = yes } instantiate { } modules { # Instantiating module "files" from file /app/radius/conf/proxy-test-A/mods-enabled/files reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/authorize reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/authorize reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/accounting reading pairlist file /app/radius/conf/proxy-test-A/mods-config/files/pre-proxy # Instantiating module "preprocess" from file /app/radius/conf/proxy-test-A/mods-enabled/preprocess # Instantiating module "reject" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "fail" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "ok" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "handled" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "invalid" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "userlock" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "notfound" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "noop" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "updated" from file /app/radius/conf/proxy-test-A/mods-enabled/always # Instantiating module "linelog" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "log_request" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "log_control" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "log_reply" from file /app/radius/conf/proxy-test-A/mods-enabled/linelog # Instantiating module "suffix" from file /app/radius/conf/proxy-test-A/mods-enabled/realm # Instantiating module "pap" from file /app/radius/conf/proxy-test-A/mods-enabled/pap } # modules radiusd: #### Loading Virtual Servers #### server { # from file /app/radius/conf/proxy-test-A/radiusd.conf } # server server default { # from file /app/radius/conf/proxy-test-A/sites-enabled/default # Loading authenticate {...} # Loading authorize {...} # Loading accounting {...} } # server default radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipv4addr = localhost IPv4 address [127.0.0.1] port = 60812 } listen { type = "acct" ipv4addr = localhost IPv4 address [127.0.0.1] port = 60813 } Listening on auth address 127.0.0.1 port 60812 bound to server default Listening on acct address 127.0.0.1 port 60813 bound to server default Ready to process requests (0) Received Status-Server Id 14 from 127.0.0.1:36571 to 127.0.0.1:60813 length 70 (0) Message-Authenticator = 0x46034a1513fb5693229fc1460c1866cc (0) NAS-Identifier = "Status Check 1. Are you alive?" (0) Sent Accounting-Response Id 14 from 127.0.0.1:60813 to 127.0.0.1:36571 length 0 (0) Finished request Waking up in 1.9 seconds. (0) <done>: Cleaning up request packet ID 14 with timestamp +23 Ready to process requests On Fri, Aug 14, 2015 at 10:11 PM, Alan DeKok <aland@deployingradius.com> wrote:
OK... that's just weird.
What are you doing with the config? You're clearly in some unusual corner case which causes this problem. I can't see it here, and there have been no other reports.
So... it works 99% of the time. What causes the problem?
i.e. start with a default config, test that it works. Make one change to get it closer to your current config, test it again, etc. When it stops working, you've narrowed it down to the one change that causes the problem.
You don't need to change much... just anything related to proxying and status checks. There's no need to look users up in a DB, etc.
Unless I know what's different about your system, it will be impossible to understand what's going wrong. And therefore impossible to fix it.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html