Eap in v4

Aleksandr Stepanov alex-eri at ya.ru
Tue Mar 20 19:46:05 CET 2018


I lost somethinng again

Debug : (8.0)  authenticate eap {
Debug : (8.0)    eap-inner - Peer sent packet with EAP method MSCHAPv2 (26)
Debug : (8.0)    eap-inner - Calling submodule eap_mschapv2
Debug : (8.0)    eap-inner - Empty authenticate section in virtual server "peap-tunnel".  Using default return value (reject)
Debug : (8.0)    eap-inner - Submodule eap_mschapv2 returned
Debug : (8.0)    eap-inner - Sending EAP Failure (code 4) ID 8 length 4
Debug : (8.0)    eap-inner - Cleaning up EAP session
Debug : (8.0)    eap-inner (reject)
Debug : (8.0)  } # authenticate eap (reject)

peap with inner tunnel not working


Info  : FreeRADIUS Version 4.0.0
Info  : Copyright (C) 1999-2017 The FreeRADIUS server project and contributors
Info  : There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
Info  : PARTICULAR PURPOSE
Info  : You may redistribute copies of FreeRADIUS under the terms of the
Info  : GNU General Public License
Info  : For more information about these matters, see the file named COPYRIGHT
Getting debug state failed: ptrace capability not set.  If debugger detection is required run as root or: setcap cap_sys_ptrace+ep <path_to_radiusd>
Info  : Starting - reading configuration files ...
Debug : Including dictionary file "/opt/freeradius/share/freeradius/dictionary"
Debug : Including configuration file "/opt/freeradius/etc/raddb/radiusd.conf"
Debug : Including files in directory "/opt/freeradius/etc/raddb/mods-enabled/"
Debug : Including configuration file "/opt/freeradius/etc/raddb/mods-enabled/always"
Debug : Including configuration file "/opt/freeradius/etc/raddb/mods-enabled/pap"
Debug : Including configuration file "/opt/freeradius/etc/raddb/mods-enabled/expr"
Debug : Including configuration file "/opt/freeradius/etc/raddb/mods-enabled/eap"
Debug : Including configuration file "/opt/freeradius/etc/raddb/mods-enabled/sql"
Debug : Including configuration file "/opt/freeradius/etc/raddb/sql/driver.conf"
Debug : Including configuration file "/opt/freeradius/etc/raddb/sql/queries.conf"
Debug : Including configuration file "/opt/freeradius/etc/raddb/sql/auth.conf"
Debug : Including configuration file "/opt/freeradius/etc/raddb/sql/acct.conf"
Debug : Including configuration file "/opt/freeradius/etc/raddb/mods-enabled/eap-inner"
Debug : Including files in directory "/opt/freeradius/etc/raddb/policy.d/"
Debug : Including configuration file "/opt/freeradius/etc/raddb/policy.d/eap"
Debug : Including configuration file "/opt/freeradius/etc/raddb/server.conf"
Debug : Including configuration file "/opt/freeradius/etc/raddb/clients.conf"
Debug : Including configuration file "/opt/freeradius/etc/raddb/auth.conf"
Debug : Parsing security rules to bootstrap UID / GID / chroot / etc.
Debug : main {
Debug :   security {
Debug :     allow_core_dumps = no
Debug :     reject_delay = 1.000000
Debug :     status_server = yes
Debug :     allow_vulnerable_openssl = "yes"
Debug :   }
Debug :   prefix = "/usr/local"
Debug :   run_dir = "/var//run/radiusd"
Debug : }
Debug : Parsing main configuration.
Debug : main {
Debug :   security {
Debug :   }
Debug :   sbindir = "/usr/local/sbin"
Debug :   logdir = "/var//log"
Debug :   libdir = "/usr/lib/"
Debug :   radacctdir = "/var//log/radacct"
Debug :   hostname_lookups = no
Debug :   max_request_time = 30
Debug :   cleanup_delay = 5
Debug :   continuation_timeout = 15
Debug :   max_requests = 256
Debug :   pidfile = "/var//run/radiusd/radiusd.pid"
Debug :   debug_level = 0
Debug :   proxy_requests = yes
Debug :   log {
Debug :     stripped_names = no
Debug :     auth = yes
Debug :     auth_badpass = no
Debug :     auth_goodpass = no
Debug :     colourise = yes
Debug :     msg_denied = "You are already logged in - access denied"
Debug :   }
Debug :   resources {
Debug :   }
Debug :   thread {
Debug :     num_networks = 1
Debug :     num_workers = 4
Debug :   }
Debug :   server internet {
Debug :     namespace = "radius"
Info  : Loaded module "proto_radius"
Debug :     listen {
Debug :       type = Access-Request
Info  : Loaded module "proto_radius_auth"
Debug :       type = Status-Server
Info  : Loaded module "proto_radius_status"
Debug :       type = Accounting-Request
Info  : Loaded module "proto_radius_acct"
Debug :       transport = udp
Info  : Loaded module "proto_radius_udp"
Debug :       udp {
Debug :         ipaddr = *
Debug :         port = 1812
Debug :         cleanup_delay = 5
Debug :         connected = no
Debug :         dynamic_clients {
Debug :           network = 0.0.0.0/0
Debug :           max_clients = 65536
Debug :           max_pending_clients = 256
Debug :           max_pending_packets = 4096
Debug :           lifetime = 3600
Debug :         }
Debug :       }
Debug :       max_attributes = 255
Debug :     }
Debug :   }
Debug :   server peap-tunnel {
Debug :     namespace = "radius"
Debug :     listen {
Debug :       type = Access-Request
Debug :       transport = udp
Debug :       udp {
Debug :         ipaddr = 127.0.0.1
Debug :         port = 18120
Debug :         cleanup_delay = 5
Debug :         connected = no
Debug :       }
Debug :       max_attributes = 255
Debug :     }
Debug :   }
Debug : }
Info  : Switching to configured log settings
Debug : radiusd: #### Loading Clients ####
Info  : Debug state unknown (cap_sys_ptrace capability not set)
Info  : systemd watchdog is disabled
Debug : #### Bootstrapping listeners ####
Debug : Creating Auth-Type = pap
Debug : Creating Auth-Type = chap
Debug : Creating Auth-Type = mschap
Debug : Creating Auth-Type = digest
Debug : Creating Auth-Type = eap
Info  : Loaded module "proto_radius_dynamic_client"
Debug : #### Bootstrapping modules ####
Debug :  modules {
Info  : Loaded module "rlm_always"
Debug :     always reject {
Debug :       rcode = "reject"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always fail {
Debug :       rcode = "fail"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always ok {
Debug :       rcode = "ok"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always handled {
Debug :       rcode = "handled"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always invalid {
Debug :       rcode = "invalid"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always userlock {
Debug :       rcode = "userlock"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always notfound {
Debug :       rcode = "notfound"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always noop {
Debug :       rcode = "noop"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Debug :     always updated {
Debug :       rcode = "updated"
Debug :       simulcount = 0
Debug :       mpp = no
Debug :     }
Info  : Loaded module "rlm_pap"
Debug :     pap {
Debug :       normalise = yes
Debug :     }
Info  : Loaded module "rlm_chap"
Info  : Loaded module "rlm_mschap"
Debug :     mschap {
Debug :       use_mppe = yes
Debug :       require_encryption = no
Debug :       require_strong = no
Debug :       with_ntdomain_hack = yes
Debug :       passchange {
Debug :       }
Debug :       allow_retry = yes
Debug :       winbind_retry_with_normalised_username = no
Debug :     }
Info  : Loaded module "rlm_digest"
Info  : Loaded module "rlm_expr"
Debug :     expr {
Debug :       safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Debug :     }
Info  : Loaded module "rlm_eap"
Debug :     eap {
Debug :       default_eap_type = peap
Debug :       type = md5
Info  : Loaded module "rlm_eap_md5"
Debug :       type = mschapv2
Info  : Loaded module "rlm_eap_mschapv2"
Debug :       mschapv2 {
Debug :         with_ntdomain_hack = no
Debug :         send_error = no
Debug :         identity = "UNA"
Debug :       }
Debug :       type = peap
Info  : Loaded module "rlm_eap_peap"
Debug :       peap {
Debug :         tls = "tls-common"
Debug :         proxy_tunneled_request_as_eap = yes
Debug :         virtual_server = "peap-tunnel"
Debug :         soh = no
Debug :         require_client_cert = no
Debug :       }
Debug :       ignore_unknown_eap_types = yes
Debug :       cisco_accounting_username_bug = no
Debug :     }
Info  : Loaded module "rlm_sql"
Debug :     sql {
Debug :       driver = "rlm_sql_postgresql"
Debug :       server = ""
Debug :       port = 0
Debug :       login = ""
Debug :       password = <<< secret >>>
Debug :       radius_db = "host=postgres port=5432 dbname=billing user=radius password=raddpass"
Debug :       read_groups = yes
Debug :       read_profiles = yes
Debug :       sql_user_name = "%{User-Name}"
Debug :       default_user_profile = ""
Debug :       authorize_check_query = "SELECT uuid as id, login as UserName, 'Cleartext-Password' as Attribute, password as Value , ':=' as Op FROM login 	WHERE login = 'root' ORDER BY uuid"
Debug :       safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Debug :       accounting {
Debug :         reference = "%{tolower:type.%{%{Acct-Status-Type}:-none}.query}"
Debug :         type {
Debug :           accounting-on {
Debug :           }
Debug :           accounting-off {
Debug :             query = "UPDATE radacct SET AcctStopTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctSessionTime = (%{integer:Event-Timestamp} - EXTRACT(EPOCH FROM(AcctStartTime))), AcctTerminateCause = '%{%{Acct-Terminate-Cause}:-NAS-Reboot}' WHERE AcctStopTime IS NULL AND NASIPAddress= '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}' AND AcctStartTime <= '%S'::timestamp"
Debug :           }
Debug :           start {
Debug :             query = "INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, account_id, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Chargeable-User-Identity}', ''),NULLIF('%{Realm}', ''), '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}', NULLIF('%{%{NAS-Port-ID}:-%{NAS-Port}}', ''), '%{NAS-Port-Type}', TO_TIMESTAMP(%{integer:Event-Timestamp}), TO_TIMESTAMP(%{integer:Event-Timestamp}), NULL, 0, '%{Acct-Authentic}', '%{Connect-Info}', NULL, 0, 0, '%{Called-Station-Id}', '%{Calling-Station-Id}', NULL, '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', '')::inet)"
Debug :             query = "UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), ConnectInfo_start = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL"
Debug :             query = "UPDATE radacct SET AcctStartTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), ConnectInfo_start = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'"
Debug :           }
Debug :           interim-update {
Debug :             query = "UPDATE radacct SET FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, AcctSessionTime = %{%{Acct-Session-Time}:-NULL}, AcctInterval = (%{integer:Event-Timestamp} - EXTRACT(EPOCH FROM (COALESCE(AcctUpdateTime, AcctStartTime)))), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctInputOctets = (('%{%{Acct-Input-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Input-Octets}:-0}'::bigint), AcctOutputOctets = (('%{%{Acct-Output-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Output-Octets}:-0}'::bigint) WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL"
Debug :             query = "INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, account_id, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Chargeable-User-Identity}', ''),NULLIF('%{Realm}', ''), '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}', NULLIF('%{%{NAS-Port-ID}:-%{NAS-Port}}', ''), '%{NAS-Port-Type}', TO_TIMESTAMP(%{integer:Event-Timestamp}), TO_TIMESTAMP(%{integer:Event-Timestamp}), NULL, %{%{Acct-Session-Time}:-NULL}, '%{Acct-Authentic}', '%{Connect-Info}', NULL, (('%{%{Acct-Input-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Input-Octets}:-0}'::bigint), (('%{%{Acct-Output-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Output-Octets}:-0}'::bigint), '%{Called-Station-Id}', '%{Calling-Station-Id}', NULL, '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', '')::inet)"
Debug :           }
Debug :           stop {
Debug :             query = "UPDATE radacct SET AcctStopTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctSessionTime = COALESCE(%{%{Acct-Session-Time}:-NULL}, (%{integer:Event-Timestamp} - EXTRACT(EPOCH FROM(AcctStartTime)))), AcctInputOctets = (('%{%{Acct-Input-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Input-Octets}:-0}'::bigint), AcctOutputOctets = (('%{%{Acct-Output-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Output-Octets}:-0}'::bigint), AcctTerminateCause = '%{Acct-Terminate-Cause}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, ConnectInfo_stop = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}' AND AcctStopTime IS NULL"
Debug :             query = "INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, account_id, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctUpdateTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, ConnectInfo_Stop, AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIpAddress) VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Chargeable-User-Identity}', ''),NULLIF('%{Realm}', ''), '%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}}', NULLIF('%{%{NAS-Port-ID}:-%{NAS-Port}}', ''), '%{NAS-Port-Type}', TO_TIMESTAMP(%{integer:Event-Timestamp} - %{%{Acct-Session-Time}:-0}), TO_TIMESTAMP(%{integer:Event-Timestamp}), TO_TIMESTAMP(%{integer:Event-Timestamp}), NULLIF('%{Acct-Session-Time}', '')::bigint, '%{Acct-Authentic}', '%{Connect-Info}', NULL, (('%{%{Acct-Input-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Input-Octets}:-0}'::bigint), (('%{%{Acct-Output-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Output-Octets}:-0}'::bigint), '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', '')::inet)"
Debug :             query = "UPDATE radacct SET AcctStopTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctUpdateTime = TO_TIMESTAMP(%{integer:Event-Timestamp}), AcctSessionTime = COALESCE(%{%{Acct-Session-Time}:-NULL}, (%{integer:Event-Timestamp} - EXTRACT(EPOCH FROM(AcctStartTime)))), AcctInputOctets = (('%{%{Acct-Input-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Input-Octets}:-0}'::bigint), AcctOutputOctets = (('%{%{Acct-Output-Gigawords}:-0}'::bigint << 32) + '%{%{Acct-Output-Octets}:-0}'::bigint), AcctTerminateCause = '%{Acct-Terminate-Cause}', FramedIPAddress = NULLIF('%{Framed-IP-Address}', '')::inet, ConnectInfo_stop = '%{Connect-Info}' WHERE AcctUniqueId = '%{Acct-Unique-Session-Id}'"
Debug :           }
Debug :         }
Debug :       }
Debug :       post-auth {
Debug :         reference = ".query"
Debug :       }
Debug :     }
Info  : Loaded module "rlm_sql_postgresql"
Debug :       postgresql {
Debug :         send_application_name = yes
Debug :       }
Debug :     eap eap-inner {
Debug :       default_eap_type = md5
Debug :       type = md5
Debug :       type = mschapv2
Debug :       mschapv2 {
Debug :         with_ntdomain_hack = no
Debug :         send_error = no
Debug :         identity = "UNA"
Debug :       }
Debug :       ignore_unknown_eap_types = yes
Debug :       cisco_accounting_username_bug = no
Debug :     }
Debug :   instantiate {
Warn  : /opt/freeradius/etc/raddb/radiusd.conf[45]: Only virtual modules can be instantiated with the instantiate section
Debug :   }
Debug :  } # modules
Debug : #### Instantiating listeners ####
Debug : Compiling policies in server internet { ... }
Debug : Compiling policies - new client {...}
Debug : Compiling policies - add client {...}
Debug : Compiling policies - deny client {...}
Debug : compiling - recv Access-Request {...}
Debug : compiling - recv Status-Server {...}
Debug : compiling - recv Accounting-Request {...}
Error : /opt/freeradius/etc/raddb/auth.conf[16]: "sql" modules aren't allowed in 'recv Accounting-Request { ... }' sections -- they have no such method.
Warn  : /opt/freeradius/etc/raddb/auth.conf[16]: Ignoring "sql" (see raddb/mods-available/README.rst)
Debug : compiling - send Access-Challenge {...}
Debug : compiling - send Access-Accept {...}
Debug : Compiling policies - authenticate pap {...}
Debug : Compiling policies - authenticate chap {...}
Debug : Compiling policies - authenticate mschap {...}
Debug : Compiling policies - authenticate digest {...}
Debug : Compiling policies - authenticate eap {...}
Debug : Compiling policies in server peap-tunnel { ... }
Debug : compiling - recv Access-Request {...}
Debug : compiling - send Access-Accept {...}
Debug : Compiling policies - authenticate eap {...}
Debug : Compiling policies - authenticate pap {...}
Debug : #### Instantiating modules ####
Debug : Instantiating module "eap"
Debug :       tls-config tls-common {
Debug :         auto_chain = yes
Debug :         chain {
Debug :           format = pem
Debug :           certificate_file = "/opt/freeradius/etc/raddb/certs/server.pem"
Debug :           private_key_file = "/opt/freeradius/etc/raddb/certs/server.pem"
Debug :           verify_mode = hard
Debug :           include_root_ca = no
Debug :         }
Debug :         verify_depth = 0
Debug :         fragment_size = 1024
Debug :         check_crl = no
Debug :         cipher_list = "DEFAULT"
Debug :         cipher_server_preference = yes
Debug :         allow_renegotiation = no
Debug :         ecdh_curve = "prime256v1"
Debug :         tls_min_version = 1.000000
Debug :         cache {
Debug :           lifetime = 86400
Debug :           verify = no
Debug :           require_extended_master_secret = yes
Debug :           require_perfect_forward_secrecy = no
Debug :         }
Debug :         verify {
Debug :         }
Debug :         ocsp {
Debug :           enable = no
Debug :           override_cert_url = no
Debug :           use_nonce = yes
Debug :           timeout = 0
Debug :           softfail = no
Debug :         }
Debug :         staple {
Debug :           enable = no
Debug :           override_cert_url = no
Debug :           use_nonce = yes
Debug :           timeout = 0
Debug :           softfail = no
Debug :         }
Debug :       }
Debug : Instantiating module "eap-inner"
Debug : Instantiating module "fail"
Debug : Instantiating module "handled"
Debug : Instantiating module "invalid"
Debug : Instantiating module "mschap"
Debug : mschap: using internal authentication
Debug : Instantiating module "noop"
Debug : Instantiating module "notfound"
Debug : Instantiating module "ok"
Debug : Instantiating module "pap"
Debug : Instantiating module "reject"
Debug : Instantiating module "sql"
Info  : rlm_sql (sql) - Attempting to connect to database "host=postgres port=5432 dbname=billing user=radius password=raddpass"
Debug : rlm_sql (sql) - Initialising connection pool
Debug :       pool {
Debug :         start = 5
Debug :         min = 3
Debug :         max = 32
Debug :         max_pending = 0
Debug :         spare = 10
Debug :         uses = 0
Debug :         lifetime = 0
Debug :         cleanup_interval = 30
Debug :         idle_timeout = 60
Debug :         connect_timeout = 3.000000
Debug :         held_trigger_min = 0.000000
Debug :         held_trigger_max = 0.500000
Debug :         retry_delay = 30
Debug :         spread = no
Debug :       }
Debug : rlm_sql (sql) - Opening additional connection (0), 1 of 32 pending slots used
Debug : rlm_sql_postgresql - Connecting using parameters: host=postgres port=5432 dbname=billing user=radius password=raddpass application_name='FreeRADIUS 4.0.0 - radiusd (sql)'
Debug : rlm_sql_postgresql - Connected to database 'billing' on 'postgres' server version 100003, protocol version 3, backend PID 672 
Debug : rlm_sql (sql) - Opening additional connection (1), 1 of 31 pending slots used
Debug : rlm_sql_postgresql - Connecting using parameters: host=postgres port=5432 dbname=billing user=radius password=raddpass application_name='FreeRADIUS 4.0.0 - radiusd (sql)'
Debug : rlm_sql_postgresql - Connected to database 'billing' on 'postgres' server version 100003, protocol version 3, backend PID 673 
Debug : rlm_sql (sql) - Opening additional connection (2), 1 of 30 pending slots used
Debug : rlm_sql_postgresql - Connecting using parameters: host=postgres port=5432 dbname=billing user=radius password=raddpass application_name='FreeRADIUS 4.0.0 - radiusd (sql)'
Debug : rlm_sql_postgresql - Connected to database 'billing' on 'postgres' server version 100003, protocol version 3, backend PID 674 
Debug : rlm_sql (sql) - Opening additional connection (3), 1 of 29 pending slots used
Debug : rlm_sql_postgresql - Connecting using parameters: host=postgres port=5432 dbname=billing user=radius password=raddpass application_name='FreeRADIUS 4.0.0 - radiusd (sql)'
Debug : rlm_sql_postgresql - Connected to database 'billing' on 'postgres' server version 100003, protocol version 3, backend PID 675 
Debug : rlm_sql (sql) - Opening additional connection (4), 1 of 28 pending slots used
Debug : rlm_sql_postgresql - Connecting using parameters: host=postgres port=5432 dbname=billing user=radius password=raddpass application_name='FreeRADIUS 4.0.0 - radiusd (sql)'
Debug : rlm_sql_postgresql - Connected to database 'billing' on 'postgres' server version 100003, protocol version 3, backend PID 676 
Debug : Instantiating module "updated"
Debug : Instantiating module "userlock"
Debug : Scheduler created in single-threaded mode
Debug : #### Opening listener interfaces ####
Debug : Listening on radius address proto udp address * port 1812 bound to virtual server internet
Debug : Listening on radius address proto udp address 127.0.0.1 port 18120 bound to virtual server peap-tunnel
Info  : Ready to process requests
Info  : Ready to process requests
Info  : Ready to process requests
Debug : Found matching network.  Checking for dynamic client definition.
Debug : Network received packet size 128
Info  : Ready to process requests
Debug : Resetting worker cleanup timer to +30s
Debug : (0)  running request
Debug : (0)  Received Access-Request ID 136
Debug : (0)    User-Name = "root"
Debug : (0)    NAS-IP-Address = 192.168.117.1
Debug : (0)    NAS-Identifier = "RalinkAP0"
Debug : (0)    NAS-Port = 0
Debug : (0)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (0)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (0)    Framed-MTU = 1400
Debug : (0)    NAS-Port-Type = Wireless-802.11
Debug : (0)    EAP-Message = 0x0201000901726f6f74
Debug : (0)    Message-Authenticator = 0x0a89466ca425ba15608ae5910e409384
Debug : (0)  Running 'new client' from file /opt/freeradius/etc/raddb/clients.conf
Debug : (0)  new client {
Debug : (0)    EXPAND %{NAS-Identifier}
Debug : (0)      --> RalinkAP0
Debug : (0)    MAP sql "SELECT type,secret,server FROM nas WHERE shortname = 'RalinkAP0'"
Debug : (0)    EXPAND %{User-Name}
Debug : (0)    --> root
Debug : (0)    SQL-User-Name set to 'root'
Debug : (0)    Reserved connection (4)
Debug : (0)    Executing select query: SELECT type,secret,server FROM nas WHERE shortname = 'RalinkAP0'
Debug : rlm_sql_postgresql - Status: PGRES_TUPLES_OK
Debug : rlm_sql_postgresql - query affected rows = 1 , fields = 3
Debug : (0)    &control:FreeRADIUS-Client-NAS-Type = other
Debug : (0)    &control:FreeRADIUS-Client-Secret = secret
Debug : (0)    &control:FreeRADIUS-Client-Virtual-Server = internet
Debug : (0)    Released connection (4)
Info  : (0)    Need 5 more connections to reach 10 spares
Debug : (0)    Opening additional connection (5), 1 of 27 pending slots used
Debug : rlm_sql_postgresql - Connecting using parameters: host=postgres port=5432 dbname=billing user=radius password=raddpass application_name='FreeRADIUS 4.0.0 - radiusd (sql)'
Debug : rlm_sql_postgresql - Connected to database 'billing' on 'postgres' server version 100003, protocol version 3, backend PID 678 
Debug : (0)    Closing expired connection (4): Needs reconnecting
Debug : rlm_sql_postgresql - Socket destructor called, closing socket
Debug : (0)    Closing expired connection (3): Needs reconnecting
Debug : rlm_sql_postgresql - Socket destructor called, closing socket
Debug : (0)    Closing expired connection (2): Needs reconnecting
Debug : rlm_sql_postgresql - Socket destructor called, closing socket
Debug : (0)    Closing expired connection (1): Needs reconnecting
Debug : (0)    You probably need to lower "min"
Debug : rlm_sql_postgresql - Socket destructor called, closing socket
Debug : (0)    Closing expired connection (0): Needs reconnecting
Debug : (0)    You probably need to lower "min"
Debug : rlm_sql_postgresql - Socket destructor called, closing socket
Debug : (0)    update control {
Debug : (0)      EXPAND %{Packet-Src-IP-Address}
Debug : (0)        --> 192.168.117.1
Debug : (0)      EXPAND %{NAS-Identifier}
Debug : (0)        --> RalinkAP0
Debug : (0)      &FreeRADIUS-Client-IP-Address = 192.168.117.1
Debug : (0)      &FreeRADIUS-Client-Shortname = "RalinkAP0"
Debug : (0)    } # update control (noop)
Debug : (0)  } # new client (updated)
Debug : (0)  Running 'add client' from file /opt/freeradius/etc/raddb/clients.conf
Debug : (0)  add client {
Debug : (0)    ok (ok)
Debug : (0)  } # add client (ok)
Debug : (0)  Adding client
Debug : (0)  done request
Debug : (0)  Converting &request:control to client {...} section
Debug : (0)    nas_type = other
Debug : (0)    secret = secret
Debug : (0)    ipv4addr = 192.168.117.1
Debug : (0)    shortname = RalinkAP0
Debug : client dynamic0 {
Debug :   ipv4addr = 192.168.117.1
Debug :   require_message_authenticator = no
Debug :   secret = <<< secret >>>
Debug :   shortname = "RalinkAP0"
Debug :   nas_type = "other"
Debug :   limit {
Debug :     max_connections = 16
Debug :     lifetime = 0
Debug :     idle_timeout = 30
Debug :   }
Debug : }
Debug : (0)  finished request.
Debug : Waking up in 28.6 seconds.
Debug : proto udp address * port 1812 - Defining new client 
Debug : Waking up in 28.6 seconds.
Debug : Waking up in 28.6 seconds.
Debug : Network received packet size 128
Debug : Waking up in 27.6 seconds.
Debug : (1)  running request
Debug : (1)  Received Access-Request ID 136
Debug : (1)    User-Name = "root"
Debug : (1)    NAS-IP-Address = 192.168.117.1
Debug : (1)    NAS-Identifier = "RalinkAP0"
Debug : (1)    NAS-Port = 0
Debug : (1)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (1)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (1)    Framed-MTU = 1400
Debug : (1)    NAS-Port-Type = Wireless-802.11
Debug : (1)    EAP-Message = 0x0201000901726f6f74
Debug : (1)    Message-Authenticator = 0x0a89466ca425ba15608ae5910e409384
Debug : (1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (1)  recv Access-Request {
Debug : (1)    chap (noop)
Debug : (1)    mschap (noop)
Debug : (1)    eap - Peer sent EAP Response (code 2) ID 1 length 9
Debug : (1)    eap - Peer sent EAP-Identity.  Returning 'ok' so we can short-circuit the rest of authorize
Debug : (1)    eap (ok)
Debug : (1)  } # recv Access-Request (ok)
Debug : (1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (1)  authenticate eap {
Debug : (1)    eap - Peer sent packet with EAP method Identity (1)
Debug : (1)    eap - Calling submodule eap_peap
Debug : (1)    eap - Initiating new TLS session
Debug : (1)    eap - EXPAND %{EAP-Type}%{Virtual-Server}
Debug : (1)    eap - --> Identityinternet
Debug : (1)    eap - Submodule eap_peap returned
Debug : (1)    eap - Sending EAP Request (code 1) ID 2 length 6
Debug : (1)    eap (handled)
Debug : (1)  } # authenticate eap (handled)
Debug : (1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (1)  send Access-Challenge {
Debug : (1)    handled (handled)
Debug : (1)  } # send Access-Challenge (handled)
Debug : (1)  Sent code 11 Id 136 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (1)    EAP-Message = 0x010200061920
Debug : (1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (1)    State = 0x9582b11402620f2da3373c745f8886f0
Debug : (1)  done request
Debug : (1)  finished request.
Debug : Waking up in 27.6 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 452
Debug : Waking up in 4.9 seconds.
Debug : Resetting worker cleanup timer to +30s
Debug : (2)  running request
Debug : (2)  Received Access-Request ID 137
Debug : (2)    User-Name = "root"
Debug : (2)    NAS-IP-Address = 192.168.117.1
Debug : (2)    NAS-Identifier = "RalinkAP0"
Debug : (2)    NAS-Port = 0
Debug : (2)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (2)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (2)    Framed-MTU = 1400
Debug : (2)    NAS-Port-Type = Wireless-802.11
Debug : (2)    EAP-Message = 0x0202013919800000012f160301012a01000126030344df9cd20fc70a21a4c1157d9cbc6653022e9de7d98aabd2a1bc6b80f5bccd970000acc030c02cc028c024c014c00a00a500a300a1009f006b006a0069006800390038003700360088008700860085c032c02ec02ac026c00fc005009d003d00350084c02fc02bc027c023c013c00900a400a200a0009e00670040003f003e0033003200310030009a0099009800970045004400430042c031c02dc029c025c00ec004009c003c002f009600410007c011c007c00cc00200050004c012c008001600130010000dc00dc003000a00ff01000051000b000403000102000a001c001a00170019001c001b0018001a0016000e000d000b000c0009000a000d0020001e060106020603050105020503040104020403030103020303020102020203000f000101
Debug : (2)    State = 0x9582b11402620f2da3373c745f8886f0
Debug : (2)    Message-Authenticator = 0xd5652f41458e9052701f8635bb625ef6
Debug : (2,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (2,1)  recv Access-Request {
Debug : (2,1)    chap (noop)
Debug : (2,1)    mschap (noop)
Debug : (2,1)    eap - Peer sent EAP Response (code 2) ID 2 length 313
Debug : (2,1)    eap - Continuing tunnel setup
Debug : (2,1)    eap (ok)
Debug : (2,1)  } # recv Access-Request (ok)
Debug : (2,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (2,1)  authenticate eap {
Debug : (2,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (2,1)    eap - Calling submodule eap_peap
Debug : (2,1)    eap - Continuing EAP-TLS
Debug : (2,1)    eap - Peer indicated complete TLS record size will be 303 bytes
Debug : (2,1)    eap - Got complete TLS record, with length field (303 bytes)
Debug : (2,1)    eap - [eap-tls verify] = complete
Debug : (2,1)    eap - Handshake state - before SSL initialization
Debug : (2,1)    eap - Handshake state - Server before SSL initialization
Debug : (2,1)    eap - Handshake state - Server before SSL initialization
Debug : (2,1)    eap - <<< recv TLS 1.2 handshake [length 298], client_hello 
Debug : (2,1)    eap - Handshake state - Server SSLv3/TLS read client hello
Debug : (2,1)    eap - >>> send TLS 1.2 handshake [length 57], server_hello 
Debug : (2,1)    eap - Handshake state - Server SSLv3/TLS write server hello
Debug : (2,1)    eap - >>> send TLS 1.2 handshake [length 977], certificate 
Debug : (2,1)    eap - Handshake state - Server SSLv3/TLS write certificate
Debug : (2,1)    eap - >>> send TLS 1.2 handshake [length 333], server_key_exchange 
Debug : (2,1)    eap - Handshake state - Server SSLv3/TLS write key exchange
Debug : (2,1)    eap - >>> send TLS 1.2 handshake [length 4], server_hello_done 
Debug : (2,1)    eap - Handshake state - Server SSLv3/TLS write server done
Debug : (2,1)    eap - Need more data from client
Debug : (2,1)    eap - Complete TLS record (1391 bytes) larger than MTU (1010 bytes), will fragment
Debug : (2,1)    eap - Sending first TLS record fragment (1010 bytes), 381 bytes remaining
Debug : (2,1)    eap - [eap-tls process] = handled
Debug : (2,1)    eap - Submodule eap_peap returned
Debug : (2,1)    eap - Sending EAP Request (code 1) ID 3 length 1020
Debug : (2,1)    eap (handled)
Debug : (2,1)  } # authenticate eap (handled)
Debug : (2,1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (2,1)  send Access-Challenge {
Debug : (2,1)    handled (handled)
Debug : (2,1)  } # send Access-Challenge (handled)
Debug : (2,1)  Sent code 11 Id 137 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (2,1)    EAP-Message = 0x010303fc19c00000056f1603030039020000350303549703689a939aeac1c66f69ed8baea993f697fbe505022dfe1de234167cbeee00c03000000dff01000100000b00040300010216030303d10b0003cd0003ca0003c7308203c3308202ab020900afb3f37fbfccf043300d06092a864886f70d01010b05003081ba310b30090603550406130252553118301606035504080c0f526f73746f76736b617961206f626c3117301506035504070c0e42656c617961204b616c6974766131283026060355040a0c1f495020436865726b61736f7620416e647265792056696b746f726f766963683110300e060355040b0c0742696c6c696e673118301606035504030c0f495020436865726b61736f762043413122302006092a864886f70d01090116137a61726563682e6d7440676d61696c2e636f6d301e170d3136313230323233303734345a170d3139303231303233303734345a30818b310b30090603550406130252553114301206035504080c0b4976616e6f76736b6179613110300e06035504070c074976616e6f766f310f300d060355040a0c0645657269657331133011060355040b0c0a4e6574776f726b696e67310f300d06035504030c06526164697573311d301b06092a864886f70d010901160e616c65782d6572694079612e727530820122300d06092a864886f70d01010105000382010f003082010a0282010100e7cbf2e573ded0439a98f471d6665a77265f4286d7d8470dc867ef1e05fbf980871fb0acca211769d3bb3a3e03ea9ba934ca1e07788d0229daa48f785a159453d1040b8e6ae38a05049c7b375dfd261a6c86380cce8c226336875fa3bf5f3989381c4192ab5f1416181af8f6dee8a8c1793319865554cebe79ebe5e4fe528b0a8a8305583a83d499c3951e518c2354f21dcf1bf24620a53bf506ca965dcc7d62c979f3cd4a1c15a9586b83cc1988f71d9ef246fe0ac5cd1eff6f28bdf3d64fbc9080376767d65991e81b9707b258a5c71149b7e13ba6618b09a04fc7c6e5a32d23710e08b9edc034f83e65c7a2272cbd882130f617f0f1965180a1628286de010203010001300d06092a864886f70d01010b0500038201010031d9a5dbf25b9e68e3328741adf3b5a9285e6fbff761903dc2c6492f1c2b4efafa9c0252ee3d69586fc065b08728604a9d6a651d601d255264ceecd5989728e89635fbce5e64f09294e1635076cb4dd44a2bd9c6ce17d2234d201ada79d7415c6ccd8fb24430ed51d0de114d705a86f6ffc45275e6d557ec0e9960a73a47eda65b33002afbd5f133ba3f87839448ba556ae5c3eb821e56ce97aa918d64d1e190bb3daaceb4c742acc67e64bce3a986228cdb4da70346f43905100f47332196cb248e5e8f011d9df204f8b12c5939c3b02af
eff1e495577947292d03d7b5b
Debug : (2,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (2,1)    State = 0xb2642b2a813d8f79ac8a8184b2c3da85
Debug : (2)  done request
Debug : (2)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 143
Debug : Waking up in 4.9 seconds.
Debug : (3)  running request
Debug : (3)  Received Access-Request ID 138
Debug : (3)    User-Name = "root"
Debug : (3)    NAS-IP-Address = 192.168.117.1
Debug : (3)    NAS-Identifier = "RalinkAP0"
Debug : (3)    NAS-Port = 0
Debug : (3)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (3)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (3)    Framed-MTU = 1400
Debug : (3)    NAS-Port-Type = Wireless-802.11
Debug : (3)    EAP-Message = 0x020300061900
Debug : (3)    State = 0xb2642b2a813d8f79ac8a8184b2c3da85
Debug : (3)    Message-Authenticator = 0xf805b9a6268f13776c3d1eab0daaf378
Debug : (3,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (3,1)  recv Access-Request {
Debug : (3,1)    chap (noop)
Debug : (3,1)    mschap (noop)
Debug : (3,1)    eap - Peer sent EAP Response (code 2) ID 3 length 6
Debug : (3,1)    eap - Continuing tunnel setup
Debug : (3,1)    eap (ok)
Debug : (3,1)  } # recv Access-Request (ok)
Debug : (3,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (3,1)  authenticate eap {
Debug : (3,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (3,1)    eap - Calling submodule eap_peap
Debug : (3,1)    eap - Continuing EAP-TLS
Debug : (3,1)    eap - Peer ACKed our handshake fragment
Debug : (3,1)    eap - [eap-tls verify] = request
Debug : (3,1)    eap - Sending final TLS record fragment (381 bytes)
Debug : (3,1)    eap - [eap-tls process] = handled
Debug : (3,1)    eap - Submodule eap_peap returned
Debug : (3,1)    eap - Sending EAP Request (code 1) ID 4 length 387
Debug : (3,1)    eap (handled)
Debug : (3,1)  } # authenticate eap (handled)
Debug : (3,1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (3,1)  send Access-Challenge {
Debug : (3,1)    handled (handled)
Debug : (3,1)  } # send Access-Challenge (handled)
Debug : (3,1)  Sent code 11 Id 138 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (3,1)    EAP-Message = 0x010401831900fbbaf15e1a3e293a327e82d010cdd49f3559bc29d02fce116a258446e8ce9e7c6402160303014d0c0001490300174104c93a5787ae35adc6bfd9144e20cbd8c58d75f48444ac828c73bd949feb7ebeebbff328c4a6644b8457428236836e716b45b93b17da3baf4d6f7b2120842697f106010100afec75a99af69478fadfad73b6701bf7cfc54b93229339b7ee3951e6f3b94605ddd6046fca2f431ef26238ce43e2a1c69064aa8fb8708039eb596418c184689220a6baea52deb8fbc6c4fe33f4611b1f8fc13ecc133da24a2d2083836886d65341c4bea240fd325cc7c2a6fcb3af220bcbae77fe456e8ba8fcf133e12e9e113821d1fddf56d097ab8bb4c3f6bab8a26ab464041b141bdf99b76f1fc49be4ce44348d8e0ccd7dbc5533cffd6275665dd3606d1bb2a10d3a56d9aacb155522b3344442f9a1d6f65692b84f50b7a90f11cfbbf98b3ddc661a05f83af3c80a0fb11310c467cbb8aaf896d56584fd85d3d91f1d02b3eca5af419230a2539c6eb55de316030300040e000000
Debug : (3,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (3,1)    State = 0x65d194cfa08ad2d79bedf3ecee9534ae
Debug : (3)  done request
Debug : (3)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 273
Debug : Waking up in 4.9 seconds.
Debug : (4)  running request
Debug : (4)  Received Access-Request ID 139
Debug : (4)    User-Name = "root"
Debug : (4)    NAS-IP-Address = 192.168.117.1
Debug : (4)    NAS-Identifier = "RalinkAP0"
Debug : (4)    NAS-Port = 0
Debug : (4)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (4)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (4)    Framed-MTU = 1400
Debug : (4)    NAS-Port-Type = Wireless-802.11
Debug : (4)    EAP-Message = 0x0204008819800000007e1603030046100000424104da13159aa0ac86434cc6d7f84ecc35ed7a8c1e8b5d283b5379eb6fbab21da0c36bb0947adb8f3fd8403c490d694a8ad709f5c273173af8224f565a76dc1d0e961403030001011603030028a067af59dd1d68664ec57e42d6ea2cadf396a82902ecae3ca160a3f43ae92520b121198f8cd39a20
Debug : (4)    State = 0x65d194cfa08ad2d79bedf3ecee9534ae
Debug : (4)    Message-Authenticator = 0x2abbb039a268c2a0f7c29a349ed6ee03
Debug : (4,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (4,1)  recv Access-Request {
Debug : (4,1)    chap (noop)
Debug : (4,1)    mschap (noop)
Debug : (4,1)    eap - Peer sent EAP Response (code 2) ID 4 length 136
Debug : (4,1)    eap - Continuing tunnel setup
Debug : (4,1)    eap (ok)
Debug : (4,1)  } # recv Access-Request (ok)
Debug : (4,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (4,1)  authenticate eap {
Debug : (4,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (4,1)    eap - Calling submodule eap_peap
Debug : (4,1)    eap - Continuing EAP-TLS
Debug : (4,1)    eap - Peer indicated complete TLS record size will be 126 bytes
Debug : (4,1)    eap - Got complete TLS record, with length field (126 bytes)
Debug : (4,1)    eap - [eap-tls verify] = complete
Debug : (4,1)    eap - Handshake state - Server SSLv3/TLS write server done
Debug : (4,1)    eap - <<< recv TLS 1.2 handshake [length 70], client_key_exchange 
Debug : (4,1)    eap - Handshake state - Server SSLv3/TLS read client key exchange
Debug : (4,1)    eap - Handshake state - Server SSLv3/TLS read change cipher spec
Debug : (4,1)    eap - <<< recv TLS 1.2 handshake [length 16], finished 
Debug : (4,1)    eap - Handshake state - Server SSLv3/TLS read finished
Debug : (4,1)    eap - >>> send TLS 1.2 change_cipher_spec [length 1] 
Debug : (4,1)    eap - Handshake state - Server SSLv3/TLS write change cipher spec
Debug : (4,1)    eap - >>> send TLS 1.2 handshake [length 16], finished 
Debug : (4,1)    eap - Handshake state - Server SSLv3/TLS write finished
Debug : (4,1)    eap - Handshake state - SSL negotiation finished successfully
Debug : (4,1)    eap - Cipher suite: CDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH Au=RSA Enc=AESGCM(256) Mac=AEAD 
Debug : (4,1)    eap - Sending complete TLS record (51 bytes)
Debug : (4,1)    eap - [eap-tls process] = handled
Debug : (4,1)    eap - Submodule eap_peap returned
Debug : (4,1)    eap - Sending EAP Request (code 1) ID 5 length 57
Debug : (4,1)    eap (handled)
Debug : (4,1)  } # authenticate eap (handled)
Debug : (4,1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (4,1)  send Access-Challenge {
Debug : (4,1)    handled (handled)
Debug : (4,1)  } # send Access-Challenge (handled)
Debug : (4,1)  Sent code 11 Id 139 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (4,1)    EAP-Message = 0x01050039190014030300010116030300280b604285400b205afdec0353bedec29d892baf11dde8bd350919c83674207294df0ddb99275a7b1e
Debug : (4,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (4,1)    State = 0x178ff424c1fbc3000969a78129d34a8f
Debug : (4)  done request
Debug : (4)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 143
Debug : Waking up in 4.9 seconds.
Debug : (5)  running request
Debug : (5)  Received Access-Request ID 140
Debug : (5)    User-Name = "root"
Debug : (5)    NAS-IP-Address = 192.168.117.1
Debug : (5)    NAS-Identifier = "RalinkAP0"
Debug : (5)    NAS-Port = 0
Debug : (5)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (5)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (5)    Framed-MTU = 1400
Debug : (5)    NAS-Port-Type = Wireless-802.11
Debug : (5)    EAP-Message = 0x020500061900
Debug : (5)    State = 0x178ff424c1fbc3000969a78129d34a8f
Debug : (5)    Message-Authenticator = 0x4554a700ca22859f544c194d9bdb71d0
Debug : (5,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (5,1)  recv Access-Request {
Debug : (5,1)    chap (noop)
Debug : (5,1)    mschap (noop)
Debug : (5,1)    eap - Peer sent EAP Response (code 2) ID 5 length 6
Debug : (5,1)    eap - Continuing tunnel setup
Debug : (5,1)    eap (ok)
Debug : (5,1)  } # recv Access-Request (ok)
Debug : (5,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (5,1)  authenticate eap {
Debug : (5,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (5,1)    eap - Calling submodule eap_peap
Debug : (5,1)    eap - Continuing EAP-TLS
Debug : (5,1)    eap - Peer ACKed our handshake fragment.  handshake is finished
Debug : (5,1)    eap - [eap-tls verify] = established
Debug : (5,1)    eap - [eap-tls process] = established
Debug : (5,1)    eap - Session established.  Decoding tunneled data
Debug : (5,1)    eap - PEAP state TUNNEL ESTABLISHED
Debug : (5,1)    eap - TLS application data to encrypt (5 bytes)
Debug : (5,1)    eap - Sending complete TLS record (34 bytes)
Debug : (5,1)    eap - Submodule eap_peap returned
Debug : (5,1)    eap - Sending EAP Request (code 1) ID 6 length 40
Debug : (5,1)    eap (handled)
Debug : (5,1)  } # authenticate eap (handled)
Debug : (5,1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (5,1)  send Access-Challenge {
Debug : (5,1)    handled (handled)
Debug : (5,1)  } # send Access-Challenge (handled)
Debug : (5,1)  Sent code 11 Id 140 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (5,1)    EAP-Message = 0x010600281900170303001d0b604285400b205b40e47b90a19c022cc58cf77d2435bd2dbdde93d7fe
Debug : (5,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (5,1)    State = 0xdd9d61181528ed51c335dd222177283e
Debug : (5)  done request
Debug : (5)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 177
Debug : Waking up in 4.9 seconds.
Debug : (6)  running request
Debug : (6)  Received Access-Request ID 141
Debug : (6)    User-Name = "root"
Debug : (6)    NAS-IP-Address = 192.168.117.1
Debug : (6)    NAS-Identifier = "RalinkAP0"
Debug : (6)    NAS-Port = 0
Debug : (6)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (6)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (6)    Framed-MTU = 1400
Debug : (6)    NAS-Port-Type = Wireless-802.11
Debug : (6)    EAP-Message = 0x020600281900170303001da067af59dd1d6867587c3781f68700da3b1714b7feb2c17fc21e538221
Debug : (6)    State = 0xdd9d61181528ed51c335dd222177283e
Debug : (6)    Message-Authenticator = 0x9b212313562c103adc03cd269bba419a
Debug : (6,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (6,1)  recv Access-Request {
Debug : (6,1)    chap (noop)
Debug : (6,1)    mschap (noop)
Debug : (6,1)    eap - Peer sent EAP Response (code 2) ID 6 length 40
Debug : (6,1)    eap - Continuing tunnel setup
Debug : (6,1)    eap (ok)
Debug : (6,1)  } # recv Access-Request (ok)
Debug : (6,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (6,1)  authenticate eap {
Debug : (6,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (6,1)    eap - Calling submodule eap_peap
Debug : (6,1)    eap - Continuing EAP-TLS
Debug : (6,1)    eap - Got complete TLS record (34 bytes)
Debug : (6,1)    eap - [eap-tls verify] = complete
Debug : (6,1)    eap - Decrypted TLS application data (5 bytes)
Debug : (6,1)    eap - [eap-tls process] = complete
Debug : (6,1)    eap - Session established.  Decoding tunneled data
Debug : (6,1)    eap - PEAP state WAITING FOR INNER IDENTITY
Debug : (6,1)    eap - Received EAP-Identity-Response
Debug : (6,1)    eap - Got inner identity 'root'
Debug : (6,1)    eap - Got tunneled request
Debug : (6,1)    eap -   &EAP-Message = 0x0206000901726f6f74
Debug : (6,1)    eap - Setting &request:User-Name from tunneled (inner) identity "root"
Debug : (6,1)    eap - Proxying tunneled request to virtual server "peap-tunnel"
Debug : (6.0)  Virtual server peap-tunnel received request
Debug : (6.0)    &EAP-Message = 0x0206000901726f6f74
Debug : (6.0)    &FreeRADIUS-Proxied-To = 127.0.0.1
Debug : (6.0)    &User-Name = "root"
WARN  : (6.0)  WARNING: Outer and inner identities are the same.  User privacy is compromised.
Debug : (6.0)  server peap-tunnel {
Debug : (6.0)  Received Access-Request ID 0
Debug : (6.0)    EAP-Message = 0x0206000901726f6f74
Debug : (6.0)    FreeRADIUS-Proxied-To = 127.0.0.1
Debug : (6.0)    User-Name = "root"
Debug : (6.0)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/server.conf
Debug : (6.0)  recv Access-Request {
Debug : (6.0)    eap - Peer sent EAP Response (code 2) ID 6 length 9
Debug : (6.0)    eap - Peer sent EAP-Identity.  Returning 'ok' so we can short-circuit the rest of authorize
Debug : (6.0)    eap (ok)
Debug : (6.0)  } # recv Access-Request (ok)
Debug : (6.0)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/server.conf
Debug : (6.0)  authenticate eap {
Debug : (6.0)    eap-inner - Peer sent packet with EAP method Identity (1)
Debug : (6.0)    eap-inner - Calling submodule eap_md5
Debug : (6.0)    eap-inner - Issuing MD5 Challenge
Debug : (6.0)    eap-inner - Submodule eap_md5 returned
Debug : (6.0)    eap-inner - Sending EAP Request (code 1) ID 7 length 22
Debug : (6.0)    eap-inner (handled)
Debug : (6.0)  } # authenticate eap (handled)
Debug : (6.0)  Sent Access-Challenge ID 0
Debug : (6.0)    EAP-Message = 0x0107001604109cfc58244b118bafdb8fd01345521f6c
Debug : (6.0)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (6.0)  } # server peap-tunnel
Debug : (6,1)    eap - Got tunneled reply Access-Challenge
Debug : (6,1)    eap -   &EAP-Message = 0x0107001604109cfc58244b118bafdb8fd01345521f6c
Debug : (6,1)    eap -   &Message-Authenticator = 0x00000000000000000000000000000000
Debug : (6,1)    eap - Got tunneled Access-Challenge
Debug : (6,1)    eap - TLS application data to encrypt (18 bytes)
Debug : (6,1)    eap - Sending complete TLS record (47 bytes)
Debug : (6,1)    eap - Submodule eap_peap returned
Debug : (6,1)    eap - Sending EAP Request (code 1) ID 7 length 53
Debug : (6,1)    eap (handled)
Debug : (6,1)  } # authenticate eap (handled)
Debug : (6,1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (6,1)  send Access-Challenge {
Debug : (6,1)    handled (handled)
Debug : (6,1)  } # send Access-Challenge (handled)
Debug : (6,1)  Sent code 11 Id 141 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (6,1)    EAP-Message = 0x010700351900170303002a0b604285400b205c76d2346d2235bbf7b944cc355d686b3e2a62ea956f493e98cfe29ccaf14ed1ee85b5
Debug : (6,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (6,1)    State = 0x952878a5d2bbbd5b27d1d926f44fdfdc
Debug : (6)  done request
Debug : (6)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 174
Debug : Waking up in 4.9 seconds.
Debug : (7)  running request
Debug : (7)  Received Access-Request ID 142
Debug : (7)    User-Name = "root"
Debug : (7)    NAS-IP-Address = 192.168.117.1
Debug : (7)    NAS-Identifier = "RalinkAP0"
Debug : (7)    NAS-Port = 0
Debug : (7)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (7)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (7)    Framed-MTU = 1400
Debug : (7)    NAS-Port-Type = Wireless-802.11
Debug : (7)    EAP-Message = 0x020700251900170303001aa067af59dd1d6868ff062c2574f115f2435d32563b9caccf379a
Debug : (7)    State = 0x952878a5d2bbbd5b27d1d926f44fdfdc
Debug : (7)    Message-Authenticator = 0x24a5855266a45af7159e746a1d408543
Debug : (7,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (7,1)  recv Access-Request {
Debug : (7,1)    chap (noop)
Debug : (7,1)    mschap (noop)
Debug : (7,1)    eap - Peer sent EAP Response (code 2) ID 7 length 37
Debug : (7,1)    eap - Continuing tunnel setup
Debug : (7,1)    eap (ok)
Debug : (7,1)  } # recv Access-Request (ok)
Debug : (7,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (7,1)  authenticate eap {
Debug : (7,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (7,1)    eap - Calling submodule eap_peap
Debug : (7,1)    eap - Continuing EAP-TLS
Debug : (7,1)    eap - Got complete TLS record (31 bytes)
Debug : (7,1)    eap - [eap-tls verify] = complete
Debug : (7,1)    eap - Decrypted TLS application data (2 bytes)
Debug : (7,1)    eap - [eap-tls process] = complete
Debug : (7,1)    eap - Session established.  Decoding tunneled data
Debug : (7,1)    eap - PEAP state phase2
Debug : (7,1)    eap - EAP method NAK (3)
Debug : (7,1)    eap - Got tunneled request
Debug : (7,1)    eap -   &EAP-Message = 0x02070006031a
Debug : (7,1)    eap - Setting &request:User-Name from tunneled (inner) identity "root"
Debug : (7,1)    eap - Proxying tunneled request to virtual server "peap-tunnel"
Debug : (7.0)  Virtual server peap-tunnel received request
Debug : (7.0)    &EAP-Message = 0x02070006031a
Debug : (7.0)    &FreeRADIUS-Proxied-To = 127.0.0.1
Debug : (7.0)    &User-Name = "root"
WARN  : (7.0)  WARNING: Outer and inner identities are the same.  User privacy is compromised.
Debug : (7.0)  server peap-tunnel {
Debug : (7.0)  Received Access-Request ID 0
Debug : (7.0)    EAP-Message = 0x02070006031a
Debug : (7.0)    FreeRADIUS-Proxied-To = 127.0.0.1
Debug : (7.0)    User-Name = "root"
Debug : (7.0)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/server.conf
Debug : (7.0)  recv Access-Request {
Debug : (7.0)    eap - Peer sent EAP Response (code 2) ID 7 length 6
Debug : (7.0)    eap - Continuing on-going EAP conversation
Debug : (7.0)    eap (updated)
Debug : (7.0)    sql - EXPAND %{User-Name}
Debug : (7.0)    sql - --> root
Debug : (7.0)    sql - SQL-User-Name set to 'root'
Debug : (7.0)    sql - Reserved connection (5)
Debug : (7.0)    sql - EXPAND SELECT uuid as id, login as UserName, 'Cleartext-Password' as Attribute, password as Value , ':=' as Op FROM login 	WHERE login = 'root' ORDER BY uuid
Debug : (7.0)    sql - --> SELECT uuid as id, login as UserName, 'Cleartext-Password' as Attribute, password as Value , ':=' as Op FROM login 	WHERE login = 'root' ORDER BY uuid
Debug : (7.0)    sql - Executing select query: SELECT uuid as id, login as UserName, 'Cleartext-Password' as Attribute, password as Value , ':=' as Op FROM login 	WHERE login = 'root' ORDER BY uuid
Debug : rlm_sql_postgresql - Status: PGRES_TUPLES_OK
Debug : rlm_sql_postgresql - query affected rows = 1 , fields = 5
Debug : (7.0)    sql - User found in radcheck table
Debug : (7.0)    sql - Conditional check items matched, merging assignment check items
Debug : (7.0)    sql -   &Cleartext-Password := "admin"
Debug : (7.0)    sql - Released connection (5)
Info  : (7.0)    sql - Need 2 more connections to reach min connections (3)
Debug : (7.0)    sql - Opening additional connection (6), 1 of 31 pending slots used
Debug : rlm_sql_postgresql - Connecting using parameters: host=postgres port=5432 dbname=billing user=radius password=raddpass application_name='FreeRADIUS 4.0.0 - radiusd (sql)'
Debug : rlm_sql_postgresql - Connected to database 'billing' on 'postgres' server version 100003, protocol version 3, backend PID 679 
Debug : (7.0)    sql - Closing expired connection (5): Needs reconnecting
Debug : (7.0)    sql - You probably need to lower "min"
Debug : rlm_sql_postgresql - Socket destructor called, closing socket
Debug : (7.0)    sql (ok)
Debug : (7.0)  } # recv Access-Request (updated)
Debug : (7.0)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/server.conf
Debug : (7.0)  authenticate eap {
Debug : (7.0)    eap-inner - Peer sent packet with EAP method NAK (3)
Debug : (7.0)    eap-inner - Found mutually acceptable type MSCHAPv2 (26)
Debug : (7.0)    eap-inner - Calling submodule eap_mschapv2
Debug : (7.0)    eap-inner - Issuing Challenge
Debug : (7.0)    eap-inner - Submodule eap_mschapv2 returned
Debug : (7.0)    eap-inner - Sending EAP Request (code 1) ID 8 length 29
Debug : (7.0)    eap-inner (handled)
Debug : (7.0)  } # authenticate eap (handled)
Debug : (7.0)  Sent Access-Challenge ID 0
Debug : (7.0)    EAP-Message = 0x0108001d1a01080018103d41d0780eb5da44fe1364d75e0393ac554e41
Debug : (7.0)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (7.0)  } # server peap-tunnel
Debug : (7,1)    eap - Got tunneled reply Access-Challenge
Debug : (7,1)    eap -   &EAP-Message = 0x0108001d1a01080018103d41d0780eb5da44fe1364d75e0393ac554e41
Debug : (7,1)    eap -   &Message-Authenticator = 0x00000000000000000000000000000000
Debug : (7,1)    eap - Got tunneled Access-Challenge
Debug : (7,1)    eap - TLS application data to encrypt (25 bytes)
Debug : (7,1)    eap - Sending complete TLS record (54 bytes)
Debug : (7,1)    eap - Submodule eap_peap returned
Debug : (7,1)    eap - Sending EAP Request (code 1) ID 8 length 60
Debug : (7,1)    eap (handled)
Debug : (7,1)  } # authenticate eap (handled)
Debug : (7,1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (7,1)  send Access-Challenge {
Debug : (7,1)    handled (handled)
Debug : (7,1)  } # send Access-Challenge (handled)
Debug : (7,1)  Sent code 11 Id 142 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (7,1)    EAP-Message = 0x0108003c190017030300310b604285400b205db520709c48fa87df49eefddb448560fafb40fe0ca53a93279c9b72cc5d22f093757bf40da9a76a986d
Debug : (7,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (7,1)    State = 0xa2b9a122d310a2ebcec21c99f9293684
Debug : (7)  done request
Debug : (7)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 231
Debug : Waking up in 4.9 seconds.
Debug : (8)  running request
Debug : (8)  Received Access-Request ID 143
Debug : (8)    User-Name = "root"
Debug : (8)    NAS-IP-Address = 192.168.117.1
Debug : (8)    NAS-Identifier = "RalinkAP0"
Debug : (8)    NAS-Port = 0
Debug : (8)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (8)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (8)    Framed-MTU = 1400
Debug : (8)    NAS-Port-Type = Wireless-802.11
Debug : (8)    EAP-Message = 0x0208005e19001703030053a067af59dd1d6869898cd60cc2638f8d3d61deca0b4aeb0c15eb65833df12dbfb27832b3a3778e8149a1d119544b19e907e1dd987f0f231ec075c98060358c39ad3a8a3c51956a852feed12ddba47cbbb5d2bd
Debug : (8)    State = 0xa2b9a122d310a2ebcec21c99f9293684
Debug : (8)    Message-Authenticator = 0x03584e211552b8a5c47e114fb0874e34
Debug : (8,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (8,1)  recv Access-Request {
Debug : (8,1)    chap (noop)
Debug : (8,1)    mschap (noop)
Debug : (8,1)    eap - Peer sent EAP Response (code 2) ID 8 length 94
Debug : (8,1)    eap - Continuing tunnel setup
Debug : (8,1)    eap (ok)
Debug : (8,1)  } # recv Access-Request (ok)
Debug : (8,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (8,1)  authenticate eap {
Debug : (8,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (8,1)    eap - Calling submodule eap_peap
Debug : (8,1)    eap - Continuing EAP-TLS
Debug : (8,1)    eap - Got complete TLS record (88 bytes)
Debug : (8,1)    eap - [eap-tls verify] = complete
Debug : (8,1)    eap - Decrypted TLS application data (59 bytes)
Debug : (8,1)    eap - [eap-tls process] = complete
Debug : (8,1)    eap - Session established.  Decoding tunneled data
Debug : (8,1)    eap - PEAP state phase2
Debug : (8,1)    eap - EAP method MSCHAPv2 (26)
Debug : (8,1)    eap - Got tunneled request
Debug : (8,1)    eap -   &EAP-Message = 0x0208003f1a0208003a31263c0d593e3e8477431b6be93d5a0a69000000000000000060fc0b3e58ab7f4eed03c5f8acb1b88e01740259f4ac63dc00726f6f74
Debug : (8,1)    eap - Setting &request:User-Name from tunneled (inner) identity "root"
Debug : (8,1)    eap - Proxying tunneled request to virtual server "peap-tunnel"
Debug : (8.0)  Virtual server peap-tunnel received request
Debug : (8.0)    &EAP-Message = 0x0208003f1a0208003a31263c0d593e3e8477431b6be93d5a0a69000000000000000060fc0b3e58ab7f4eed03c5f8acb1b88e01740259f4ac63dc00726f6f74
Debug : (8.0)    &FreeRADIUS-Proxied-To = 127.0.0.1
Debug : (8.0)    &User-Name = "root"
WARN  : (8.0)  WARNING: Outer and inner identities are the same.  User privacy is compromised.
Debug : (8.0)  server peap-tunnel {
Debug : (8.0)  Received Access-Request ID 0
Debug : (8.0)    EAP-Message = 0x0208003f1a0208003a31263c0d593e3e8477431b6be93d5a0a69000000000000000060fc0b3e58ab7f4eed03c5f8acb1b88e01740259f4ac63dc00726f6f74
Debug : (8.0)    FreeRADIUS-Proxied-To = 127.0.0.1
Debug : (8.0)    User-Name = "root"
Debug : (8.0)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/server.conf
Debug : (8.0)  recv Access-Request {
Debug : (8.0)    eap - Peer sent EAP Response (code 2) ID 8 length 63
Debug : (8.0)    eap - Continuing on-going EAP conversation
Debug : (8.0)    eap (updated)
Debug : (8.0)    sql - EXPAND %{User-Name}
Debug : (8.0)    sql - --> root
Debug : (8.0)    sql - SQL-User-Name set to 'root'
Debug : (8.0)    sql - Reserved connection (6)
Debug : (8.0)    sql - EXPAND SELECT uuid as id, login as UserName, 'Cleartext-Password' as Attribute, password as Value , ':=' as Op FROM login 	WHERE login = 'root' ORDER BY uuid
Debug : (8.0)    sql - --> SELECT uuid as id, login as UserName, 'Cleartext-Password' as Attribute, password as Value , ':=' as Op FROM login 	WHERE login = 'root' ORDER BY uuid
Debug : (8.0)    sql - Executing select query: SELECT uuid as id, login as UserName, 'Cleartext-Password' as Attribute, password as Value , ':=' as Op FROM login 	WHERE login = 'root' ORDER BY uuid
Debug : rlm_sql_postgresql - Status: PGRES_TUPLES_OK
Debug : rlm_sql_postgresql - query affected rows = 1 , fields = 5
Debug : (8.0)    sql - User found in radcheck table
Debug : (8.0)    sql - Conditional check items matched, merging assignment check items
Debug : (8.0)    sql -   &Cleartext-Password := "admin"
Debug : (8.0)    sql - Released connection (6)
Debug : (8.0)    sql (ok)
Debug : (8.0)  } # recv Access-Request (updated)
Debug : (8.0)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/server.conf
Debug : (8.0)  authenticate eap {
Debug : (8.0)    eap-inner - Peer sent packet with EAP method MSCHAPv2 (26)
Debug : (8.0)    eap-inner - Calling submodule eap_mschapv2
Debug : (8.0)    eap-inner - Empty authenticate section in virtual server "peap-tunnel".  Using default return value (reject)
Debug : (8.0)    eap-inner - Submodule eap_mschapv2 returned
Debug : (8.0)    eap-inner - Sending EAP Failure (code 4) ID 8 length 4
Debug : (8.0)    eap-inner - Cleaning up EAP session
Debug : (8.0)    eap-inner (reject)
Debug : (8.0)  } # authenticate eap (reject)
Debug : (8.0)  Failed to authenticate the user
Auth  : (8.0)  Login incorrect: [root] (from client RalinkAP0 port 0 via proxy to virtual server)
Debug : (8.0)  Sent Access-Reject ID 0
Debug : (8.0)    EAP-Message = 0x04080004
Debug : (8.0)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (8.0)  } # server peap-tunnel
Debug : (8,1)    eap - Got tunneled reply Access-Reject
Debug : (8,1)    eap -   &EAP-Message = 0x04080004
Debug : (8,1)    eap -   &Message-Authenticator = 0x00000000000000000000000000000000
Debug : (8,1)    eap - Tunneled authentication was rejected
Debug : (8,1)    eap - FAILURE
Debug : (8,1)    eap - TLS application data to encrypt (11 bytes)
Debug : (8,1)    eap - Sending complete TLS record (40 bytes)
Debug : (8,1)    eap - Submodule eap_peap returned
Debug : (8,1)    eap - Sending EAP Request (code 1) ID 9 length 46
Debug : (8,1)    eap (handled)
Debug : (8,1)  } # authenticate eap (handled)
Debug : (8,1)  Running 'send Access-Challenge' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (8,1)  send Access-Challenge {
Debug : (8,1)    handled (handled)
Debug : (8,1)  } # send Access-Challenge (handled)
Debug : (8,1)  Sent code 11 Id 143 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (8,1)    EAP-Message = 0x0109002e190017030300230b604285400b205e1172f1d017a3d121e8b13c1e0a94597c55090a3d212d38322e7402
Debug : (8,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (8,1)    State = 0x8af9a0eafbad677fea529a5f34932034
Debug : (8)  done request
Debug : (8)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Network received packet size 183
Debug : Waking up in 4.9 seconds.
Debug : (9)  running request
Debug : (9)  Received Access-Request ID 144
Debug : (9)    User-Name = "root"
Debug : (9)    NAS-IP-Address = 192.168.117.1
Debug : (9)    NAS-Identifier = "RalinkAP0"
Debug : (9)    NAS-Port = 0
Debug : (9)    Called-Station-Id = "C0-25-E9-4C-71-36"
Debug : (9)    Calling-Station-Id = "7C-B0-C2-74-6C-CE"
Debug : (9)    Framed-MTU = 1400
Debug : (9)    NAS-Port-Type = Wireless-802.11
Debug : (9)    EAP-Message = 0x0209002e19001703030023a067af59dd1d686a0b857024c375deaeff75be1164607b6caa4ed6738a9e81a79712c4
Debug : (9)    State = 0x8af9a0eafbad677fea529a5f34932034
Debug : (9)    Message-Authenticator = 0x316492614b92a839a8e8d5ad0ba4e2b5
Debug : (9,1)  Running 'recv Access-Request' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (9,1)  recv Access-Request {
Debug : (9,1)    chap (noop)
Debug : (9,1)    mschap (noop)
Debug : (9,1)    eap - Peer sent EAP Response (code 2) ID 9 length 46
Debug : (9,1)    eap - Continuing tunnel setup
Debug : (9,1)    eap (ok)
Debug : (9,1)  } # recv Access-Request (ok)
Debug : (9,1)  Running 'authenticate eap' from file /opt/freeradius/etc/raddb/auth.conf
Debug : (9,1)  authenticate eap {
Debug : (9,1)    eap - Peer sent packet with EAP method PEAP (25)
Debug : (9,1)    eap - Calling submodule eap_peap
Debug : (9,1)    eap - Continuing EAP-TLS
Debug : (9,1)    eap - Got complete TLS record (40 bytes)
Debug : (9,1)    eap - [eap-tls verify] = complete
Debug : (9,1)    eap - Decrypted TLS application data (11 bytes)
Debug : (9,1)    eap - [eap-tls process] = complete
Debug : (9,1)    eap - Session established.  Decoding tunneled data
Debug : (9,1)    eap - PEAP state send tlv failure
ERROR : (9,1)    eap -   ERROR: The users session was previously rejected: returning reject (again.)
: (9,1)    eap -   This means you need to read the PREVIOUS messages in the debug output
: (9,1)    eap -   to find out the reason why the user was rejected
: (9,1)    eap -   Look for "reject" or "fail".  Those earlier messages will tell you
: (9,1)    eap -   what went wrong, and how to fix the problem
Debug : (9,1)    eap - Submodule eap_peap returned
Debug : (9,1)    eap - Sending EAP Failure (code 4) ID 9 length 4
Debug : (9,1)    eap - Cleaning up EAP session
Debug : (9,1)    eap (reject)
Debug : (9,1)  } # authenticate eap (reject)
Debug : (9,1)  Failed to authenticate the user
Auth  : (9,1)  Login incorrect (eap: The users session was previously rejected: returning reject (again.)): [root] (from client RalinkAP0 port 0 cli 7C-B0-C2-74-6C-CE)
Debug : (9,1)  Sent code 3 Id 144 from 172.18.0.3:1812 to 192.168.117.1:38107 via eth0 length 0
Debug : (9,1)    EAP-Message = 0x04090004
Debug : (9,1)    Message-Authenticator = 0x00000000000000000000000000000000
Debug : (9)  done request
Debug : (9)  finished request.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : Waking up in 4.9 seconds.
Debug : TIMER - proto_radius cleanup delay for ID 136
Debug : TIMER - proto_radius cleanup delay for ID 137
Debug : TIMER - proto_radius cleanup delay for ID 138
Debug : TIMER - proto_radius cleanup delay for ID 139
Debug : TIMER - proto_radius cleanup delay for ID 140
Debug : TIMER - proto_radius cleanup delay for ID 141
Debug : TIMER - proto_radius cleanup delay for ID 142
Debug : TIMER - proto_radius cleanup delay for ID 143
Debug : TIMER - proto_radius cleanup delay for ID 144
Debug : Waking up in 23.5 seconds.
Debug : TIMER - worker max_request_time
Debug : Waking up in 3570.3 seconds.



-- 
Best regards, Aleksandr Stepanov.


20.03.2018, 17:49, "Aleksandr Stepanov" <alex-eri at ya.ru>:
> my config was copied from v3 =)
> v4 has this section!
>
> thanks
>
> --
> Best regards, Aleksandr Stepanov.
>
> 20.03.2018, 17:44, "Aleksandr Stepanov" <alex-eri at ya.ru>:
>>  This file listed in my first message and it has all subsections.
>>
>>  I found problem.
>>
>>  Eap module also need included:
>>
>>          type = md5
>>          type = mschapv2
>>          type = peap
>>
>>  This part is missed in default configuration for v4. Seems its ok if "eap-inner" loaded before "eap". Eap-inner has "type" lines and bootstraps submodules.
>>
>>  --
>>  Best regards, Aleksandr Stepanov.
>>
>>  20.03.2018, 17:35, "Matthew Newton" <mcn at freeradius.org>:
>>>   On Tue, 2018-03-20 at 17:25 +0300, Aleksandr Stepanov wrote:
>>>>    Debug : Including configuration file "/opt/freeradius/etc/raddb/mods-
>>>>    enabled/eap"
>>>
>>>   Check "/opt/freeradius/etc/raddb/mods-enabled/eap", and make sure it
>>>   contains the full default eap config.
>>>
>>>   It's missing all the peap{}, tls{}, etc sections.
>>>
>>>   --
>>>   Matthew
>>>
>>>   -
>>>   List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>>
>>  -
>>  List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html



More information about the Freeradius-Users mailing list