Class Attribute Missing in Accounting Request Packets from Windows 8.1
I have encountered a strange issue with Accounting Request when I connected a fresh-installed Windows 8.1 Pro machine to the Wi-Fi network. When I connect using an iPhone 5SE, I see the all important Class attribute in the Accounting Request packets, but it is missing when I connect the Windows 8.1 Pro machine. That did not happen with FreeRADIUS 2.2.9. Why does that happen? How can I solve this problem? # radiusd -X FreeRADIUS Version 3.0.15 Copyright (C) 1999-2017 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 /usr/local/share/freeradius/dictionary including dictionary file /usr/local/share/freeradius/dictionary.dhcp including dictionary file /usr/local/share/freeradius/dictionary.vqp including dictionary file /usr/local/etc/raddb/dictionary including configuration file /usr/local/etc/raddb/radiusd.conf including configuration file /usr/local/etc/raddb/clients.conf including files in directory /usr/local/etc/raddb/mods-enabled/ including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter including configuration file /usr/local/etc/raddb/mods-enabled/cache_eap including configuration file /usr/local/etc/raddb/mods-enabled/chap including configuration file /usr/local/etc/raddb/mods-enabled/date including configuration file /usr/local/etc/raddb/mods-enabled/detail including configuration file /usr/local/etc/raddb/mods-enabled/detail.log including configuration file /usr/local/etc/raddb/mods-enabled/dhcp including configuration file /usr/local/etc/raddb/mods-enabled/digest including configuration file /usr/local/etc/raddb/mods-enabled/dynamic_clients including configuration file /usr/local/etc/raddb/mods-enabled/eap including configuration file /usr/local/etc/raddb/mods-enabled/echo including configuration file /usr/local/etc/raddb/mods-enabled/exec including configuration file /usr/local/etc/raddb/mods-enabled/expiration including configuration file /usr/local/etc/raddb/mods-enabled/expr including configuration file /usr/local/etc/raddb/mods-enabled/files including configuration file /usr/local/etc/raddb/mods-enabled/linelog including configuration file /usr/local/etc/raddb/mods-enabled/logintime including configuration file /usr/local/etc/raddb/mods-enabled/mschap including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth including configuration file /usr/local/etc/raddb/mods-enabled/pap including configuration file /usr/local/etc/raddb/mods-enabled/passwd including configuration file /usr/local/etc/raddb/mods-enabled/preprocess including configuration file /usr/local/etc/raddb/mods-enabled/radutmp including configuration file /usr/local/etc/raddb/mods-enabled/realm including configuration file /usr/local/etc/raddb/mods-enabled/replicate including configuration file /usr/local/etc/raddb/mods-enabled/soh including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp including configuration file /usr/local/etc/raddb/mods-enabled/always including configuration file /usr/local/etc/raddb/mods-enabled/unix including configuration file /usr/local/etc/raddb/mods-enabled/unpack including configuration file /usr/local/etc/raddb/mods-enabled/utf8 including configuration file /usr/local/etc/raddb/mods-enabled/motp including configuration file /usr/local/etc/raddb/mods-enabled/googleauth including configuration file /usr/local/etc/raddb/mods-enabled/datacounter_acct including configuration file /usr/local/etc/raddb/mods-enabled/sql including configuration file /usr/local/etc/raddb/mods-config/sql/main/mysql/queries.conf including configuration file /usr/local/etc/raddb/mods-enabled/sqlcounter including configuration file /usr/local/etc/raddb/mods-config/sql/counter/mysql/dailycounter.conf including configuration file /usr/local/etc/raddb/mods-config/sql/counter/mysql/monthlycounter.conf including configuration file /usr/local/etc/raddb/mods-config/sql/counter/mysql/noresetcounter.conf including configuration file /usr/local/etc/raddb/mods-config/sql/counter/mysql/expire_on_login.conf including files in directory /usr/local/etc/raddb/policy.d/ including configuration file /usr/local/etc/raddb/policy.d/accounting including configuration file /usr/local/etc/raddb/policy.d/canonicalization including configuration file /usr/local/etc/raddb/policy.d/control including configuration file /usr/local/etc/raddb/policy.d/cui including configuration file /usr/local/etc/raddb/policy.d/debug including configuration file /usr/local/etc/raddb/policy.d/dhcp including configuration file /usr/local/etc/raddb/policy.d/eap including configuration file /usr/local/etc/raddb/policy.d/filter including configuration file /usr/local/etc/raddb/policy.d/moonshot-targeted-ids including configuration file /usr/local/etc/raddb/policy.d/operator-name including configuration file /usr/local/etc/raddb/policy.d/abfab-tr including configuration file /usr/local/etc/raddb/policy.d/pfs_custom_policies including files in directory /usr/local/etc/raddb/sites-enabled/ including configuration file /usr/local/etc/raddb/sites-enabled/default including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel-peap including configuration file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls main { security { allow_core_dumps = no } name = "radiusd" prefix = "/usr/local" localstatedir = "/var" logdir = "/var/log" run_dir = "/var/run" } main { name = "radiusd" prefix = "/usr/local" localstatedir = "/var" sbindir = "/usr/local/sbin" logdir = "/var/log" run_dir = "/var/run" libdir = "/usr/local/lib/freeradius-3.0.15" radacctdir = "/var/log/radacct" hostname_lookups = no max_request_time = 30 cleanup_delay = 5 max_requests = 36864 pidfile = "/var/run/radiusd.pid" checkrad = "/usr/local/sbin/checkrad" debug_level = 0 proxy_requests = yes log { stripped_names = no auth = yes auth_badpass = no auth_goodpass = no msg_badpass = "" msg_goodpass = "" colourise = yes msg_denied = "You are already logged in - access denied" } resources { } security { max_attributes = 200 reject_delay = 3.000000 status_server = no allow_vulnerable_openssl = "yes" } } radiusd: #### Loading Realms and Home Servers #### radiusd: #### Loading Clients #### client pfsense { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> shortname = "pfsense" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } Debugger not attached # Creating Auth-Type = pap # Creating Auth-Type = eap # Creating Auth-Type = mschap # Creating Auth-Type = MS-CHAP # Creating Auth-Type = CHAP radiusd: #### Instantiating modules #### modules { # Loaded module rlm_attr_filter # Loading module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.post-proxy { filename = "/usr/local/etc/raddb/mods-config/attr_filter/post-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.pre-proxy { filename = "/usr/local/etc/raddb/mods-config/attr_filter/pre-proxy" key = "%{Realm}" relaxed = no } # Loading module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.access_reject { filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_reject" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.access_challenge { filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_challenge" key = "%{User-Name}" relaxed = no } # Loading module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.accounting_response { filename = "/usr/local/etc/raddb/mods-config/attr_filter/accounting_response" key = "%{User-Name}" relaxed = no } # Loaded module rlm_cache # Loading module "cache_eap" from file /usr/local/etc/raddb/mods-enabled/cache_eap cache cache_eap { driver = "rlm_cache_rbtree" key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}" ttl = 15 max_entries = 0 epoch = 0 add_stats = no } # Loaded module rlm_chap # Loading module "chap" from file /usr/local/etc/raddb/mods-enabled/chap # Loaded module rlm_date # Loading module "date" from file /usr/local/etc/raddb/mods-enabled/date date { format = "%b %e %Y %H:%M:%S %Z" utc = no } # Loaded module rlm_detail # Loading module "detail" from file /usr/local/etc/raddb/mods-enabled/detail detail { filename = "/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail auth_log { filename = "/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail reply_log { filename = "/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail pre_proxy_log { filename = "/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loading module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail post_proxy_log { filename = "/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" header = "%t" permissions = 384 locking = no escape_filenames = no log_packet_header = no } # Loaded module rlm_dhcp # Loading module "dhcp" from file /usr/local/etc/raddb/mods-enabled/dhcp # Loaded module rlm_digest # Loading module "digest" from file /usr/local/etc/raddb/mods-enabled/digest # Loaded module rlm_dynamic_clients # Loading module "dynamic_clients" from file /usr/local/etc/raddb/mods-enabled/dynamic_clients # Loaded module rlm_eap # Loading module "eap" from file /usr/local/etc/raddb/mods-enabled/eap eap { default_eap_type = "ttls" timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = 4096 } # Loaded module rlm_exec # Loading module "echo" from file /usr/local/etc/raddb/mods-enabled/echo exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = "request" output_pairs = "reply" shell_escape = yes } # Loading module "exec" from file /usr/local/etc/raddb/mods-enabled/exec exec { wait = no input_pairs = "request" shell_escape = yes timeout = 10 } # Loaded module rlm_expiration # Loading module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration # Loaded module rlm_expr # Loading module "expr" from file /usr/local/etc/raddb/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /äéöüàâæçèéêëîïôSùûüa ÄÉÖÜßÀÂÆÇÈÉÊËÎÏÔRÙÛÜx" } # Loaded module rlm_files # Loading module "files" from file /usr/local/etc/raddb/mods-enabled/files files { filename = "/usr/local/etc/raddb/mods-config/files/authorize" acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting" preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy" } # Loaded module rlm_linelog # Loading module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog linelog { filename = "/var/log/linelog" escape_filenames = no syslog_severity = "info" permissions = 384 format = "This is a log message for %{User-Name}" reference = "messages.%{%{reply:Packet-Type}:-default}" } # Loading module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog linelog log_accounting { filename = "/var/log/linelog-accounting" escape_filenames = no syslog_severity = "info" permissions = 384 format = "" reference = "Accounting-Request.%{%{Acct-Status-Type}:-unknown}" } # Loaded module rlm_logintime # Loading module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime logintime { minimum_timeout = 60 } # Loaded module rlm_mschap # Loading module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap mschap { use_mppe = yes require_encryption = no require_strong = no with_ntdomain_hack = yes passchange { } allow_retry = yes winbind_retry_with_normalised_username = no } # Loading module "ntlm_auth" from file /usr/local/etc/raddb/mods-enabled/ntlm_auth exec ntlm_auth { wait = yes program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" shell_escape = yes } # Loaded module rlm_pap # Loading module "pap" from file /usr/local/etc/raddb/mods-enabled/pap pap { normalise = yes } # Loaded module rlm_passwd # Loading module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd passwd etc_passwd { filename = "/etc/passwd" format = "*User-Name:Crypt-Password:" delimiter = ":" ignore_nislike = no ignore_empty = yes allow_multiple_keys = no hash_size = 100 } # Loaded module rlm_preprocess # Loading module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess preprocess { huntgroups = "/usr/local/etc/raddb/mods-config/preprocess/huntgroups" hints = "/usr/local/etc/raddb/mods-config/preprocess/hints" 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_radutmp # Loading module "radutmp" from file /usr/local/etc/raddb/mods-enabled/radutmp radutmp { filename = "/var/log/radutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 384 caller_id = yes } # Loaded module rlm_realm # Loading module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm realm IPASS { format = "prefix" delimiter = "/" ignore_default = no ignore_null = yes } # Loading module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = yes } # Loading module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm realm realmpercent { format = "suffix" delimiter = "%" ignore_default = no ignore_null = yes } # Loading module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm realm ntdomain { format = "prefix" delimiter = "\" ignore_default = no ignore_null = yes } # Loaded module rlm_replicate # Loading module "replicate" from file /usr/local/etc/raddb/mods-enabled/replicate # Loaded module rlm_soh # Loading module "soh" from file /usr/local/etc/raddb/mods-enabled/soh soh { dhcp = yes } # Loading module "sradutmp" from file /usr/local/etc/raddb/mods-enabled/sradutmp radutmp sradutmp { filename = "/var/log/sradutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 420 caller_id = no } # Loaded module rlm_always # Loading module "reject" from file /usr/local/etc/raddb/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Loading module "fail" from file /usr/local/etc/raddb/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Loading module "ok" from file /usr/local/etc/raddb/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Loading module "handled" from file /usr/local/etc/raddb/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Loading module "invalid" from file /usr/local/etc/raddb/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Loading module "userlock" from file /usr/local/etc/raddb/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Loading module "notfound" from file /usr/local/etc/raddb/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Loading module "noop" from file /usr/local/etc/raddb/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Loading module "updated" from file /usr/local/etc/raddb/mods-enabled/always always updated { rcode = "updated" simulcount = 0 mpp = no } # Loaded module rlm_unix # Loading module "unix" from file /usr/local/etc/raddb/mods-enabled/unix unix { radwtmp = "/var/log/radwtmp" } Creating attribute Unix-Group # Loaded module rlm_unpack # Loading module "unpack" from file /usr/local/etc/raddb/mods-enabled/unpack # Loaded module rlm_utf8 # Loading module "utf8" from file /usr/local/etc/raddb/mods-enabled/utf8 # Loading module "motp" from file /usr/local/etc/raddb/mods-enabled/motp exec motp { wait = yes program = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/otpverify.sh %{request:User-Name} %{request:User-Password} %{reply:MOTP-Init-Secret} %{reply:MOTP-PIN} %{ reply:MOTP-Offset}" shell_escape = yes } # Loading module "googleauth" from file /usr/local/etc/raddb/mods-enabled/googleauth exec googleauth { wait = yes program = "/usr/local/etc/raddb/scripts/googleauth.py %{request:User-Name} %{reply:MOTP-Init-Secret} %{reply:MOTP-PIN} %{request:User-Password}" shell_escape = yes } # Loading module "check_quota" from file /usr/local/etc/raddb/mods-enabled/datacounter_acct exec check_quota { wait = no program = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_acct.sh %{request:User-Name} %{request:Calling-Station-Id} %{request:NAS-IP-Address} %{reques t:Class} %{request:Acct-Status-Type}" shell_escape = yes } # Loaded module rlm_sql # Loading module "sql1" from file /usr/local/etc/raddb/mods-enabled/sql sql sql1 { driver = "rlm_sql_mysql" server = "localhost" port = 33316 login = "raduser" password = <<< secret >>> radius_db = "raddb3" read_groups = yes read_profiles = yes read_clients = yes delete_stale_sessions = yes sql_user_name = "%{User-Name}" logfile = "/var/log/sqltrace.sql" default_user_profile = "" client_query = "CALL load_clients()" authorize_check_query = "CALL authorize_check('%{SQL-User-Name}')" authorize_reply_query = "CALL authorize_reply('%{SQL-User-Name}')" authorize_group_check_query = "CALL authorize_group_check('%{sql1-SQL-Group}')" authorize_group_reply_query = "CALL authorize_group_reply('%{sql1-SQL-Group}')" group_membership_query = "CALL group_membership('%{SQL-User-Name}')" simul_count_query = "CALL simul_count('%{SQL-User-Name}')" safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_" accounting { reference = "%{tolower:type.%{Acct-Status-Type}.query}" type { accounting-on { query = "CALL accounting_on('%{Called-Station-Id}')" } accounting-off { query = "CALL accounting_off('%{Called-Station-Id}')" } start { query = "CALL accounting_start('%{Acct-Session-Id}','%{SQL-User-Name}','%{Class}','%{NAS-IP-Address}','%{Called-Station-Id}','%{Calling-Station-Id}')" } interim-update { query = "CALL accounting_update ('%{Acct-Session-Id}','%{Called-Station-Id}','%{Calling-Station-Id}','%{Acct-Session-Time}','%{Acct-Input-Octets}','%{Acct-Input-Giga words}','%{Acct-Output-Octets}','%{Acct-Output-Gigawords}')" } stop { query = "CALL accounting_stop ('%{Acct-Session-Id}','%{SQL-User-Name}','%{Called-Station-Id}','%{Calling-Station-Id}','%{Acct-Session-Time}','%{Acct-Input-Octets}',' %{Acct-Input-Gigawords}','%{Acct-Output-Octets}','%{Acct-Output-Gigawords}','%{Acct-Terminate-Cause}')" } } } post-auth { reference = ".query" } } rlm_sql (sql1): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Creating attribute sql1-SQL-Group # Loaded module rlm_sqlcounter # Loading module "dailycounter" from file /usr/local/etc/raddb/mods-enabled/sqlcounter sqlcounter dailycounter { sql_module_instance = "sql" key = "User-Name" query = "SELECT SUM(acctsessiontime - GREATEST((%%b - UNIX_TIMESTAMP(acctstarttime)), 0)) FROM radacct WHERE username = '%{User-Name}' AND UNIX_TIMESTAMP(acctstartti me) + acctsessiontime > '%%b'" reset = "daily" counter_name = "Daily-Session-Time" check_name = "Max-Daily-Session" reply_name = "Session-Timeout" } # Loading module "monthlycounter" from file /usr/local/etc/raddb/mods-enabled/sqlcounter sqlcounter monthlycounter { sql_module_instance = "sql" key = "User-Name" query = "SELECT SUM(acctsessiontime - GREATEST((%%b - UNIX_TIMESTAMP(acctstarttime)), 0)) FROM radacct WHERE username='%{User-Name}' AND UNIX_TIMESTAMP(acctstarttime ) + acctsessiontime > '%%b'" reset = "monthly" counter_name = "Monthly-Session-Time" check_name = "Max-Monthly-Session" reply_name = "Session-Timeout" } # Loading module "noresetcounter" from file /usr/local/etc/raddb/mods-enabled/sqlcounter sqlcounter noresetcounter { sql_module_instance = "sql" key = "User-Name" query = "SELECT IFNULL(SUM(AcctSessionTime),0) FROM radacct WHERE UserName='%{User-Name}'" reset = "never" counter_name = "Max-All-Session-Time" check_name = "Max-All-Session" reply_name = "Session-Timeout" } # Loading module "expire_on_login" from file /usr/local/etc/raddb/mods-enabled/sqlcounter sqlcounter expire_on_login { sql_module_instance = "sql" key = "User-Name" query = "SELECT IFNULL( MAX(TIME_TO_SEC(TIMEDIFF(NOW(), acctstarttime))),0) FROM radacct WHERE UserName='%{User-Name}' ORDER BY acctstarttime LIMIT 1;" reset = "never" counter_name = "Expire-After-Initial-Login" check_name = "Expire-After" reply_name = "Session-Timeout" } instantiate { # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime # Instantiating module "sql1" from file /usr/local/etc/raddb/mods-enabled/sql rlm_sql_mysql: libmysql version: 5.6.35 mysql { tls { } warnings = "auto" } rlm_sql (sql1): Attempting to connect to database "raddb3" rlm_sql (sql1): Initialising connection pool pool { start = 32 min = 16 max = 16 spare = 32 uses = 0 lifetime = 0 cleanup_interval = 30 idle_timeout = 60 retry_delay = 60 spread = no } WARNING: Ignoring "start = 32", forcing to "start = 16" WARNING: Ignoring "spare = 32", forcing to "spare = 0" rlm_sql (sql1): Opening additional connection (0), 1 of 16 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (1), 1 of 15 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (2), 1 of 14 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (3), 1 of 13 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (4), 1 of 12 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (5), 1 of 11 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (6), 1 of 10 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (7), 1 of 9 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (8), 1 of 8 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (9), 1 of 7 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (10), 1 of 6 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (11), 1 of 5 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (12), 1 of 4 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (13), 1 of 3 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (14), 1 of 2 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Opening additional connection (15), 1 of 1 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 rlm_sql (sql1): Processing generate_sql_clients rlm_sql (sql1) in generate_sql_clients: query is CALL load_clients() rlm_sql (sql1): Reserved connection (0) rlm_sql (sql1): Executing select query: CALL load_clients() rlm_sql (sql1): Adding client 192.168.0.4 (HOME_AP) to global clients list rlm_sql (192.168.0.4): Client "HOME_AP" (sql1) added rlm_sql (sql1): Released connection (0) } # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_reject [/usr/local/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". [/usr/local/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response # Instantiating module "cache_eap" from file /usr/local/etc/raddb/mods-enabled/cache_eap rlm_cache (cache_eap): Driver rlm_cache_rbtree (module rlm_cache_rbtree) loaded and linked # Instantiating module "detail" from file /usr/local/etc/raddb/mods-enabled/detail # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log # Instantiating module "eap" from file /usr/local/etc/raddb/mods-enabled/eap # Linked to sub-module rlm_eap_tls tls { tls = "tls-common" } tls-config tls-common { verify_depth = 0 ca_path = "/usr/local/etc/raddb/certs" pem_file_type = yes private_key_file = "/usr/local/etc/raddb/certs/server_key.pem" certificate_file = "/usr/local/etc/raddb/certs/server_cert.pem" ca_file = "/usr/local/etc/raddb/certs/ca_cert.pem" dh_file = "/usr/local/etc/raddb/certs/dh" random_file = "/dev/urandom" fragment_size = 1024 include_length = yes auto_chain = yes check_crl = no check_all_crl = no cipher_list = "DEFAULT" cipher_server_preference = no ecdh_curve = "prime256v1" cache { enable = no lifetime = 24 max_entries = 255 } verify { skip_if_ocsp_ok = no } ocsp { enable = no override_cert_url = no url = "http://127.0.0.1/ocsp/"<http://127.0.0.1/ocsp/> use_nonce = yes timeout = 0 softfail = no } } # Linked to sub-module rlm_eap_ttls ttls { tls = "tls-common" default_eap_type = "tls" copy_request_to_tunnel = yes use_tunneled_reply = no virtual_server = "inner-tunnel-ttls" include_length = yes require_client_cert = no } tls: Using cached TLS configuration from previous invocation # Linked to sub-module rlm_eap_peap peap { tls = "tls-common" default_eap_type = "tls" copy_request_to_tunnel = yes use_tunneled_reply = no proxy_tunneled_request_as_eap = yes virtual_server = "inner-tunnel-peap" soh = no require_client_cert = no } tls: Using cached TLS configuration from previous invocation # Linked to sub-module rlm_eap_mschapv2 mschapv2 { with_ntdomain_hack = no send_error = no } # Instantiating module "files" from file /usr/local/etc/raddb/mods-enabled/files reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize reading pairlist file /usr/local/etc/raddb/mods-config/files/accounting reading pairlist file /usr/local/etc/raddb/mods-config/files/pre-proxy # Instantiating module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog # Instantiating module "log_accounting" from file /usr/local/etc/raddb/mods-enabled/linelog # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap rlm_mschap (mschap): using internal authentication # Instantiating module "pap" from file /usr/local/etc/raddb/mods-enabled/pap # Instantiating module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/huntgroups reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/hints # Instantiating module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm # Instantiating module "reject" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "fail" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "ok" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "handled" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "noop" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "updated" from file /usr/local/etc/raddb/mods-enabled/always # Instantiating module "dailycounter" from file /usr/local/etc/raddb/mods-enabled/sqlcounter rlm_sqlcounter: Current Time: 1502046043 [2017-08-06 22:00:43], Prev reset 1501966800 [2017-08-06 00:00:00] # Instantiating module "monthlycounter" from file /usr/local/etc/raddb/mods-enabled/sqlcounter rlm_sqlcounter: Current Time: 1502046043 [2017-08-06 22:00:43], Prev reset 1501534800 [2017-08-01 00:00:00] # Instantiating module "noresetcounter" from file /usr/local/etc/raddb/mods-enabled/sqlcounter rlm_sqlcounter: Current Time: 1502046043 [2017-08-06 22:00:43], Prev reset 0 [2017-08-06 22:00:00] # Instantiating module "expire_on_login" from file /usr/local/etc/raddb/mods-enabled/sqlcounter rlm_sqlcounter: Current Time: 1502046043 [2017-08-06 22:00:43], Prev reset 0 [2017-08-06 22:00:00] } # modules radiusd: #### Loading Virtual Servers #### server { # from file /usr/local/etc/raddb/radiusd.conf } # server server default { # from file /usr/local/etc/raddb/sites-enabled/default # Loading authenticate {...} # Loading authorize {...} # Loading preacct {...} # Loading accounting {...} # Loading session {...} # Loading post-proxy {...} # Loading post-auth {...} } # server default server inner-tunnel-peap { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-peap # Loading authenticate {...} # Loading authorize {...} # Loading session {...} # Loading post-proxy {...} # Loading post-auth {...} } # server inner-tunnel-peap server inner-tunnel-ttls { # from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls # Loading authenticate {...} # Loading authorize {...} # Loading session {...} # Loading post-proxy {...} # Loading post-auth {...} } # server inner-tunnel-ttls radiusd: #### Opening IP addresses and Ports #### listen { type = "auth" ipaddr = 192.168.0.1 port = 1812 } listen { type = "acct" ipaddr = 192.168.0.1 port = 1813 } listen { type = "auth" ipaddr = 127.0.0.1 port = 18128 } listen { type = "auth" ipaddr = 127.0.0.1 port = 18127 } Listening on auth address 192.168.0.1 port 1812 bound to server default Listening on acct address 192.168.0.1 port 1813 bound to server default Listening on auth address 127.0.0.1 port 18128 bound to server inner-tunnel-peap Listening on auth address 127.0.0.1 port 18127 bound to server inner-tunnel-ttls Ready to process requests (0) Received Accounting-Request Id 147 from 192.168.0.4:44463 to 192.168.0.1:1813 length 208 (0) Acct-Session-Id = "59873E49-00000019" (0) Acct-Status-Type = Stop (0) Acct-Authentic = RADIUS (0) User-Name = "anonymous" (0) Framed-IP-Address = 192.168.0.104 (0) NAS-Identifier = "802aa8ac1ef9" (0) NAS-Port = 0 (0) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (0) Calling-Station-Id = "00-22-FA-F5-B9-0A" (0) NAS-Port-Type = Wireless-802.11 (0) Connect-Info = "CONNECT 0Mbps 802.11b" (0) Acct-Session-Time = 51 (0) Acct-Input-Packets = 176 (0) Acct-Output-Packets = 22 (0) Acct-Input-Octets = 16127 (0) Acct-Output-Octets = 4777 (0) Event-Timestamp = "Aug 6 2017 22:00:04 +03" (0) Acct-Terminate-Cause = User-Request (0) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (0) preacct { (0) [preprocess] = ok (0) } # preacct = ok (0) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (0) accounting { (0) detail: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d (0) detail: --> /var/log/radacct/192.168.0.4/detail_2017_08_06 (0) detail: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d expands to /var/log/radacct/192.168.0.4/detail_2017_08_06 (0) detail: EXPAND %t (0) detail: --> Sun Aug 6 22:00:54 2017 (0) [detail] = ok (0) redundant sql { (0) sql1: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (0) sql1: --> type.stop.query (0) sql1: Using query template 'query' rlm_sql (sql1): Reserved connection (1) (0) sql1: EXPAND %{User-Name} (0) sql1: --> anonymous (0) sql1: SQL-User-Name set to 'anonymous' (0) sql1: EXPAND CALL accounting_stop ('%{Acct-Session-Id}','%{SQL-User-Name}','%{Called-Station-Id}','%{Calling-Station-Id}','%{Acct-Session-Time}','%{Acct-Input-Octets}',' %{Acct-Input-Gigawords}','%{Acct-Output-Octets}','%{Acct-Output-Gigawords}','%{Acct-Terminate-Cause}') (0) sql1: --> CALL accounting_stop ('59873E49-00000019','anonymous','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A','51','16127','','4777','','User-Request') (0) sql1: EXPAND /var/log/sqltrace.sql (0) sql1: --> /var/log/sqltrace.sql (0) sql1: Executing query: CALL accounting_stop ('59873E49-00000019','anonymous','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A','51','16127','','4777','','User-Request ') (0) sql1: SQL query returned: success (0) sql1: 1 record(s) updated rlm_sql (sql1): Released connection (1) (0) [sql1] = ok (0) } # redundant sql = ok (0) [exec] = noop (0) if (request:Acct-Status-Type == Interim-Update) { (0) if (request:Acct-Status-Type == Interim-Update) -> FALSE (0) } # accounting = ok (0) Sent Accounting-Response Id 147 from 192.168.0.1:1813 to 192.168.0.4:44463 length 0 (0) Finished request (0) Cleaning up request packet ID 147 with timestamp +11 Ready to process requests (1) Received Access-Request Id 148 from 192.168.0.4:37009 to 192.168.0.1:1812 length 163 (1) User-Name = "scilek" (1) NAS-Identifier = "802aa8ac1ef9" (1) NAS-Port = 0 (1) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (1) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (1) Framed-MTU = 1400 (1) NAS-Port-Type = Wireless-802.11 (1) Connect-Info = "CONNECT 0Mbps 802.11b" (1) EAP-Message = 0x02b6000b017363696c656b (1) Message-Authenticator = 0xecd086e7eb7d720848f759fbea3e68dd (1) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (1) authorize { (1) [preprocess] = ok (1) redundant sql { (1) sql1: EXPAND %{User-Name} (1) sql1: --> scilek (1) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (2) (1) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (1) sql1: --> CALL authorize_check('scilek') (1) sql1: Executing select query: CALL authorize_check('scilek') (1) sql1: User found in radcheck table (1) sql1: Conditional check items matched, merging assignment check items (1) sql1: Cleartext-Password := "0000" (1) sql1: Simultaneous-Use := 1 (1) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (1) sql1: --> CALL authorize_reply('scilek') (1) sql1: Executing select query: CALL authorize_reply('scilek') (1) sql1: User found in radreply table, merging reply items (1) sql1: Class := 0x7363696c656b (1) sql1: Idle-Timeout := 120 (1) sql1: Acct-Interim-Interval := 600 (1) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (1) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (1) sql1: --> CALL group_membership('scilek') (1) sql1: Executing select query: CALL group_membership('scilek') (1) sql1: User not found in any groups rlm_sql (sql1): Released connection (2) (1) [sql1] = ok (1) } # redundant sql = ok (1) pap: No User-Password attribute in the request. Cannot do PAP (1) [pap] = noop (1) eap: Peer sent EAP Response (code 2) ID 182 length 11 (1) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (1) [eap] = ok (1) } # authorize = ok (1) Found Auth-Type = eap (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (1) authenticate { (1) eap: Peer sent packet with method EAP Identity (1) (1) eap: Calling submodule eap_ttls to process data (1) eap_ttls: Initiating new EAP-TLS session (1) eap_ttls: [eaptls start] = request (1) eap: Sending EAP Request (code 1) ID 183 length 6 (1) eap: EAP session adding &reply:State = 0x04505bcc04e74ea0 (1) [eap] = handled (1) } # authenticate = handled (1) Using Post-Auth-Type Challenge (1) Post-Auth-Type sub-section not found. Ignoring. (1) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (1) Sent Access-Challenge Id 148 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (1) Class = 0x7363696c656b (1) Idle-Timeout = 120 (1) Acct-Interim-Interval = 600 (1) EAP-Message = 0x01b700061520 (1) Message-Authenticator = 0x00000000000000000000000000000000 (1) State = 0x04505bcc04e74ea0e22d93a65254c60e (1) Finished request Waking up in 4.9 seconds. (2) Received Access-Request Id 149 from 192.168.0.4:37009 to 192.168.0.1:1812 length 297 (2) User-Name = "scilek" (2) NAS-Identifier = "802aa8ac1ef9" (2) NAS-Port = 0 (2) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (2) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (2) Framed-MTU = 1400 (2) NAS-Port-Type = Wireless-802.11 (2) Connect-Info = "CONNECT 0Mbps 802.11b" (2) EAP-Message = 0x02b7007f15800000007516030100700100006c030159876769a174d1b43f51e91a68364f8fe5c039642809fc74205540b4eaa79c9600002000ffc024c023c00ac009c008c028c027c014c01 3c012003d003c0035002f000a01000023000a00080006001700180019000b00020100000500050100000000 (2) State = 0x04505bcc04e74ea0e22d93a65254c60e (2) Message-Authenticator = 0x4a0a55f0a010a073bf4399b9bf683ec3 (2) session-state: No cached attributes (2) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (2) authorize { (2) [preprocess] = ok (2) redundant sql { (2) sql1: EXPAND %{User-Name} (2) sql1: --> scilek (2) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (3) (2) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (2) sql1: --> CALL authorize_check('scilek') (2) sql1: Executing select query: CALL authorize_check('scilek') (2) sql1: User found in radcheck table (2) sql1: Conditional check items matched, merging assignment check items (2) sql1: Cleartext-Password := "0000" (2) sql1: Simultaneous-Use := 1 (2) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (2) sql1: --> CALL authorize_reply('scilek') (2) sql1: Executing select query: CALL authorize_reply('scilek') (2) sql1: User found in radreply table, merging reply items (2) sql1: Class := 0x7363696c656b (2) sql1: Idle-Timeout := 120 (2) sql1: Acct-Interim-Interval := 600 (2) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (2) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (2) sql1: --> CALL group_membership('scilek') (2) sql1: Executing select query: CALL group_membership('scilek') (2) sql1: User not found in any groups rlm_sql (sql1): Released connection (3) (2) [sql1] = ok (2) } # redundant sql = ok (2) pap: No User-Password attribute in the request. Cannot do PAP (2) [pap] = noop (2) eap: Peer sent EAP Response (code 2) ID 183 length 127 (2) eap: Continuing tunnel setup (2) [eap] = ok (2) } # authorize = ok (2) Found Auth-Type = eap (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (2) authenticate { (2) eap: Expiring EAP session with state 0x04505bcc04e74ea0 (2) eap: Finished EAP session with state 0x04505bcc04e74ea0 (2) eap: Previous EAP request found for state 0x04505bcc04e74ea0, released from the list (2) eap: Peer sent packet with method EAP TTLS (21) (2) eap: Calling submodule eap_ttls to process data (2) eap_ttls: Authenticate (2) eap_ttls: Continuing EAP-TLS (2) eap_ttls: Peer indicated complete TLS record size will be 117 bytes (2) eap_ttls: Got complete TLS record (117 bytes) (2) eap_ttls: [eaptls verify] = length included (2) eap_ttls: (other): before/accept initialization (2) eap_ttls: TLS_accept: before/accept initialization (2) eap_ttls: <<< recv TLS 1.0 Handshake [length 0070], ClientHello (2) eap_ttls: TLS_accept: SSLv3 read client hello A (2) eap_ttls: >>> send TLS 1.0 Handshake [length 0039], ServerHello (2) eap_ttls: TLS_accept: SSLv3 write server hello A (2) eap_ttls: >>> send TLS 1.0 Handshake [length 09de], Certificate (2) eap_ttls: TLS_accept: SSLv3 write certificate A (2) eap_ttls: >>> send TLS 1.0 Handshake [length 014b], ServerKeyExchange (2) eap_ttls: TLS_accept: SSLv3 write key exchange A (2) eap_ttls: >>> send TLS 1.0 Handshake [length 0004], ServerHelloDone (2) eap_ttls: TLS_accept: SSLv3 write server done A (2) eap_ttls: TLS_accept: SSLv3 flush data (2) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A (2) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A (2) eap_ttls: In SSL Handshake Phase (2) eap_ttls: In SSL Accept mode (2) eap_ttls: [eaptls process] = handled (2) eap: Sending EAP Request (code 1) ID 184 length 1004 (2) eap: EAP session adding &reply:State = 0x04505bcc05e84ea0 (2) [eap] = handled (2) } # authenticate = handled (2) Using Post-Auth-Type Challenge (2) Post-Auth-Type sub-section not found. Ignoring. (2) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (2) Sent Access-Challenge Id 149 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (2) Class = 0x7363696c656b (2) Idle-Timeout = 120 (2) Acct-Interim-Interval = 600 (2) EAP-Message = 0x01b803ec15c000000b7a160301003902000035030155db105da8ad066200feca07bf619b9573fcfb7388515a37695fd8d75b5675c400c01400000dff01000100000b0004030001021603010 9de0b0009da0009d70005333082052f30820417a003020102020103300d06092a864886f70d01010b050030 (2) Message-Authenticator = 0x00000000000000000000000000000000 (2) State = 0x04505bcc05e84ea0e22d93a65254c60e (2) Finished request Waking up in 4.9 seconds. (3) Received Access-Request Id 150 from 192.168.0.4:37009 to 192.168.0.1:1812 length 176 (3) User-Name = "scilek" (3) NAS-Identifier = "802aa8ac1ef9" (3) NAS-Port = 0 (3) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (3) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (3) Framed-MTU = 1400 (3) NAS-Port-Type = Wireless-802.11 (3) Connect-Info = "CONNECT 0Mbps 802.11b" (3) EAP-Message = 0x02b800061500 (3) State = 0x04505bcc05e84ea0e22d93a65254c60e (3) Message-Authenticator = 0x45a91ad09cc1e4c9a5f76538b1a75bdf (3) session-state: No cached attributes (3) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (3) authorize { (3) [preprocess] = ok (3) redundant sql { (3) sql1: EXPAND %{User-Name} (3) sql1: --> scilek (3) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (4) (3) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (3) sql1: --> CALL authorize_check('scilek') (3) sql1: Executing select query: CALL authorize_check('scilek') (3) sql1: User found in radcheck table (3) sql1: Conditional check items matched, merging assignment check items (3) sql1: Cleartext-Password := "0000" (3) sql1: Simultaneous-Use := 1 (3) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (3) sql1: --> CALL authorize_reply('scilek') (3) sql1: Executing select query: CALL authorize_reply('scilek') (3) sql1: User found in radreply table, merging reply items (3) sql1: Class := 0x7363696c656b (3) sql1: Idle-Timeout := 120 (3) sql1: Acct-Interim-Interval := 600 (3) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (3) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (3) sql1: --> CALL group_membership('scilek') (3) sql1: Executing select query: CALL group_membership('scilek') (3) sql1: User not found in any groups rlm_sql (sql1): Released connection (4) (3) [sql1] = ok (3) } # redundant sql = ok (3) pap: No User-Password attribute in the request. Cannot do PAP (3) [pap] = noop (3) eap: Peer sent EAP Response (code 2) ID 184 length 6 (3) eap: Continuing tunnel setup (3) [eap] = ok (3) } # authorize = ok (3) Found Auth-Type = eap (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) authenticate { (3) eap: Expiring EAP session with state 0x04505bcc05e84ea0 (3) eap: Finished EAP session with state 0x04505bcc05e84ea0 (3) eap: Previous EAP request found for state 0x04505bcc05e84ea0, released from the list (3) eap: Peer sent packet with method EAP TTLS (21) (3) eap: Calling submodule eap_ttls to process data (3) eap_ttls: Authenticate (3) eap_ttls: Continuing EAP-TLS (3) eap_ttls: Peer ACKed our handshake fragment (3) eap_ttls: [eaptls verify] = request (3) eap_ttls: [eaptls process] = handled (3) eap: Sending EAP Request (code 1) ID 185 length 1004 (3) eap: EAP session adding &reply:State = 0x04505bcc06e94ea0 (3) [eap] = handled (3) } # authenticate = handled (3) Using Post-Auth-Type Challenge (3) Post-Auth-Type sub-section not found. Ignoring. (3) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (3) Sent Access-Challenge Id 150 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (3) Class = 0x7363696c656b (3) Idle-Timeout = 120 (3) Acct-Interim-Interval = 600 (3) EAP-Message = 0x01b903ec15c000000b7a864886f70d010901161c73656c6168617474696e5f63696c656b40686f746d61696c2e636f6d3111300f0603550403130864616d6c612d6361820100301d0603551 d250416301406082b0601050507030106082b06010505080202300b0603551d0f0404030205a03020060355 (3) Message-Authenticator = 0x00000000000000000000000000000000 (3) State = 0x04505bcc06e94ea0e22d93a65254c60e (3) Finished request Waking up in 4.9 seconds. (4) Received Access-Request Id 151 from 192.168.0.4:37009 to 192.168.0.1:1812 length 176 (4) User-Name = "scilek" (4) NAS-Identifier = "802aa8ac1ef9" (4) NAS-Port = 0 (4) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (4) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (4) Framed-MTU = 1400 (4) NAS-Port-Type = Wireless-802.11 (4) Connect-Info = "CONNECT 0Mbps 802.11b" (4) EAP-Message = 0x02b900061500 (4) State = 0x04505bcc06e94ea0e22d93a65254c60e (4) Message-Authenticator = 0xb7b7deb80f22c03b7b67284e31aedfe7 (4) session-state: No cached attributes (4) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (4) authorize { (4) [preprocess] = ok (4) redundant sql { (4) sql1: EXPAND %{User-Name} (4) sql1: --> scilek (4) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (5) (4) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (4) sql1: --> CALL authorize_check('scilek') (4) sql1: Executing select query: CALL authorize_check('scilek') (4) sql1: User found in radcheck table (4) sql1: Conditional check items matched, merging assignment check items (4) sql1: Cleartext-Password := "0000" (4) sql1: Simultaneous-Use := 1 (4) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (4) sql1: --> CALL authorize_reply('scilek') (4) sql1: Executing select query: CALL authorize_reply('scilek') (4) sql1: User found in radreply table, merging reply items (4) sql1: Class := 0x7363696c656b (4) sql1: Idle-Timeout := 120 (4) sql1: Acct-Interim-Interval := 600 (4) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (4) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (4) sql1: --> CALL group_membership('scilek') (4) sql1: Executing select query: CALL group_membership('scilek') (4) sql1: User not found in any groups rlm_sql (sql1): Released connection (5) (4) [sql1] = ok (4) } # redundant sql = ok (4) pap: No User-Password attribute in the request. Cannot do PAP (4) [pap] = noop (4) eap: Peer sent EAP Response (code 2) ID 185 length 6 (4) eap: Continuing tunnel setup (4) [eap] = ok (4) } # authorize = ok (4) Found Auth-Type = eap (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (4) authenticate { (4) eap: Expiring EAP session with state 0x04505bcc06e94ea0 (4) eap: Finished EAP session with state 0x04505bcc06e94ea0 (4) eap: Previous EAP request found for state 0x04505bcc06e94ea0, released from the list (4) eap: Peer sent packet with method EAP TTLS (21) (4) eap: Calling submodule eap_ttls to process data (4) eap_ttls: Authenticate (4) eap_ttls: Continuing EAP-TLS (4) eap_ttls: Peer ACKed our handshake fragment (4) eap_ttls: [eaptls verify] = request (4) eap_ttls: [eaptls process] = handled (4) eap: Sending EAP Request (code 1) ID 186 length 960 (4) eap: EAP session adding &reply:State = 0x04505bcc07ea4ea0 (4) [eap] = handled (4) } # authenticate = handled (4) Using Post-Auth-Type Challenge (4) Post-Auth-Type sub-section not found. Ignoring. (4) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (4) Sent Access-Challenge Id 151 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (4) Class = 0x7363696c656b (4) Idle-Timeout = 120 (4) Acct-Interim-Interval = 600 (4) EAP-Message = 0x01ba03c0158000000b7ad35ed94c294c4915363eead91eb754997cc9e358432fc92ea951cc3bf0ca257b331a7cb6a269a2a68568a263e95de9f53ec3793bc049b13f139ae3b681106134abf 5b4d08b0203010001a381fc3081f9301d0603551d0e04160414af297b64d5335e54578a00c1231a91e0b971 (4) Message-Authenticator = 0x00000000000000000000000000000000 (4) State = 0x04505bcc07ea4ea0e22d93a65254c60e (4) Finished request Waking up in 4.9 seconds. (5) Received Access-Request Id 152 from 192.168.0.4:37009 to 192.168.0.1:1812 length 314 (5) User-Name = "scilek" (5) NAS-Identifier = "802aa8ac1ef9" (5) NAS-Port = 0 (5) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (5) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (5) Framed-MTU = 1400 (5) NAS-Port-Type = Wireless-802.11 (5) Connect-Info = "CONNECT 0Mbps 802.11b" (5) EAP-Message = 0x02ba00901580000000861603010046100000424104930a9b3c73dac921851d8ab0f682712f717dcabd9168c5198e90ee4e8f42c0df4222a064549fa68d3c58f0ece3bfa78dff21ff2053f6e f8442299d87f05682481403010001011603010030f9dccf05d275407d8a94d01743bbca728333116b00a1e7 (5) State = 0x04505bcc07ea4ea0e22d93a65254c60e (5) Message-Authenticator = 0x9a619954e29219b191d011153f6c40b0 (5) session-state: No cached attributes (5) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (5) authorize { (5) [preprocess] = ok (5) redundant sql { (5) sql1: EXPAND %{User-Name} (5) sql1: --> scilek (5) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (6) (5) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (5) sql1: --> CALL authorize_check('scilek') (5) sql1: Executing select query: CALL authorize_check('scilek') (5) sql1: User found in radcheck table (5) sql1: Conditional check items matched, merging assignment check items (5) sql1: Cleartext-Password := "0000" (5) sql1: Simultaneous-Use := 1 (5) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (5) sql1: --> CALL authorize_reply('scilek') (5) sql1: Executing select query: CALL authorize_reply('scilek') (5) sql1: User found in radreply table, merging reply items (5) sql1: Class := 0x7363696c656b (5) sql1: Idle-Timeout := 120 (5) sql1: Acct-Interim-Interval := 600 (5) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (5) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (5) sql1: --> CALL group_membership('scilek') (5) sql1: Executing select query: CALL group_membership('scilek') (5) sql1: User not found in any groups rlm_sql (sql1): Released connection (6) (5) [sql1] = ok (5) } # redundant sql = ok (5) pap: No User-Password attribute in the request. Cannot do PAP (5) [pap] = noop (5) eap: Peer sent EAP Response (code 2) ID 186 length 144 (5) eap: Continuing tunnel setup (5) [eap] = ok (5) } # authorize = ok (5) Found Auth-Type = eap (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (5) authenticate { (5) eap: Expiring EAP session with state 0x04505bcc07ea4ea0 (5) eap: Finished EAP session with state 0x04505bcc07ea4ea0 (5) eap: Previous EAP request found for state 0x04505bcc07ea4ea0, released from the list (5) eap: Peer sent packet with method EAP TTLS (21) (5) eap: Calling submodule eap_ttls to process data (5) eap_ttls: Authenticate (5) eap_ttls: Continuing EAP-TLS (5) eap_ttls: Peer indicated complete TLS record size will be 134 bytes (5) eap_ttls: Got complete TLS record (134 bytes) (5) eap_ttls: [eaptls verify] = length included (5) eap_ttls: <<< recv TLS 1.0 Handshake [length 0046], ClientKeyExchange (5) eap_ttls: TLS_accept: SSLv3 read client key exchange A (5) eap_ttls: TLS_accept: SSLv3 read certificate verify A (5) eap_ttls: <<< recv TLS 1.0 ChangeCipherSpec [length 0001] (5) eap_ttls: <<< recv TLS 1.0 Handshake [length 0010], Finished (5) eap_ttls: TLS_accept: SSLv3 read finished A (5) eap_ttls: >>> send TLS 1.0 ChangeCipherSpec [length 0001] (5) eap_ttls: TLS_accept: SSLv3 write change cipher spec A (5) eap_ttls: >>> send TLS 1.0 Handshake [length 0010], Finished (5) eap_ttls: TLS_accept: SSLv3 write finished A (5) eap_ttls: TLS_accept: SSLv3 flush data (5) eap_ttls: (other): SSL negotiation finished successfully (5) eap_ttls: SSL Connection Established (5) eap_ttls: [eaptls process] = handled (5) eap: Sending EAP Request (code 1) ID 187 length 69 (5) eap: EAP session adding &reply:State = 0x04505bcc00eb4ea0 (5) [eap] = handled (5) } # authenticate = handled (5) Using Post-Auth-Type Challenge (5) Post-Auth-Type sub-section not found. Ignoring. (5) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (5) Sent Access-Challenge Id 152 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (5) Class = 0x7363696c656b (5) Idle-Timeout = 120 (5) Acct-Interim-Interval = 600 (5) EAP-Message = 0x01bb004515800000003b1403010001011603010030634c922d6bc2683c316c571d9c853fac87c9e27f07fa69d43607157d30546461b057cbe08149b128d53f3056e46ef21e (5) Message-Authenticator = 0x00000000000000000000000000000000 (5) State = 0x04505bcc00eb4ea0e22d93a65254c60e (5) Finished request Waking up in 3.1 seconds. (6) Received Access-Request Id 153 from 192.168.0.4:37009 to 192.168.0.1:1812 length 233 (6) User-Name = "scilek" (6) NAS-Identifier = "802aa8ac1ef9" (6) NAS-Port = 0 (6) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (6) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (6) Framed-MTU = 1400 (6) NAS-Port-Type = Wireless-802.11 (6) Connect-Info = "CONNECT 0Mbps 802.11b" (6) EAP-Message = 0x02bb003f158000000035170301003032c62cae5225ad1cc1be64730c15889bf074af354c931c15c9470ded18a4b61bad881d0e401a037f6d522797d226d5f3 (6) State = 0x04505bcc00eb4ea0e22d93a65254c60e (6) Message-Authenticator = 0x5523305c39995cf5e531221ccc3a6912 (6) session-state: No cached attributes (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (6) authorize { (6) [preprocess] = ok (6) redundant sql { (6) sql1: EXPAND %{User-Name} (6) sql1: --> scilek (6) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (7) (6) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (6) sql1: --> CALL authorize_check('scilek') (6) sql1: Executing select query: CALL authorize_check('scilek') (6) sql1: User found in radcheck table (6) sql1: Conditional check items matched, merging assignment check items (6) sql1: Cleartext-Password := "0000" (6) sql1: Simultaneous-Use := 1 (6) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (6) sql1: --> CALL authorize_reply('scilek') (6) sql1: Executing select query: CALL authorize_reply('scilek') (6) sql1: User found in radreply table, merging reply items (6) sql1: Class := 0x7363696c656b (6) sql1: Idle-Timeout := 120 (6) sql1: Acct-Interim-Interval := 600 (6) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (6) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (6) sql1: --> CALL group_membership('scilek') (6) sql1: Executing select query: CALL group_membership('scilek') (6) sql1: User not found in any groups rlm_sql (sql1): Released connection (7) (6) [sql1] = ok (6) } # redundant sql = ok (6) pap: No User-Password attribute in the request. Cannot do PAP (6) [pap] = noop (6) eap: Peer sent EAP Response (code 2) ID 187 length 63 (6) eap: Continuing tunnel setup (6) [eap] = ok (6) } # authorize = ok (6) Found Auth-Type = eap (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (6) authenticate { (6) eap: Expiring EAP session with state 0x04505bcc00eb4ea0 (6) eap: Finished EAP session with state 0x04505bcc00eb4ea0 (6) eap: Previous EAP request found for state 0x04505bcc00eb4ea0, released from the list (6) eap: Peer sent packet with method EAP TTLS (21) (6) eap: Calling submodule eap_ttls to process data (6) eap_ttls: Authenticate (6) eap_ttls: Continuing EAP-TLS (6) eap_ttls: Peer indicated complete TLS record size will be 53 bytes (6) eap_ttls: Got complete TLS record (53 bytes) (6) eap_ttls: [eaptls verify] = length included (6) eap_ttls: [eaptls process] = ok (6) eap_ttls: Session established. Proceeding to decode tunneled attributes (6) eap_ttls: Got tunneled request (6) eap_ttls: EAP-Message = 0x0200000b017363696c656b (6) eap_ttls: FreeRADIUS-Proxied-To = 127.0.0.1 (6) eap_ttls: Got tunneled identity of scilek (6) eap_ttls: Setting default EAP type for tunneled EAP session (6) eap_ttls: Sending tunneled request (6) Virtual server inner-tunnel-ttls received request (6) EAP-Message = 0x0200000b017363696c656b (6) FreeRADIUS-Proxied-To = 127.0.0.1 (6) User-Name = "scilek" (6) NAS-Identifier = "802aa8ac1ef9" (6) NAS-Port = 0 (6) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (6) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (6) Framed-MTU = 1400 (6) NAS-Port-Type = Wireless-802.11 (6) Connect-Info = "CONNECT 0Mbps 802.11b" (6) Event-Timestamp = "Aug 6 2017 22:01:04 +03" (6) NAS-IP-Address = 192.168.0.4 (6) WARNING: Outer and inner identities are the same. User privacy is compromised. (6) server inner-tunnel-ttls { (6) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (6) authorize { (6) update control { (6) &Proxy-To-Realm := LOCAL (6) } # update control = noop (6) eap: Peer sent EAP Response (code 2) ID 0 length 11 (6) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (6) [eap] = ok (6) } # authorize = ok (6) WARNING: You set Proxy-To-Realm = LOCAL, but the realm does not exist! Cancelling invalid proxy request. (6) Found Auth-Type = eap (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (6) authenticate { (6) eap: Peer sent packet with method EAP Identity (1) (6) eap: Calling submodule eap_tls to process data (6) eap_tls: Initiating new EAP-TLS session (6) eap_tls: Setting verify mode to require certificate from client (6) eap_tls: [eaptls start] = request (6) eap: Sending EAP Request (code 1) ID 1 length 6 (6) eap: EAP session adding &reply:State = 0xb261b712b260baef (6) [eap] = handled (6) } # authenticate = handled (6) } # server inner-tunnel-ttls (6) Virtual server sending reply (6) EAP-Message = 0x010100060d20 (6) Message-Authenticator = 0x00000000000000000000000000000000 (6) State = 0xb261b712b260baef1bb99e7a9d2d07d1 (6) eap_ttls: Got tunneled Access-Challenge (6) eap: Sending EAP Request (code 1) ID 188 length 63 (6) eap: EAP session adding &reply:State = 0x04505bcc01ec4ea0 (6) [eap] = handled (6) } # authenticate = handled (6) Using Post-Auth-Type Challenge (6) Post-Auth-Type sub-section not found. Ignoring. (6) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (6) Sent Access-Challenge Id 153 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (6) Class = 0x7363696c656b (6) Idle-Timeout = 120 (6) Acct-Interim-Interval = 600 (6) EAP-Message = 0x01bc003f158000000035170301003071469a10b0f1b3b1435b53b91ff9222f139ad1069d07f31fd9be750df2d0318c204da31cacfccfdf07670980b8c7d825 (6) Message-Authenticator = 0x00000000000000000000000000000000 (6) State = 0x04505bcc01ec4ea0e22d93a65254c60e (6) Finished request Waking up in 3.1 seconds. (7) Received Access-Request Id 154 from 192.168.0.4:37009 to 192.168.0.1:1812 length 233 (7) User-Name = "scilek" (7) NAS-Identifier = "802aa8ac1ef9" (7) NAS-Port = 0 (7) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (7) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (7) Framed-MTU = 1400 (7) NAS-Port-Type = Wireless-802.11 (7) Connect-Info = "CONNECT 0Mbps 802.11b" (7) EAP-Message = 0x02bc003f15800000003517030100308b11e5a28fd93731564ae120793d5d4c1d1b1ebbdf8f8631529412cb8c943e87e3a255fa25307aedc28e2ce0fa6374d4 (7) State = 0x04505bcc01ec4ea0e22d93a65254c60e (7) Message-Authenticator = 0xd2091d38934748e580def21e79c2dcba (7) session-state: No cached attributes (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (7) authorize { (7) [preprocess] = ok (7) redundant sql { (7) sql1: EXPAND %{User-Name} (7) sql1: --> scilek (7) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (8) (7) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (7) sql1: --> CALL authorize_check('scilek') (7) sql1: Executing select query: CALL authorize_check('scilek') (7) sql1: User found in radcheck table (7) sql1: Conditional check items matched, merging assignment check items (7) sql1: Cleartext-Password := "0000" (7) sql1: Simultaneous-Use := 1 (7) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (7) sql1: --> CALL authorize_reply('scilek') (7) sql1: Executing select query: CALL authorize_reply('scilek') (7) sql1: User found in radreply table, merging reply items (7) sql1: Class := 0x7363696c656b (7) sql1: Idle-Timeout := 120 (7) sql1: Acct-Interim-Interval := 600 (7) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (7) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (7) sql1: --> CALL group_membership('scilek') (7) sql1: Executing select query: CALL group_membership('scilek') (7) sql1: User not found in any groups rlm_sql (sql1): Released connection (8) (7) [sql1] = ok (7) } # redundant sql = ok (7) pap: No User-Password attribute in the request. Cannot do PAP (7) [pap] = noop (7) eap: Peer sent EAP Response (code 2) ID 188 length 63 (7) eap: Continuing tunnel setup (7) [eap] = ok (7) } # authorize = ok (7) Found Auth-Type = eap (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (7) authenticate { (7) eap: Expiring EAP session with state 0xb261b712b260baef (7) eap: Finished EAP session with state 0x04505bcc01ec4ea0 (7) eap: Previous EAP request found for state 0x04505bcc01ec4ea0, released from the list (7) eap: Peer sent packet with method EAP TTLS (21) (7) eap: Calling submodule eap_ttls to process data (7) eap_ttls: Authenticate (7) eap_ttls: Continuing EAP-TLS (7) eap_ttls: Peer indicated complete TLS record size will be 53 bytes (7) eap_ttls: Got complete TLS record (53 bytes) (7) eap_ttls: [eaptls verify] = length included (7) eap_ttls: [eaptls process] = ok (7) eap_ttls: Session established. Proceeding to decode tunneled attributes (7) eap_ttls: Got tunneled request (7) eap_ttls: EAP-Message = 0x02010006031a (7) eap_ttls: FreeRADIUS-Proxied-To = 127.0.0.1 (7) eap_ttls: Sending tunneled request (7) Virtual server inner-tunnel-ttls received request (7) EAP-Message = 0x02010006031a (7) FreeRADIUS-Proxied-To = 127.0.0.1 (7) User-Name = "scilek" (7) State = 0xb261b712b260baef1bb99e7a9d2d07d1 (7) NAS-Identifier = "802aa8ac1ef9" (7) NAS-Port = 0 (7) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (7) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (7) Framed-MTU = 1400 (7) NAS-Port-Type = Wireless-802.11 (7) Connect-Info = "CONNECT 0Mbps 802.11b" (7) Event-Timestamp = "Aug 6 2017 22:01:04 +03" (7) NAS-IP-Address = 192.168.0.4 (7) WARNING: Outer and inner identities are the same. User privacy is compromised. (7) server inner-tunnel-ttls { (7) session-state: No cached attributes (7) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (7) authorize { (7) update control { (7) &Proxy-To-Realm := LOCAL (7) } # update control = noop (7) eap: Peer sent EAP Response (code 2) ID 1 length 6 (7) eap: No EAP Start, assuming it's an on-going EAP conversation (7) [eap] = updated (7) redundant sql { (7) sql1: EXPAND %{User-Name} (7) sql1: --> scilek (7) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (9) (7) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (7) sql1: --> CALL authorize_check('scilek') (7) sql1: Executing select query: CALL authorize_check('scilek') (7) sql1: User found in radcheck table (7) sql1: Conditional check items matched, merging assignment check items (7) sql1: Cleartext-Password := "0000" (7) sql1: Simultaneous-Use := 1 (7) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (7) sql1: --> CALL authorize_reply('scilek') (7) sql1: Executing select query: CALL authorize_reply('scilek') (7) sql1: User found in radreply table, merging reply items (7) sql1: Class := 0x7363696c656b (7) sql1: Idle-Timeout := 120 (7) sql1: Acct-Interim-Interval := 600 (7) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (7) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (7) sql1: --> CALL group_membership('scilek') (7) sql1: Executing select query: CALL group_membership('scilek') (7) sql1: User not found in any groups rlm_sql (sql1): Released connection (9) (7) [sql1] = ok (7) } # redundant sql = ok (7) [expiration] = noop (7) [logintime] = noop (7) pap: WARNING: Auth-Type already set. Not setting to PAP (7) [pap] = noop (7) } # authorize = updated (7) WARNING: You set Proxy-To-Realm = LOCAL, but the realm does not exist! Cancelling invalid proxy request. (7) Found Auth-Type = eap (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (7) authenticate { (7) eap: Expiring EAP session with state 0xb261b712b260baef (7) eap: Finished EAP session with state 0xb261b712b260baef (7) eap: Previous EAP request found for state 0xb261b712b260baef, released from the list (7) eap: Peer sent packet with method EAP NAK (3) (7) eap: Found mutually acceptable type MSCHAPv2 (26) (7) eap: Calling submodule eap_mschapv2 to process data (7) eap_mschapv2: Issuing Challenge (7) eap: Sending EAP Request (code 1) ID 2 length 43 (7) eap: EAP session adding &reply:State = 0xb261b712b363adef (7) [eap] = handled (7) } # authenticate = handled (7) } # server inner-tunnel-ttls (7) Virtual server sending reply (7) Class = 0x7363696c656b (7) Idle-Timeout = 120 (7) Acct-Interim-Interval = 600 (7) Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (7) EAP-Message = 0x0102002b1a010200261076275b44d652a45dd691ef8c9f594154667265657261646975732d332e302e3135 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0xb261b712b363adef1bb99e7a9d2d07d1 (7) eap_ttls: Got tunneled Access-Challenge (7) eap: Sending EAP Request (code 1) ID 189 length 95 (7) eap: EAP session adding &reply:State = 0x04505bcc02ed4ea0 (7) [eap] = handled (7) } # authenticate = handled (7) Using Post-Auth-Type Challenge (7) Post-Auth-Type sub-section not found. Ignoring. (7) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (7) Sent Access-Challenge Id 154 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (7) Class = 0x7363696c656b (7) Idle-Timeout = 120 (7) Acct-Interim-Interval = 600 (7) EAP-Message = 0x01bd005f15800000005517030100506d9b920856058f51d9d63731a1ba2cca6089b76a27e0dddbca0c273dbc8c806f5f5467b1b69776fe35cd70c68d9b3bd05b771011e352ff26e0deee630 7f527c97cf9159e92723688dbf3061a419c08f7 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0x04505bcc02ed4ea0e22d93a65254c60e (7) Finished request Waking up in 3.0 seconds. (8) Received Access-Request Id 155 from 192.168.0.4:37009 to 192.168.0.1:1812 length 297 (8) User-Name = "scilek" (8) NAS-Identifier = "802aa8ac1ef9" (8) NAS-Port = 0 (8) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (8) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (8) Framed-MTU = 1400 (8) NAS-Port-Type = Wireless-802.11 (8) Connect-Info = "CONNECT 0Mbps 802.11b" (8) EAP-Message = 0x02bd007f1580000000751703010070f2c2216c991f799561341c814c3163c6d7aef3ee5c288293c03d51683bdcb15fd1c034000acd7fca07a3c9aabea8e9c3a28b98238da442ea319076deb 6b0db7c02fe625f4166210c16388beed43b5f746b9ca8fdcc76f9534b5465685f312694803f1dcca7b3f741 (8) State = 0x04505bcc02ed4ea0e22d93a65254c60e (8) Message-Authenticator = 0x44a5776045dff1d0cd24cf4a8a73d84f (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (8) authorize { (8) [preprocess] = ok (8) redundant sql { (8) sql1: EXPAND %{User-Name} (8) sql1: --> scilek (8) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (10) (8) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (8) sql1: --> CALL authorize_check('scilek') (8) sql1: Executing select query: CALL authorize_check('scilek') (8) sql1: User found in radcheck table (8) sql1: Conditional check items matched, merging assignment check items (8) sql1: Cleartext-Password := "0000" (8) sql1: Simultaneous-Use := 1 (8) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (8) sql1: --> CALL authorize_reply('scilek') (8) sql1: Executing select query: CALL authorize_reply('scilek') (8) sql1: User found in radreply table, merging reply items (8) sql1: Class := 0x7363696c656b (8) sql1: Idle-Timeout := 120 (8) sql1: Acct-Interim-Interval := 600 (8) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (8) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (8) sql1: --> CALL group_membership('scilek') (8) sql1: Executing select query: CALL group_membership('scilek') (8) sql1: User not found in any groups rlm_sql (sql1): Released connection (10) (8) [sql1] = ok (8) } # redundant sql = ok (8) pap: No User-Password attribute in the request. Cannot do PAP (8) [pap] = noop (8) eap: Peer sent EAP Response (code 2) ID 189 length 127 (8) eap: Continuing tunnel setup (8) [eap] = ok (8) } # authorize = ok (8) Found Auth-Type = eap (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) authenticate { (8) eap: Expiring EAP session with state 0xb261b712b363adef (8) eap: Finished EAP session with state 0x04505bcc02ed4ea0 (8) eap: Previous EAP request found for state 0x04505bcc02ed4ea0, released from the list (8) eap: Peer sent packet with method EAP TTLS (21) (8) eap: Calling submodule eap_ttls to process data (8) eap_ttls: Authenticate (8) eap_ttls: Continuing EAP-TLS (8) eap_ttls: Peer indicated complete TLS record size will be 117 bytes (8) eap_ttls: Got complete TLS record (117 bytes) (8) eap_ttls: [eaptls verify] = length included (8) eap_ttls: [eaptls process] = ok (8) eap_ttls: Session established. Proceeding to decode tunneled attributes (8) eap_ttls: Got tunneled request (8) eap_ttls: EAP-Message = 0x020200411a0202003c3123b9165317bd2d22a434e4ac00b57acc000000000000000095496f7e45ddbc1dd890243a7947e68d2749164433e3a15e007363696c656b (8) eap_ttls: FreeRADIUS-Proxied-To = 127.0.0.1 (8) eap_ttls: Sending tunneled request (8) Virtual server inner-tunnel-ttls received request (8) EAP-Message = 0x020200411a0202003c3123b9165317bd2d22a434e4ac00b57acc000000000000000095496f7e45ddbc1dd890243a7947e68d2749164433e3a15e007363696c656b (8) FreeRADIUS-Proxied-To = 127.0.0.1 (8) User-Name = "scilek" (8) State = 0xb261b712b363adef1bb99e7a9d2d07d1 (8) NAS-Identifier = "802aa8ac1ef9" (8) NAS-Port = 0 (8) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (8) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (8) Framed-MTU = 1400 (8) NAS-Port-Type = Wireless-802.11 (8) Connect-Info = "CONNECT 0Mbps 802.11b" (8) Event-Timestamp = "Aug 6 2017 22:01:05 +03" (8) NAS-IP-Address = 192.168.0.4 (8) WARNING: Outer and inner identities are the same. User privacy is compromised. (8) server inner-tunnel-ttls { (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (8) authorize { (8) update control { (8) &Proxy-To-Realm := LOCAL (8) } # update control = noop (8) eap: Peer sent EAP Response (code 2) ID 2 length 65 (8) eap: No EAP Start, assuming it's an on-going EAP conversation (8) [eap] = updated (8) redundant sql { (8) sql1: EXPAND %{User-Name} (8) sql1: --> scilek (8) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (11) (8) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (8) sql1: --> CALL authorize_check('scilek') (8) sql1: Executing select query: CALL authorize_check('scilek') (8) sql1: User found in radcheck table (8) sql1: Conditional check items matched, merging assignment check items (8) sql1: Cleartext-Password := "0000" (8) sql1: Simultaneous-Use := 1 (8) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (8) sql1: --> CALL authorize_reply('scilek') (8) sql1: Executing select query: CALL authorize_reply('scilek') (8) sql1: User found in radreply table, merging reply items (8) sql1: Class := 0x7363696c656b (8) sql1: Idle-Timeout := 120 (8) sql1: Acct-Interim-Interval := 600 (8) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (8) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (8) sql1: --> CALL group_membership('scilek') (8) sql1: Executing select query: CALL group_membership('scilek') (8) sql1: User not found in any groups rlm_sql (sql1): Released connection (11) (8) [sql1] = ok (8) } # redundant sql = ok (8) [expiration] = noop (8) [logintime] = noop (8) pap: WARNING: Auth-Type already set. Not setting to PAP (8) [pap] = noop (8) } # authorize = updated (8) WARNING: You set Proxy-To-Realm = LOCAL, but the realm does not exist! Cancelling invalid proxy request. (8) Found Auth-Type = eap (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (8) authenticate { (8) eap: Expiring EAP session with state 0xb261b712b363adef (8) eap: Finished EAP session with state 0xb261b712b363adef (8) eap: Previous EAP request found for state 0xb261b712b363adef, released from the list (8) eap: Peer sent packet with method EAP MSCHAPv2 (26) (8) eap: Calling submodule eap_mschapv2 to process data (8) eap_mschapv2: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (8) eap_mschapv2: authenticate { (8) mschap: Found Cleartext-Password, hashing to create NT-Password (8) mschap: Found Cleartext-Password, hashing to create LM-Password (8) mschap: Creating challenge hash with username: scilek (8) mschap: Client is using MS-CHAPv2 (8) mschap: Adding MS-CHAPv2 MPPE keys (8) [mschap] = ok (8) } # authenticate = ok (8) MSCHAP Success (8) eap: Sending EAP Request (code 1) ID 3 length 51 (8) eap: EAP session adding &reply:State = 0xb261b712b062adef (8) [eap] = handled (8) } # authenticate = handled (8) } # server inner-tunnel-ttls (8) Virtual server sending reply (8) Class = 0x7363696c656b (8) Idle-Timeout = 120 (8) Acct-Interim-Interval = 600 (8) Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (8) EAP-Message = 0x010300331a0302002e533d35374338384535394446343042374534464530344235393938433245343036413942414330313735 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0xb261b712b062adef1bb99e7a9d2d07d1 (8) eap_ttls: Got tunneled Access-Challenge (8) eap: Sending EAP Request (code 1) ID 190 length 111 (8) eap: EAP session adding &reply:State = 0x04505bcc03ee4ea0 (8) [eap] = handled (8) } # authenticate = handled (8) Using Post-Auth-Type Challenge (8) Post-Auth-Type sub-section not found. Ignoring. (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) Sent Access-Challenge Id 155 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (8) Class = 0x7363696c656b (8) Idle-Timeout = 120 (8) Acct-Interim-Interval = 600 (8) EAP-Message = 0x01be006f15800000006517030100607fa1a1325acdddb66d4edf3e8ca2e1ce4efbab2332a0db5f9b9fd88f89d4740dc90babafc823bf48e0eef8baf16b27939ef7b632d37b7c2c0b26a7ae0 86fb09e5059665a5c0ab2642e517da8daa1f5d410bd49833b5b06ddc3ba709fc00c6397 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0x04505bcc03ee4ea0e22d93a65254c60e (8) Finished request Waking up in 3.0 seconds. (9) Received Access-Request Id 156 from 192.168.0.4:37009 to 192.168.0.1:1812 length 233 (9) User-Name = "scilek" (9) NAS-Identifier = "802aa8ac1ef9" (9) NAS-Port = 0 (9) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (9) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (9) Framed-MTU = 1400 (9) NAS-Port-Type = Wireless-802.11 (9) Connect-Info = "CONNECT 0Mbps 802.11b" (9) EAP-Message = 0x02be003f15800000003517030100307b461ab4e2d39fbcdc7e73d4ad3e69bd4a10b459077867f0d1caa1e8f7be1e0b977e098f3f5c753ff00974b1d596ada8 (9) State = 0x04505bcc03ee4ea0e22d93a65254c60e (9) Message-Authenticator = 0x75a8ef09c04fddc52861bdbd1959b9af (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (9) authorize { (9) [preprocess] = ok (9) redundant sql { (9) sql1: EXPAND %{User-Name} (9) sql1: --> scilek (9) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (12) (9) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (9) sql1: --> CALL authorize_check('scilek') (9) sql1: Executing select query: CALL authorize_check('scilek') (9) sql1: User found in radcheck table (9) sql1: Conditional check items matched, merging assignment check items (9) sql1: Cleartext-Password := "0000" (9) sql1: Simultaneous-Use := 1 (9) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (9) sql1: --> CALL authorize_reply('scilek') (9) sql1: Executing select query: CALL authorize_reply('scilek') (9) sql1: User found in radreply table, merging reply items (9) sql1: Class := 0x7363696c656b (9) sql1: Idle-Timeout := 120 (9) sql1: Acct-Interim-Interval := 600 (9) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (9) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (9) sql1: --> CALL group_membership('scilek') (9) sql1: Executing select query: CALL group_membership('scilek') (9) sql1: User not found in any groups rlm_sql (sql1): Released connection (12) (9) [sql1] = ok (9) } # redundant sql = ok (9) pap: No User-Password attribute in the request. Cannot do PAP (9) [pap] = noop (9) eap: Peer sent EAP Response (code 2) ID 190 length 63 (9) eap: Continuing tunnel setup (9) [eap] = ok (9) } # authorize = ok (9) Found Auth-Type = eap (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (9) authenticate { (9) eap: Expiring EAP session with state 0xb261b712b062adef (9) eap: Finished EAP session with state 0x04505bcc03ee4ea0 (9) eap: Previous EAP request found for state 0x04505bcc03ee4ea0, released from the list (9) eap: Peer sent packet with method EAP TTLS (21) (9) eap: Calling submodule eap_ttls to process data (9) eap_ttls: Authenticate (9) eap_ttls: Continuing EAP-TLS (9) eap_ttls: Peer indicated complete TLS record size will be 53 bytes (9) eap_ttls: Got complete TLS record (53 bytes) (9) eap_ttls: [eaptls verify] = length included (9) eap_ttls: [eaptls process] = ok (9) eap_ttls: Session established. Proceeding to decode tunneled attributes (9) eap_ttls: Got tunneled request (9) eap_ttls: EAP-Message = 0x020300061a03 (9) eap_ttls: FreeRADIUS-Proxied-To = 127.0.0.1 (9) eap_ttls: Sending tunneled request (9) Virtual server inner-tunnel-ttls received request (9) EAP-Message = 0x020300061a03 (9) FreeRADIUS-Proxied-To = 127.0.0.1 (9) User-Name = "scilek" (9) State = 0xb261b712b062adef1bb99e7a9d2d07d1 (9) NAS-Identifier = "802aa8ac1ef9" (9) NAS-Port = 0 (9) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (9) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (9) Framed-MTU = 1400 (9) NAS-Port-Type = Wireless-802.11 (9) Connect-Info = "CONNECT 0Mbps 802.11b" (9) Event-Timestamp = "Aug 6 2017 22:01:05 +03" (9) NAS-IP-Address = 192.168.0.4 (9) WARNING: Outer and inner identities are the same. User privacy is compromised. (9) server inner-tunnel-ttls { (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (9) authorize { (9) update control { (9) &Proxy-To-Realm := LOCAL (9) } # update control = noop (9) eap: Peer sent EAP Response (code 2) ID 3 length 6 (9) eap: No EAP Start, assuming it's an on-going EAP conversation (9) [eap] = updated (9) redundant sql { (9) sql1: EXPAND %{User-Name} (9) sql1: --> scilek (9) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (13) (9) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (9) sql1: --> CALL authorize_check('scilek') (9) sql1: Executing select query: CALL authorize_check('scilek') (9) sql1: User found in radcheck table (9) sql1: Conditional check items matched, merging assignment check items (9) sql1: Cleartext-Password := "0000" (9) sql1: Simultaneous-Use := 1 (9) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (9) sql1: --> CALL authorize_reply('scilek') (9) sql1: Executing select query: CALL authorize_reply('scilek') (9) sql1: User found in radreply table, merging reply items (9) sql1: Class := 0x7363696c656b (9) sql1: Idle-Timeout := 120 (9) sql1: Acct-Interim-Interval := 600 (9) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (9) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (9) sql1: --> CALL group_membership('scilek') (9) sql1: Executing select query: CALL group_membership('scilek') (9) sql1: User not found in any groups rlm_sql (sql1): Released connection (13) (9) [sql1] = ok (9) } # redundant sql = ok (9) [expiration] = noop (9) [logintime] = noop (9) pap: WARNING: Auth-Type already set. Not setting to PAP (9) [pap] = noop (9) } # authorize = updated (9) WARNING: You set Proxy-To-Realm = LOCAL, but the realm does not exist! Cancelling invalid proxy request. (9) Found Auth-Type = eap (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (9) authenticate { (9) eap: Expiring EAP session with state 0xb261b712b062adef (9) eap: Finished EAP session with state 0xb261b712b062adef (9) eap: Previous EAP request found for state 0xb261b712b062adef, released from the list (9) eap: Peer sent packet with method EAP MSCHAPv2 (26) (9) eap: Calling submodule eap_mschapv2 to process data (9) eap: Sending EAP Success (code 3) ID 3 length 4 (9) eap: Freeing handler (9) [eap] = ok (9) } # authenticate = ok (9) # Executing section session from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (9) session { (9) redundant sql { (9) sql1: EXPAND %{User-Name} (9) sql1: --> scilek (9) sql1: SQL-User-Name set to 'scilek' (9) sql1: EXPAND CALL simul_count('%{SQL-User-Name}') (9) sql1: --> CALL simul_count('scilek') rlm_sql (sql1): Reserved connection (14) (9) sql1: Executing select query: CALL simul_count('scilek') rlm_sql (sql1): Released connection (14) (9) [sql1] = ok (9) } # redundant sql = ok (9) } # session = ok (9) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (9) post-auth { (9) if (1) { (9) if (1) -> TRUE (9) if (1) { (9) update reply { (9) User-Name !* ANY (9) Message-Authenticator !* ANY (9) EAP-Message !* ANY (9) Proxy-State !* ANY (9) MS-MPPE-Encryption-Types !* ANY (9) MS-MPPE-Encryption-Policy !* ANY (9) MS-MPPE-Send-Key !* ANY (9) MS-MPPE-Recv-Key !* ANY (9) } # update reply = noop (9) update { (9) &outer.session-state::Class += &reply:Class[*] -> 0x7363696c656b (9) &outer.session-state::Idle-Timeout += &reply:Idle-Timeout[*] -> 120 (9) &outer.session-state::Acct-Interim-Interval += &reply:Acct-Interim-Interval[*] -> 600 (9) &outer.session-state::Exec-Program-Wait += &reply:Exec-Program-Wait[*] -> '/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek' (9) } # update = noop (9) } # if (1) = noop (9) } # post-auth = noop (9) Login OK: [scilek] (from client HOME_AP port 0 cli 2C-F0-A2-87-C1-CA via TLS tunnel) (9) } # server inner-tunnel-ttls (9) Virtual server sending reply (9) Class = 0x7363696c656b (9) Idle-Timeout = 120 (9) Acct-Interim-Interval = 600 (9) Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (9) eap_ttls: Got tunneled Access-Accept (9) eap: Sending EAP Success (code 3) ID 190 length 4 (9) eap: Freeing handler (9) [eap] = ok (9) } # authenticate = ok (9) # Executing section session from file /usr/local/etc/raddb/sites-enabled/default (9) session { (9) redundant sql { (9) sql1: EXPAND %{User-Name} (9) sql1: --> scilek (9) sql1: SQL-User-Name set to 'scilek' (9) sql1: EXPAND CALL simul_count('%{SQL-User-Name}') (9) sql1: --> CALL simul_count('scilek') rlm_sql (sql1): Reserved connection (15) (9) sql1: Executing select query: CALL simul_count('scilek') rlm_sql (sql1): Released connection (15) (9) [sql1] = ok (9) } # redundant sql = ok (9) } # session = ok (9) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default (9) post-auth { (9) exec: Executing: /usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek: Warning: Using a password on the command line interface can be insecure. (9) exec: Program returned code (0) and output '' (9) exec: Program executed successfully (9) [exec] = ok (9) policy remove_reply_message_if_eap { (9) if (&reply:EAP-Message && &reply:Reply-Message) { (9) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (9) else { (9) [noop] = noop (9) } # else = noop (9) } # policy remove_reply_message_if_eap = noop (9) } # post-auth = ok (9) Login OK: [scilek] (from client HOME_AP port 0 cli 2C-F0-A2-87-C1-CA) (9) Sent Access-Accept Id 156 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (9) Class = 0x7363696c656b (9) Idle-Timeout = 120 (9) Acct-Interim-Interval = 600 (9) MS-MPPE-Recv-Key = 0xc2f8ed83b9161ee9e763fc08a1cbb53359246d980a1c477f8390a3766098302e (9) MS-MPPE-Send-Key = 0xbff1510aac7ed023d300ed023f9bffe2a1b76f585158b62a72e2cf196bd1c780 (9) EAP-Message = 0x03be0004 (9) Message-Authenticator = 0x00000000000000000000000000000000 (9) User-Name = "scilek" (9) Finished request Waking up in 2.9 seconds. (10) Received Accounting-Request Id 157 from 192.168.0.4:44463 to 192.168.0.1:1813 length 171 (10) Acct-Session-Id = "59873E49-0000001A" (10) Acct-Status-Type = Start (10) Acct-Authentic = RADIUS (10) User-Name = "scilek" (10) Framed-IP-Address = 0.0.0.0 (10) NAS-Identifier = "802aa8ac1ef9" (10) NAS-Port = 0 (10) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (10) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (10) NAS-Port-Type = Wireless-802.11 (10) Connect-Info = "CONNECT 0Mbps 802.11b" (10) Class = 0x7363696c656b (10) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (10) preacct { (10) [preprocess] = ok (10) } # preacct = ok (10) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (10) accounting { (10) detail: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d (10) detail: --> /var/log/radacct/192.168.0.4/detail_2017_08_06 (10) detail: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d expands to /var/log/radacct/192.168.0.4/detail_2017_08_06 (10) detail: EXPAND %t (10) detail: --> Sun Aug 6 22:01:05 2017 (10) [detail] = ok (10) redundant sql { (10) sql1: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (10) sql1: --> type.start.query (10) sql1: Using query template 'query' rlm_sql (sql1): Reserved connection (0) (10) sql1: EXPAND %{User-Name} (10) sql1: --> scilek (10) sql1: SQL-User-Name set to 'scilek' (10) sql1: EXPAND CALL accounting_start('%{Acct-Session-Id}','%{SQL-User-Name}','%{Class}','%{NAS-IP-Address}','%{Called-Station-Id}','%{Calling-Station-Id}') (10) sql1: --> CALL accounting_start('59873E49-0000001A','scilek','0x7363696c656b','192.168.0.4','80-2A-A8-AD-1E-F9=3ASCILEK.NET','2C-F0-A2-87-C1-CA') (10) sql1: EXPAND /var/log/sqltrace.sql (10) sql1: --> /var/log/sqltrace.sql (10) sql1: Executing query: CALL accounting_start('59873E49-0000001A','scilek','0x7363696c656b','192.168.0.4','80-2A-A8-AD-1E-F9=3ASCILEK.NET','2C-F0-A2-87-C1-CA') (10) sql1: SQL query returned: success (10) sql1: 1 record(s) updated rlm_sql (sql1): Released connection (0) (10) [sql1] = ok (10) } # redundant sql = ok (10) [exec] = noop (10) if (request:Acct-Status-Type == Interim-Update) { (10) if (request:Acct-Status-Type == Interim-Update) -> FALSE (10) } # accounting = ok (10) Sent Accounting-Response Id 157 from 192.168.0.1:1813 to 192.168.0.4:44463 length 0 (10) Finished request (10) Cleaning up request packet ID 157 with timestamp +22 Waking up in 2.9 seconds. (11) Received Accounting-Request Id 158 from 192.168.0.4:44463 to 192.168.0.1:1813 length 207 (11) Acct-Session-Id = "59873E49-0000001A" (11) Acct-Status-Type = Interim-Update (11) Acct-Authentic = RADIUS (11) User-Name = "scilek" (11) Framed-IP-Address = 192.168.0.103 (11) NAS-Identifier = "802aa8ac1ef9" (11) NAS-Port = 0 (11) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (11) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (11) NAS-Port-Type = Wireless-802.11 (11) Connect-Info = "CONNECT 0Mbps 802.11b" (11) Class = 0x7363696c656b (11) Acct-Session-Time = 0 (11) Acct-Input-Packets = 14 (11) Acct-Output-Packets = 14 (11) Acct-Input-Octets = 1858 (11) Acct-Output-Octets = 4091 (11) Event-Timestamp = "Aug 6 2017 22:00:59 +03" (11) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (11) preacct { (11) [preprocess] = ok (11) } # preacct = ok (11) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (11) accounting { (11) detail: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d (11) detail: --> /var/log/radacct/192.168.0.4/detail_2017_08_06 (11) detail: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d expands to /var/log/radacct/192.168.0.4/detail_2017_08_06 (11) detail: EXPAND %t (11) detail: --> Sun Aug 6 22:01:05 2017 (11) [detail] = ok (11) redundant sql { (11) sql1: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (11) sql1: --> type.interim-update.query (11) sql1: Using query template 'query' rlm_sql (sql1): Reserved connection (1) (11) sql1: EXPAND %{User-Name} (11) sql1: --> scilek (11) sql1: SQL-User-Name set to 'scilek' (11) sql1: EXPAND CALL accounting_update ('%{Acct-Session-Id}','%{Called-Station-Id}','%{Calling-Station-Id}','%{Acct-Session-Time}','%{Acct-Input-Octets}','%{Acct-Input-Gig awords}','%{Acct-Output-Octets}','%{Acct-Output-Gigawords}') (11) sql1: --> CALL accounting_update ('59873E49-0000001A','80-2A-A8-AD-1E-F9=3ASCILEK.NET','2C-F0-A2-87-C1-CA','0','1858','','4091','') (11) sql1: EXPAND /var/log/sqltrace.sql (11) sql1: --> /var/log/sqltrace.sql (11) sql1: Executing query: CALL accounting_update ('59873E49-0000001A','80-2A-A8-AD-1E-F9=3ASCILEK.NET','2C-F0-A2-87-C1-CA','0','1858','','4091','') (11) sql1: SQL query returned: success (11) sql1: 1 record(s) updated rlm_sql (sql1): Released connection (1) (11) [sql1] = ok (11) } # redundant sql = ok (11) [exec] = noop (11) if (request:Acct-Status-Type == Interim-Update) { (11) if (request:Acct-Status-Type == Interim-Update) -> TRUE (11) if (request:Acct-Status-Type == Interim-Update) { (11) check_quota: Executing: /usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_acct.sh %{request:User-Name} %{request:Calling-Station-Id} %{request:NAS-IP-Address } %{request:Class} %{request:Acct-Status-Type}: (11) check_quota: EXPAND %{request:User-Name} (11) check_quota: --> scilek (11) check_quota: EXPAND %{request:Calling-Station-Id} (11) check_quota: --> 2C-F0-A2-87-C1-CA (11) check_quota: EXPAND %{request:NAS-IP-Address} (11) check_quota: --> 192.168.0.4 (11) check_quota: EXPAND %{request:Class} (11) check_quota: --> 0x7363696c656b (11) check_quota: EXPAND %{request:Acct-Status-Type} (11) check_quota: --> Interim-Update (11) check_quota: Program executed successfully (11) [check_quota] = ok (11) } # if (request:Acct-Status-Type == Interim-Update) = ok (11) } # accounting = ok (11) Sent Accounting-Response Id 158 from 192.168.0.1:1813 to 192.168.0.4:44463 length 0 (11) Finished request (11) Cleaning up request packet ID 158 with timestamp +22 Waking up in 2.9 seconds. Warning: Using a password on the command line interface can be insecure. Warning: Using a password on the command line interface can be insecure. (1) Cleaning up request packet ID 148 with timestamp +20 (2) Cleaning up request packet ID 149 with timestamp +20 (3) Cleaning up request packet ID 150 with timestamp +20 (4) Cleaning up request packet ID 151 with timestamp +20 Waking up in 1.7 seconds. (5) Cleaning up request packet ID 152 with timestamp +21 (6) Cleaning up request packet ID 153 with timestamp +21 (7) Cleaning up request packet ID 154 with timestamp +21 (8) Cleaning up request packet ID 155 with timestamp +22 (9) Cleaning up request packet ID 156 with timestamp +22 Ready to process requests (12) Received Accounting-Request Id 159 from 192.168.0.4:44463 to 192.168.0.1:1813 length 213 (12) Acct-Session-Id = "59873E49-0000001A" (12) Acct-Status-Type = Stop (12) Acct-Authentic = RADIUS (12) User-Name = "scilek" (12) Framed-IP-Address = 192.168.0.103 (12) NAS-Identifier = "802aa8ac1ef9" (12) NAS-Port = 0 (12) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (12) Calling-Station-Id = "2C-F0-A2-87-C1-CA" (12) NAS-Port-Type = Wireless-802.11 (12) Connect-Info = "CONNECT 0Mbps 802.11b" (12) Class = 0x7363696c656b (12) Acct-Session-Time = 10 (12) Acct-Input-Packets = 178 (12) Acct-Output-Packets = 55 (12) Acct-Input-Octets = 19062 (12) Acct-Output-Octets = 17357 (12) Event-Timestamp = "Aug 6 2017 22:01:09 +03" (12) Acct-Terminate-Cause = User-Request (12) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (12) preacct { (12) [preprocess] = ok (12) } # preacct = ok (12) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (12) accounting { (12) detail: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d (12) detail: --> /var/log/radacct/192.168.0.4/detail_2017_08_06 (12) detail: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d expands to /var/log/radacct/192.168.0.4/detail_2017_08_06 (12) detail: EXPAND %t (12) detail: --> Sun Aug 6 22:01:15 2017 (12) [detail] = ok (12) redundant sql { (12) sql1: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (12) sql1: --> type.stop.query (12) sql1: Using query template 'query' rlm_sql (sql1): Reserved connection (2) (12) sql1: EXPAND %{User-Name} (12) sql1: --> scilek (12) sql1: SQL-User-Name set to 'scilek' (12) sql1: EXPAND CALL accounting_stop ('%{Acct-Session-Id}','%{SQL-User-Name}','%{Called-Station-Id}','%{Calling-Station-Id}','%{Acct-Session-Time}','%{Acct-Input-Octets}', '%{Acct-Input-Gigawords}','%{Acct-Output-Octets}','%{Acct-Output-Gigawords}','%{Acct-Terminate-Cause}') (12) sql1: --> CALL accounting_stop ('59873E49-0000001A','scilek','80-2A-A8-AD-1E-F9=3ASCILEK.NET','2C-F0-A2-87-C1-CA','10','19062','','17357','','User-Request') (12) sql1: EXPAND /var/log/sqltrace.sql (12) sql1: --> /var/log/sqltrace.sql (12) sql1: Executing query: CALL accounting_stop ('59873E49-0000001A','scilek','80-2A-A8-AD-1E-F9=3ASCILEK.NET','2C-F0-A2-87-C1-CA','10','19062','','17357','','User-Request' ) (12) sql1: SQL query returned: success (12) sql1: 1 record(s) updated rlm_sql (sql1): Released connection (2) rlm_sql (sql1): Closing connection (3), from 16 unused connections rlm_sql_mysql: Socket destructor called, closing socket (12) [sql1] = ok (12) } # redundant sql = ok (12) [exec] = noop (12) if (request:Acct-Status-Type == Interim-Update) { (12) if (request:Acct-Status-Type == Interim-Update) -> FALSE (12) } # accounting = ok (12) Sent Accounting-Response Id 159 from 192.168.0.1:1813 to 192.168.0.4:44463 length 0 (12) Finished request (12) Cleaning up request packet ID 159 with timestamp +32 Ready to process requests (13) Received Access-Request Id 160 from 192.168.0.4:37009 to 192.168.0.1:1812 length 169 (13) User-Name = "anonymous" (13) NAS-Identifier = "802aa8ac1ef9" (13) NAS-Port = 0 (13) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (13) Calling-Station-Id = "00-22-FA-F5-B9-0A" (13) Framed-MTU = 1400 (13) NAS-Port-Type = Wireless-802.11 (13) Connect-Info = "CONNECT 0Mbps 802.11b" (13) EAP-Message = 0x0245000e01616e6f6e796d6f7573 (13) Message-Authenticator = 0x42438b836ce8307cd2ec1cf6757f171e (13) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (13) authorize { (13) [preprocess] = ok (13) redundant sql { (13) sql1: EXPAND %{User-Name} (13) sql1: --> anonymous (13) sql1: SQL-User-Name set to 'anonymous' rlm_sql (sql1): Reserved connection (4) (13) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (13) sql1: --> CALL authorize_check('anonymous') (13) sql1: Executing select query: CALL authorize_check('anonymous') (13) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (13) sql1: --> CALL group_membership('anonymous') (13) sql1: Executing select query: CALL group_membership('anonymous') (13) sql1: User not found in any groups rlm_sql (sql1): Released connection (4) Need 1 more connections to reach min connections (16) rlm_sql (sql1): Opening additional connection (16), 1 of 1 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 (13) [sql1] = notfound (13) } # redundant sql = notfound (13) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (13) pap: WARNING: Authentication will fail unless a "known good" password is available (13) [pap] = noop (13) eap: Peer sent EAP Response (code 2) ID 69 length 14 (13) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (13) [eap] = ok (13) } # authorize = ok (13) Found Auth-Type = eap (13) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (13) authenticate { (13) eap: Peer sent packet with method EAP Identity (1) (13) eap: Calling submodule eap_ttls to process data (13) eap_ttls: Initiating new EAP-TLS session (13) eap_ttls: [eaptls start] = request (13) eap: Sending EAP Request (code 1) ID 70 length 6 (13) eap: EAP session adding &reply:State = 0xdc673415dc2121b4 (13) [eap] = handled (13) } # authenticate = handled (13) Using Post-Auth-Type Challenge (13) Post-Auth-Type sub-section not found. Ignoring. (13) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (13) Sent Access-Challenge Id 160 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (13) EAP-Message = 0x014600061520 (13) Message-Authenticator = 0x00000000000000000000000000000000 (13) State = 0xdc673415dc2121b4141f6b25def0c2b8 (13) Finished request Waking up in 4.9 seconds. (14) Received Access-Request Id 161 from 192.168.0.4:37009 to 192.168.0.1:1812 length 282 (14) User-Name = "anonymous" (14) NAS-Identifier = "802aa8ac1ef9" (14) NAS-Port = 0 (14) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (14) Calling-Station-Id = "00-22-FA-F5-B9-0A" (14) Framed-MTU = 1400 (14) NAS-Port-Type = Wireless-802.11 (14) Connect-Info = "CONNECT 0Mbps 802.11b" (14) EAP-Message = 0x0246006d158000000063160301005e0100005a0301598767992897f75b0513f6af9eda58e324d0eb66100a43cbaefd1e29b80338c6000018002f00350005000ac013c014c009c00a003200 380013000401000019ff01000100000a0006000400170018000b0002010000230000 (14) State = 0xdc673415dc2121b4141f6b25def0c2b8 (14) Message-Authenticator = 0x45abb8d7b842bd7204baa251c0096dbb (14) session-state: No cached attributes (14) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (14) authorize { (14) [preprocess] = ok (14) redundant sql { (14) sql1: EXPAND %{User-Name} (14) sql1: --> anonymous (14) sql1: SQL-User-Name set to 'anonymous' rlm_sql (sql1): Reserved connection (5) (14) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (14) sql1: --> CALL authorize_check('anonymous') (14) sql1: Executing select query: CALL authorize_check('anonymous') (14) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (14) sql1: --> CALL group_membership('anonymous') (14) sql1: Executing select query: CALL group_membership('anonymous') (14) sql1: User not found in any groups rlm_sql (sql1): Released connection (5) (14) [sql1] = notfound (14) } # redundant sql = notfound (14) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (14) pap: WARNING: Authentication will fail unless a "known good" password is available (14) [pap] = noop (14) eap: Peer sent EAP Response (code 2) ID 70 length 109 (14) eap: Continuing tunnel setup (14) [eap] = ok (14) } # authorize = ok (14) Found Auth-Type = eap (14) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (14) authenticate { (14) eap: Expiring EAP session with state 0xdc673415dc2121b4 (14) eap: Finished EAP session with state 0xdc673415dc2121b4 (14) eap: Previous EAP request found for state 0xdc673415dc2121b4, released from the list (14) eap: Peer sent packet with method EAP TTLS (21) (14) eap: Calling submodule eap_ttls to process data (14) eap_ttls: Authenticate (14) eap_ttls: Continuing EAP-TLS (14) eap_ttls: Peer indicated complete TLS record size will be 99 bytes (14) eap_ttls: Got complete TLS record (99 bytes) (14) eap_ttls: [eaptls verify] = length included (14) eap_ttls: (other): before/accept initialization (14) eap_ttls: TLS_accept: before/accept initialization (14) eap_ttls: <<< recv TLS 1.0 Handshake [length 005e], ClientHello (14) eap_ttls: TLS_accept: SSLv3 read client hello A (14) eap_ttls: >>> send TLS 1.0 Handshake [length 0031], ServerHello (14) eap_ttls: TLS_accept: SSLv3 write server hello A (14) eap_ttls: >>> send TLS 1.0 Handshake [length 09de], Certificate (14) eap_ttls: TLS_accept: SSLv3 write certificate A (14) eap_ttls: >>> send TLS 1.0 Handshake [length 0004], ServerHelloDone (14) eap_ttls: TLS_accept: SSLv3 write server done A (14) eap_ttls: TLS_accept: SSLv3 flush data (14) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A (14) eap_ttls: TLS_accept: Need to read more data: SSLv3 read client certificate A (14) eap_ttls: In SSL Handshake Phase (14) eap_ttls: In SSL Accept mode (14) eap_ttls: [eaptls process] = handled (14) eap: Sending EAP Request (code 1) ID 71 length 1004 (14) eap: EAP session adding &reply:State = 0xdc673415dd2021b4 (14) [eap] = handled (14) } # authenticate = handled (14) Using Post-Auth-Type Challenge (14) Post-Auth-Type sub-section not found. Ignoring. (14) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (14) Sent Access-Challenge Id 161 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (14) EAP-Message = 0x014703ec15c000000a2216030100310200002d03011ae4c8a4a3884e49362c42edc1320f9e0b83ee4ad152061ddee7acc2d9e0438200002f000005ff0100010016030109de0b0009da0009 d70005333082052f30820417a003020102020103300d06092a864886f70d01010b050030818f310b30090603 (14) Message-Authenticator = 0x00000000000000000000000000000000 (14) State = 0xdc673415dd2021b4141f6b25def0c2b8 (14) Finished request Waking up in 4.9 seconds. (15) Received Access-Request Id 162 from 192.168.0.4:37009 to 192.168.0.1:1812 length 179 (15) User-Name = "anonymous" (15) NAS-Identifier = "802aa8ac1ef9" (15) NAS-Port = 0 (15) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (15) Calling-Station-Id = "00-22-FA-F5-B9-0A" (15) Framed-MTU = 1400 (15) NAS-Port-Type = Wireless-802.11 (15) Connect-Info = "CONNECT 0Mbps 802.11b" (15) EAP-Message = 0x024700061500 (15) State = 0xdc673415dd2021b4141f6b25def0c2b8 (15) Message-Authenticator = 0x6161f01c2d94dbc44b6786ff344d1311 (15) session-state: No cached attributes (15) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (15) authorize { (15) [preprocess] = ok (15) redundant sql { (15) sql1: EXPAND %{User-Name} (15) sql1: --> anonymous (15) sql1: SQL-User-Name set to 'anonymous' rlm_sql (sql1): Reserved connection (6) (15) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (15) sql1: --> CALL authorize_check('anonymous') (15) sql1: Executing select query: CALL authorize_check('anonymous') (15) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (15) sql1: --> CALL group_membership('anonymous') (15) sql1: Executing select query: CALL group_membership('anonymous') (15) sql1: User not found in any groups rlm_sql (sql1): Released connection (6) (15) [sql1] = notfound (15) } # redundant sql = notfound (15) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (15) pap: WARNING: Authentication will fail unless a "known good" password is available (15) [pap] = noop (15) eap: Peer sent EAP Response (code 2) ID 71 length 6 (15) eap: Continuing tunnel setup (15) [eap] = ok (15) } # authorize = ok (15) Found Auth-Type = eap (15) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (15) authenticate { (15) eap: Expiring EAP session with state 0xdc673415dd2021b4 (15) eap: Finished EAP session with state 0xdc673415dd2021b4 (15) eap: Previous EAP request found for state 0xdc673415dd2021b4, released from the list (15) eap: Peer sent packet with method EAP TTLS (21) (15) eap: Calling submodule eap_ttls to process data (15) eap_ttls: Authenticate (15) eap_ttls: Continuing EAP-TLS (15) eap_ttls: Peer ACKed our handshake fragment (15) eap_ttls: [eaptls verify] = request (15) eap_ttls: [eaptls process] = handled (15) eap: Sending EAP Request (code 1) ID 72 length 1004 (15) eap: EAP session adding &reply:State = 0xdc673415de2f21b4 (15) [eap] = handled (15) } # authenticate = handled (15) Using Post-Auth-Type Challenge (15) Post-Auth-Type sub-section not found. Ignoring. (15) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (15) Sent Access-Challenge Id 162 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (15) EAP-Message = 0x014803ec15c000000a22161c73656c6168617474696e5f63696c656b40686f746d61696c2e636f6d3111300f0603550403130864616d6c612d6361820100301d0603551d25041630140608 2b0601050507030106082b06010505080202300b0603551d0f0404030205a030200603551d11041930178215 (15) Message-Authenticator = 0x00000000000000000000000000000000 (15) State = 0xdc673415de2f21b4141f6b25def0c2b8 (15) Finished request Waking up in 4.9 seconds. (16) Received Access-Request Id 163 from 192.168.0.4:37009 to 192.168.0.1:1812 length 179 (16) User-Name = "anonymous" (16) NAS-Identifier = "802aa8ac1ef9" (16) NAS-Port = 0 (16) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (16) Calling-Station-Id = "00-22-FA-F5-B9-0A" (16) Framed-MTU = 1400 (16) NAS-Port-Type = Wireless-802.11 (16) Connect-Info = "CONNECT 0Mbps 802.11b" (16) EAP-Message = 0x024800061500 (16) State = 0xdc673415de2f21b4141f6b25def0c2b8 (16) Message-Authenticator = 0x8fea16e427c8b3137cf55f16827cd2fa (16) session-state: No cached attributes (16) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (16) authorize { (16) [preprocess] = ok (16) redundant sql { (16) sql1: EXPAND %{User-Name} (16) sql1: --> anonymous (16) sql1: SQL-User-Name set to 'anonymous' rlm_sql (sql1): Reserved connection (7) (16) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (16) sql1: --> CALL authorize_check('anonymous') (16) sql1: Executing select query: CALL authorize_check('anonymous') (16) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (16) sql1: --> CALL group_membership('anonymous') (16) sql1: Executing select query: CALL group_membership('anonymous') (16) sql1: User not found in any groups rlm_sql (sql1): Released connection (7) (16) [sql1] = notfound (16) } # redundant sql = notfound (16) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (16) pap: WARNING: Authentication will fail unless a "known good" password is available (16) [pap] = noop (16) eap: Peer sent EAP Response (code 2) ID 72 length 6 (16) eap: Continuing tunnel setup (16) [eap] = ok (16) } # authorize = ok (16) Found Auth-Type = eap (16) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (16) authenticate { (16) eap: Expiring EAP session with state 0xdc673415de2f21b4 (16) eap: Finished EAP session with state 0xdc673415de2f21b4 (16) eap: Previous EAP request found for state 0xdc673415de2f21b4, released from the list (16) eap: Peer sent packet with method EAP TTLS (21) (16) eap: Calling submodule eap_ttls to process data (16) eap_ttls: Authenticate (16) eap_ttls: Continuing EAP-TLS (16) eap_ttls: Peer ACKed our handshake fragment (16) eap_ttls: [eaptls verify] = request (16) eap_ttls: [eaptls process] = handled (16) eap: Sending EAP Request (code 1) ID 73 length 616 (16) eap: EAP session adding &reply:State = 0xdc673415df2e21b4 (16) [eap] = handled (16) } # authenticate = handled (16) Using Post-Auth-Type Challenge (16) Post-Auth-Type sub-section not found. Ignoring. (16) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (16) Sent Access-Challenge Id 163 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (16) EAP-Message = 0x01490268158000000a22363eead91eb754997cc9e358432fc92ea951cc3bf0ca257b331a7cb6a269a2a68568a263e95de9f53ec3793bc049b13f139ae3b681106134abf5b4d08b02030100 01a381fc3081f9301d0603551d0e04160414af297b64d5335e54578a00c1231a91e0b971ea743081bc060355 (16) Message-Authenticator = 0x00000000000000000000000000000000 (16) State = 0xdc673415df2e21b4141f6b25def0c2b8 (16) Finished request Waking up in 4.9 seconds. (17) Received Access-Request Id 164 from 192.168.0.4:37009 to 192.168.0.1:1812 length 511 (17) User-Name = "anonymous" (17) NAS-Identifier = "802aa8ac1ef9" (17) NAS-Port = 0 (17) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (17) Calling-Station-Id = "00-22-FA-F5-B9-0A" (17) Framed-MTU = 1400 (17) NAS-Port-Type = Wireless-802.11 (17) Connect-Info = "CONNECT 0Mbps 802.11b" (17) EAP-Message = 0x024901501580000001461603010106100001020100a65b4d5c49a2215bba9dc64326661261903eac3adc93ec20ced1a1ef5626ef2c91c948960f7bfb8a82b9c8fe5d831666781bbd3dd80c 98153e7603b42851ab94ac188fd6df6c7b7f79f5678662403e7126fa270fb5c5420fde081949376a29f7f629 (17) State = 0xdc673415df2e21b4141f6b25def0c2b8 (17) Message-Authenticator = 0x0912742ea0e17ef435aefa6a2b785ba8 (17) session-state: No cached attributes (17) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (17) authorize { (17) [preprocess] = ok (17) redundant sql { (17) sql1: EXPAND %{User-Name} (17) sql1: --> anonymous (17) sql1: SQL-User-Name set to 'anonymous' rlm_sql (sql1): Reserved connection (8) (17) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (17) sql1: --> CALL authorize_check('anonymous') (17) sql1: Executing select query: CALL authorize_check('anonymous') (17) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (17) sql1: --> CALL group_membership('anonymous') (17) sql1: Executing select query: CALL group_membership('anonymous') (17) sql1: User not found in any groups rlm_sql (sql1): Released connection (8) (17) [sql1] = notfound (17) } # redundant sql = notfound (17) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (17) pap: WARNING: Authentication will fail unless a "known good" password is available (17) [pap] = noop (17) eap: Peer sent EAP Response (code 2) ID 73 length 336 (17) eap: Continuing tunnel setup (17) [eap] = ok (17) } # authorize = ok (17) Found Auth-Type = eap (17) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (17) authenticate { (17) eap: Expiring EAP session with state 0xdc673415df2e21b4 (17) eap: Finished EAP session with state 0xdc673415df2e21b4 (17) eap: Previous EAP request found for state 0xdc673415df2e21b4, released from the list (17) eap: Peer sent packet with method EAP TTLS (21) (17) eap: Calling submodule eap_ttls to process data (17) eap_ttls: Authenticate (17) eap_ttls: Continuing EAP-TLS (17) eap_ttls: Peer indicated complete TLS record size will be 326 bytes (17) eap_ttls: Got complete TLS record (326 bytes) (17) eap_ttls: [eaptls verify] = length included (17) eap_ttls: <<< recv TLS 1.0 Handshake [length 0106], ClientKeyExchange (17) eap_ttls: TLS_accept: SSLv3 read client key exchange A (17) eap_ttls: TLS_accept: SSLv3 read certificate verify A (17) eap_ttls: <<< recv TLS 1.0 ChangeCipherSpec [length 0001] (17) eap_ttls: <<< recv TLS 1.0 Handshake [length 0010], Finished (17) eap_ttls: TLS_accept: SSLv3 read finished A (17) eap_ttls: >>> send TLS 1.0 ChangeCipherSpec [length 0001] (17) eap_ttls: TLS_accept: SSLv3 write change cipher spec A (17) eap_ttls: >>> send TLS 1.0 Handshake [length 0010], Finished (17) eap_ttls: TLS_accept: SSLv3 write finished A (17) eap_ttls: TLS_accept: SSLv3 flush data (17) eap_ttls: (other): SSL negotiation finished successfully (17) eap_ttls: SSL Connection Established (17) eap_ttls: [eaptls process] = handled (17) eap: Sending EAP Request (code 1) ID 74 length 69 (17) eap: EAP session adding &reply:State = 0xdc673415d82d21b4 (17) [eap] = handled (17) } # authenticate = handled (17) Using Post-Auth-Type Challenge (17) Post-Auth-Type sub-section not found. Ignoring. (17) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (17) Sent Access-Challenge Id 164 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (17) EAP-Message = 0x014a004515800000003b1403010001011603010030b38544bf21cba71d1f37439457db5c83cb9eb80c6d852f51007a0f9fffd3c9b451989f1149d8105e84c05d7a678c7580 (17) Message-Authenticator = 0x00000000000000000000000000000000 (17) State = 0xdc673415d82d21b4141f6b25def0c2b8 (17) Finished request Waking up in 4.9 seconds. (18) Received Access-Request Id 165 from 192.168.0.4:37009 to 192.168.0.1:1812 length 252 (18) User-Name = "anonymous" (18) NAS-Identifier = "802aa8ac1ef9" (18) NAS-Port = 0 (18) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (18) Calling-Station-Id = "00-22-FA-F5-B9-0A" (18) Framed-MTU = 1400 (18) NAS-Port-Type = Wireless-802.11 (18) Connect-Info = "CONNECT 0Mbps 802.11b" (18) EAP-Message = 0x024a004f15800000004517030100401161d9d8f7802510cd5a830be41e537f91f95b6714a56475f21167d83f0dfd2451fa2b34f871f434bffda2190257c023fad8bbf0f673ef9690611a25 a4072032 (18) State = 0xdc673415d82d21b4141f6b25def0c2b8 (18) Message-Authenticator = 0xfb5c045dc54c3a1c5a23567d87d0ae99 (18) session-state: No cached attributes (18) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (18) authorize { (18) [preprocess] = ok (18) redundant sql { (18) sql1: EXPAND %{User-Name} (18) sql1: --> anonymous (18) sql1: SQL-User-Name set to 'anonymous' rlm_sql (sql1): Reserved connection (9) (18) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (18) sql1: --> CALL authorize_check('anonymous') (18) sql1: Executing select query: CALL authorize_check('anonymous') (18) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (18) sql1: --> CALL group_membership('anonymous') (18) sql1: Executing select query: CALL group_membership('anonymous') (18) sql1: User not found in any groups rlm_sql (sql1): Released connection (9) (18) [sql1] = notfound (18) } # redundant sql = notfound (18) pap: WARNING: No "known good" password found for the user. Not setting Auth-Type (18) pap: WARNING: Authentication will fail unless a "known good" password is available (18) [pap] = noop (18) eap: Peer sent EAP Response (code 2) ID 74 length 79 (18) eap: Continuing tunnel setup (18) [eap] = ok (18) } # authorize = ok (18) Found Auth-Type = eap (18) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (18) authenticate { (18) eap: Expiring EAP session with state 0xdc673415d82d21b4 (18) eap: Finished EAP session with state 0xdc673415d82d21b4 (18) eap: Previous EAP request found for state 0xdc673415d82d21b4, released from the list (18) eap: Peer sent packet with method EAP TTLS (21) (18) eap: Calling submodule eap_ttls to process data (18) eap_ttls: Authenticate (18) eap_ttls: Continuing EAP-TLS (18) eap_ttls: Peer indicated complete TLS record size will be 69 bytes (18) eap_ttls: Got complete TLS record (69 bytes) (18) eap_ttls: [eaptls verify] = length included (18) eap_ttls: [eaptls process] = ok (18) eap_ttls: Session established. Proceeding to decode tunneled attributes (18) eap_ttls: Got tunneled request (18) eap_ttls: User-Name = "scilek" (18) eap_ttls: User-Password = "0000" (18) eap_ttls: FreeRADIUS-Proxied-To = 127.0.0.1 (18) eap_ttls: Sending tunneled request (18) Virtual server inner-tunnel-ttls received request (18) User-Name = "scilek" (18) User-Password = "0000" (18) FreeRADIUS-Proxied-To = 127.0.0.1 (18) NAS-Identifier = "802aa8ac1ef9" (18) NAS-Port = 0 (18) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (18) Calling-Station-Id = "00-22-FA-F5-B9-0A" (18) Framed-MTU = 1400 (18) NAS-Port-Type = Wireless-802.11 (18) Connect-Info = "CONNECT 0Mbps 802.11b" (18) Event-Timestamp = "Aug 6 2017 22:01:45 +03" (18) NAS-IP-Address = 192.168.0.4 (18) server inner-tunnel-ttls { (18) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (18) authorize { (18) update control { (18) &Proxy-To-Realm := LOCAL (18) } # update control = noop (18) eap: No EAP-Message, not doing EAP (18) [eap] = noop (18) redundant sql { (18) sql1: EXPAND %{User-Name} (18) sql1: --> scilek (18) sql1: SQL-User-Name set to 'scilek' rlm_sql (sql1): Reserved connection (10) (18) sql1: EXPAND CALL authorize_check('%{SQL-User-Name}') (18) sql1: --> CALL authorize_check('scilek') (18) sql1: Executing select query: CALL authorize_check('scilek') (18) sql1: User found in radcheck table (18) sql1: Conditional check items matched, merging assignment check items (18) sql1: Cleartext-Password := "0000" (18) sql1: Simultaneous-Use := 1 (18) sql1: EXPAND CALL authorize_reply('%{SQL-User-Name}') (18) sql1: --> CALL authorize_reply('scilek') (18) sql1: Executing select query: CALL authorize_reply('scilek') (18) sql1: User found in radreply table, merging reply items (18) sql1: Class := 0x7363696c656b (18) sql1: Idle-Timeout := 120 (18) sql1: Acct-Interim-Interval := 600 (18) sql1: Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (18) sql1: EXPAND CALL group_membership('%{SQL-User-Name}') (18) sql1: --> CALL group_membership('scilek') (18) sql1: Executing select query: CALL group_membership('scilek') (18) sql1: User not found in any groups rlm_sql (sql1): Released connection (10) (18) [sql1] = ok (18) } # redundant sql = ok (18) [expiration] = noop (18) [logintime] = noop (18) [pap] = updated (18) } # authorize = updated (18) WARNING: You set Proxy-To-Realm = LOCAL, but the realm does not exist! Cancelling invalid proxy request. (18) Found Auth-Type = pap (18) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (18) Auth-Type PAP { (18) pap: Login attempt with password (18) pap: Comparing with "known good" Cleartext-Password (18) pap: User authenticated successfully (18) [pap] = ok (18) } # Auth-Type PAP = ok (18) # Executing section session from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (18) session { (18) redundant sql { (18) sql1: EXPAND %{User-Name} (18) sql1: --> scilek (18) sql1: SQL-User-Name set to 'scilek' (18) sql1: EXPAND CALL simul_count('%{SQL-User-Name}') (18) sql1: --> CALL simul_count('scilek') rlm_sql (sql1): Reserved connection (11) (18) sql1: Executing select query: CALL simul_count('scilek') rlm_sql (sql1): Released connection (11) (18) [sql1] = ok (18) } # redundant sql = ok (18) } # session = ok (18) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel-ttls (18) post-auth { (18) if (1) { (18) if (1) -> TRUE (18) if (1) { (18) update reply { (18) User-Name !* ANY (18) Message-Authenticator !* ANY (18) EAP-Message !* ANY (18) Proxy-State !* ANY (18) MS-MPPE-Encryption-Types !* ANY (18) MS-MPPE-Encryption-Policy !* ANY (18) MS-MPPE-Send-Key !* ANY (18) MS-MPPE-Recv-Key !* ANY (18) } # update reply = noop (18) update { (18) &outer.session-state::Class += &reply:Class[*] -> 0x7363696c656b (18) &outer.session-state::Idle-Timeout += &reply:Idle-Timeout[*] -> 120 (18) &outer.session-state::Acct-Interim-Interval += &reply:Acct-Interim-Interval[*] -> 600 (18) &outer.session-state::Exec-Program-Wait += &reply:Exec-Program-Wait[*] -> '/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek' (18) } # update = noop (18) } # if (1) = noop (18) } # post-auth = noop (18) Login OK: [scilek] (from client HOME_AP port 0 cli 00-22-FA-F5-B9-0A via TLS tunnel) (18) } # server inner-tunnel-ttls (18) Virtual server sending reply (18) Class = 0x7363696c656b (18) Idle-Timeout = 120 (18) Acct-Interim-Interval = 600 (18) Exec-Program-Wait = "/usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_auth.sh scilek" (18) eap_ttls: Got tunneled Access-Accept (18) eap: Sending EAP Success (code 3) ID 74 length 4 (18) eap: Freeing handler (18) [eap] = ok (18) } # authenticate = ok (18) # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default (18) post-auth { (18) [exec] = noop (18) policy remove_reply_message_if_eap { (18) if (&reply:EAP-Message && &reply:Reply-Message) { (18) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (18) else { (18) [noop] = noop (18) } # else = noop (18) } # policy remove_reply_message_if_eap = noop (18) } # post-auth = noop (18) Login OK: [anonymous] (from client HOME_AP port 0 cli 00-22-FA-F5-B9-0A) (18) Sent Access-Accept Id 165 from 192.168.0.1:1812 to 192.168.0.4:37009 length 0 (18) MS-MPPE-Recv-Key = 0x151579da0bae738f62b1b12c1150cc56bfa288ec7e69fb8401407407e1756b60 (18) MS-MPPE-Send-Key = 0x67877d1a658cf4f19874c1fe8d9cfa05d7bc7ceb33d6e8d25af8cf5befac456f (18) EAP-Message = 0x034a0004 (18) Message-Authenticator = 0x00000000000000000000000000000000 (18) User-Name = "anonymous" (18) Finished request Waking up in 4.9 seconds. (19) Received Accounting-Request Id 166 from 192.168.0.4:44463 to 192.168.0.1:1813 length 166 (19) Acct-Session-Id = "59873E49-0000001B" (19) Acct-Status-Type = Start (19) Acct-Authentic = RADIUS (19) User-Name = "anonymous" (19) Framed-IP-Address = 0.0.0.0 (19) NAS-Identifier = "802aa8ac1ef9" (19) NAS-Port = 0 (19) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (19) Calling-Station-Id = "00-22-FA-F5-B9-0A" (19) NAS-Port-Type = Wireless-802.11 (19) Connect-Info = "CONNECT 0Mbps 802.11b" (19) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (19) preacct { (19) [preprocess] = ok (19) } # preacct = ok (19) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (19) accounting { (19) detail: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d (19) detail: --> /var/log/radacct/192.168.0.4/detail_2017_08_06 (19) detail: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d expands to /var/log/radacct/192.168.0.4/detail_2017_08_06 (19) detail: EXPAND %t (19) detail: --> Sun Aug 6 22:01:45 2017 (19) [detail] = ok (19) redundant sql { (19) sql1: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (19) sql1: --> type.start.query (19) sql1: Using query template 'query' rlm_sql (sql1): Reserved connection (12) (19) sql1: EXPAND %{User-Name} (19) sql1: --> anonymous (19) sql1: SQL-User-Name set to 'anonymous' (19) sql1: EXPAND CALL accounting_start('%{Acct-Session-Id}','%{SQL-User-Name}','%{Class}','%{NAS-IP-Address}','%{Called-Station-Id}','%{Calling-Station-Id}') (19) sql1: --> CALL accounting_start('59873E49-0000001B','anonymous','','192.168.0.4','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A') (19) sql1: EXPAND /var/log/sqltrace.sql (19) sql1: --> /var/log/sqltrace.sql (19) sql1: Executing query: CALL accounting_start('59873E49-0000001B','anonymous','','192.168.0.4','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A') (19) sql1: SQL query returned: success (19) sql1: 1 record(s) updated rlm_sql (sql1): Released connection (12) (19) [sql1] = ok (19) } # redundant sql = ok (19) [exec] = noop (19) if (request:Acct-Status-Type == Interim-Update) { (19) if (request:Acct-Status-Type == Interim-Update) -> FALSE (19) } # accounting = ok (19) Sent Accounting-Response Id 166 from 192.168.0.1:1813 to 192.168.0.4:44463 length 0 (19) Finished request (19) Cleaning up request packet ID 166 with timestamp +62 Waking up in 4.9 seconds. (20) Received Accounting-Request Id 167 from 192.168.0.4:44463 to 192.168.0.1:1813 length 202 (20) Acct-Session-Id = "59873E49-0000001B" (20) Acct-Status-Type = Interim-Update (20) Acct-Authentic = RADIUS (20) User-Name = "anonymous" (20) Framed-IP-Address = 192.168.0.104 (20) NAS-Identifier = "802aa8ac1ef9" (20) NAS-Port = 0 (20) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (20) Calling-Station-Id = "00-22-FA-F5-B9-0A" (20) NAS-Port-Type = Wireless-802.11 (20) Connect-Info = "CONNECT 0Mbps 802.11b" (20) Acct-Session-Time = 0 (20) Acct-Input-Packets = 11 (20) Acct-Output-Packets = 11 (20) Acct-Input-Octets = 1586 (20) Acct-Output-Octets = 3417 (20) Event-Timestamp = "Aug 6 2017 22:01:39 +03" (20) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (20) preacct { (20) [preprocess] = ok (20) } # preacct = ok (20) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (20) accounting { (20) detail: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d (20) detail: --> /var/log/radacct/192.168.0.4/detail_2017_08_06 (20) detail: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d expands to /var/log/radacct/192.168.0.4/detail_2017_08_06 (20) detail: EXPAND %t (20) detail: --> Sun Aug 6 22:01:45 2017 (20) [detail] = ok (20) redundant sql { (20) sql1: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (20) sql1: --> type.interim-update.query (20) sql1: Using query template 'query' rlm_sql (sql1): Reserved connection (13) (20) sql1: EXPAND %{User-Name} (20) sql1: --> anonymous (20) sql1: SQL-User-Name set to 'anonymous' (20) sql1: EXPAND CALL accounting_update ('%{Acct-Session-Id}','%{Called-Station-Id}','%{Calling-Station-Id}','%{Acct-Session-Time}','%{Acct-Input-Octets}','%{Acct-Input-Gig awords}','%{Acct-Output-Octets}','%{Acct-Output-Gigawords}') (20) sql1: --> CALL accounting_update ('59873E49-0000001B','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A','0','1586','','3417','') (20) sql1: EXPAND /var/log/sqltrace.sql (20) sql1: --> /var/log/sqltrace.sql (20) sql1: Executing query: CALL accounting_update ('59873E49-0000001B','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A','0','1586','','3417','') (20) sql1: SQL query returned: success (20) sql1: 1 record(s) updated rlm_sql (sql1): Released connection (13) (20) [sql1] = ok (20) } # redundant sql = ok (20) [exec] = noop (20) if (request:Acct-Status-Type == Interim-Update) { (20) if (request:Acct-Status-Type == Interim-Update) -> TRUE (20) if (request:Acct-Status-Type == Interim-Update) { (20) check_quota: Executing: /usr/local/bin/bash /usr/local/etc/raddb/scripts/datacounter_acct.sh %{request:User-Name} %{request:Calling-Station-Id} %{request:NAS-IP-Address } %{request:Class} %{request:Acct-Status-Type}: (20) check_quota: EXPAND %{request:User-Name} (20) check_quota: --> anonymous (20) check_quota: EXPAND %{request:Calling-Station-Id} (20) check_quota: --> 00-22-FA-F5-B9-0A (20) check_quota: EXPAND %{request:NAS-IP-Address} (20) check_quota: --> 192.168.0.4 (20) check_quota: EXPAND %{request:Class} (20) check_quota: --> (20) check_quota: EXPAND %{request:Acct-Status-Type} (20) check_quota: --> Interim-Update (20) check_quota: Program executed successfully (20) [check_quota] = ok (20) } # if (request:Acct-Status-Type == Interim-Update) = ok (20) } # accounting = ok (20) Sent Accounting-Response Id 167 from 192.168.0.1:1813 to 192.168.0.4:44463 length 0 (20) Finished request (20) Cleaning up request packet ID 167 with timestamp +62 Waking up in 4.9 seconds. Warning: Using a password on the command line interface can be insecure. Warning: Using a password on the command line interface can be insecure. /usr/local/etc/raddb/scripts/datacounter_acct.sh: line 58: ((: < : syntax error: operand expected (error token is "< ") scilek@192.168.0.4<mailto:scilek@192.168.0.4>'s password: (13) Cleaning up request packet ID 160 with timestamp +62 (14) Cleaning up request packet ID 161 with timestamp +62 (15) Cleaning up request packet ID 162 with timestamp +62 (16) Cleaning up request packet ID 163 with timestamp +62 (17) Cleaning up request packet ID 164 with timestamp +62 (18) Cleaning up request packet ID 165 with timestamp +62 Ready to process requests (21) Received Accounting-Request Id 168 from 192.168.0.4:44463 to 192.168.0.1:1813 length 208 (21) Acct-Session-Id = "59873E49-0000001B" (21) Acct-Status-Type = Stop (21) Acct-Authentic = RADIUS (21) User-Name = "anonymous" (21) Framed-IP-Address = 192.168.0.104 (21) NAS-Identifier = "802aa8ac1ef9" (21) NAS-Port = 0 (21) Called-Station-Id = "80-2A-A8-AD-1E-F9:SCILEK.NET" (21) Calling-Station-Id = "00-22-FA-F5-B9-0A" (21) NAS-Port-Type = Wireless-802.11 (21) Connect-Info = "CONNECT 0Mbps 802.11b" (21) Acct-Session-Time = 25 (21) Acct-Input-Packets = 156 (21) Acct-Output-Packets = 17 (21) Acct-Input-Octets = 13971 (21) Acct-Output-Octets = 4095 (21) Event-Timestamp = "Aug 6 2017 22:02:04 +03" (21) Acct-Terminate-Cause = User-Request (21) # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default (21) preacct { (21) [preprocess] = ok (21) } # preacct = ok (21) # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default (21) accounting { (21) detail: EXPAND /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d (21) detail: --> /var/log/radacct/192.168.0.4/detail_2017_08_06 (21) detail: /var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail_%Y_%m_%d expands to /var/log/radacct/192.168.0.4/detail_2017_08_06 (21) detail: EXPAND %t (21) detail: --> Sun Aug 6 22:02:10 2017 (21) [detail] = ok (21) redundant sql { (21) sql1: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (21) sql1: --> type.stop.query (21) sql1: Using query template 'query' rlm_sql (sql1): Closing connection (14): Hit idle_timeout, was idle for 65 seconds rlm_sql (sql1): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql1): Closing connection (15): Hit idle_timeout, was idle for 65 seconds rlm_sql (sql1): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql1): Closing connection (0): Hit idle_timeout, was idle for 65 seconds rlm_sql (sql1): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql1): Closing connection (1): Hit idle_timeout, was idle for 65 seconds rlm_sql (sql1): You probably need to lower "min" rlm_sql_mysql: Socket destructor called, closing socket rlm_sql (sql1): Reserved connection (2) (21) sql1: EXPAND %{User-Name} (21) sql1: --> anonymous (21) sql1: SQL-User-Name set to 'anonymous' (21) sql1: EXPAND CALL accounting_stop ('%{Acct-Session-Id}','%{SQL-User-Name}','%{Called-Station-Id}','%{Calling-Station-Id}','%{Acct-Session-Time}','%{Acct-Input-Octets}', '%{Acct-Input-Gigawords}','%{Acct-Output-Octets}','%{Acct-Output-Gigawords}','%{Acct-Terminate-Cause}') (21) sql1: --> CALL accounting_stop ('59873E49-0000001B','anonymous','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A','25','13971','','4095','','User-Request') (21) sql1: EXPAND /var/log/sqltrace.sql (21) sql1: --> /var/log/sqltrace.sql (21) sql1: Executing query: CALL accounting_stop ('59873E49-0000001B','anonymous','80-2A-A8-AD-1E-F9=3ASCILEK.NET','00-22-FA-F5-B9-0A','25','13971','','4095','','User-Reques t') (21) sql1: SQL query returned: success (21) sql1: 1 record(s) updated rlm_sql (sql1): Released connection (2) Need 4 more connections to reach min connections (16) rlm_sql (sql1): Opening additional connection (17), 1 of 4 pending slots used rlm_sql_mysql: Starting connect to MySQL server rlm_sql_mysql: Connected to database 'raddb3' on Localhost via UNIX socket, server version 5.6.34, protocol version 10 (21) [sql1] = ok (21) } # redundant sql = ok (21) [exec] = noop (21) if (request:Acct-Status-Type == Interim-Update) { (21) if (request:Acct-Status-Type == Interim-Update) -> FALSE (21) } # accounting = ok (21) Sent Accounting-Response Id 168 from 192.168.0.1:1813 to 192.168.0.4:44463 length 0 (21) Finished request (21) Cleaning up request packet ID 168 with timestamp +87 Ready to process requests [https://ipmcdn.avast.com/images/icons/icon-envelope-tick-round-orange-animated-no-repeat-v1.gif]<https://www.avast.com/sig-email?utm_medium=email&utm_source=link&utm_campaign=sig-email&utm_content=emailclient> Virus-free. www.avast.com<https://www.avast.com/sig-email?utm_medium=email&utm_source=link&utm_campaign=sig-email&utm_content=emailclient>
On Aug 6, 2017, at 9:10 PM, Selahattin Cilek <selahattin_cilek@hotmail.com> wrote:
I have encountered a strange issue with Accounting Request when I connected a fresh-installed Windows 8.1 Pro machine to the Wi-Fi network.
When I connect using an iPhone 5SE, I see the all important Class attribute in the Accounting Request packets, but it is missing when I connect the Windows 8.1 Pro machine. That did not happen with FreeRADIUS 2.2.9. Why does that happen? How can I solve this problem?
How did you migrate your configuration from 2.2.9 to v3? Did you make sure that you copied all of the configuration? Where are you setting the Class attribute? It would help to describe what you're doing, and what you've configured, instead of saying "stuff goes wrong, how do I fix it?" Alan DeKok.
participants (2)
-
Alan DeKok -
Selahattin Cilek