Thu Jun 18 08:45:26 2015 : Debug: (8) Received Access-Request Id 247 from 192.168.104.80:32770 to 192.168.106.130:1812 length 321 Thu Jun 18 08:45:26 2015 : Debug: (8) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:26 2015 : Debug: (8) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:26 2015 : Debug: (8) Location-Capable = Civix-Location Thu Jun 18 08:45:26 2015 : Debug: (8) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:26 2015 : Debug: (8) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:26 2015 : Debug: (8) NAS-Port = 2 Thu Jun 18 08:45:26 2015 : Debug: (8) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:26 2015 : Debug: (8) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:26 2015 : Debug: (8) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:26 2015 : Debug: (8) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:26 2015 : Debug: (8) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:26 2015 : Debug: (8) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:26 2015 : Debug: (8) Service-Type = Framed-User Thu Jun 18 08:45:26 2015 : Debug: (8) Framed-MTU = 1300 Thu Jun 18 08:45:26 2015 : Debug: (8) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:26 2015 : Debug: (8) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:26 2015 : Debug: (8) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:26 2015 : Debug: (8) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:26 2015 : Debug: (8) EAP-Message = 0x0201001e01686f73742f4b414c4a4f2d4c542e70616c6d6174696e2e6565 Thu Jun 18 08:45:26 2015 : Debug: (8) Message-Authenticator = 0xb9535380dd9e0a5b4c9c83c85bc211b3 Thu Jun 18 08:45:26 2015 : Debug: (8) session-state: No State attribute Thu Jun 18 08:45:26 2015 : Debug: (8) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (8) authorize { Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) [preprocess] = ok Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: calling auth_log (rlm_detail) for request 8 Thu Jun 18 08:45:26 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:26 2015 : Debug: if { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: else { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:26 2015 : Debug: percent --> Y Thu Jun 18 08:45:26 2015 : Debug: percent --> m Thu Jun 18 08:45:26 2015 : Debug: percent --> d Thu Jun 18 08:45:26 2015 : Debug: (8) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: (8) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: (8) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: %t Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: percent --> t Thu Jun 18 08:45:26 2015 : Debug: (8) auth_log: EXPAND %t Thu Jun 18 08:45:26 2015 : Debug: (8) auth_log: --> Thu Jun 18 08:45:26 2015 Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: returned from auth_log (rlm_detail) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) [auth_log] = ok Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: calling chap (rlm_chap) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: returned from chap (rlm_chap) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) [chap] = noop Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: calling suffix (rlm_realm) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) suffix: Checking for suffix after "@" Thu Jun 18 08:45:26 2015 : Debug: (8) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:26 2015 : Debug: (8) suffix: No such realm "NULL" Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: returned from suffix (rlm_realm) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) [suffix] = noop Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: calling eap (rlm_eap) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) eap: Peer sent EAP Response (code 2) ID 1 length 30 Thu Jun 18 08:45:26 2015 : Debug: (8) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authorize]: returned from eap (rlm_eap) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) [eap] = ok Thu Jun 18 08:45:26 2015 : Debug: (8) } # authorize = ok Thu Jun 18 08:45:26 2015 : Debug: (8) Found Auth-Type = EAP Thu Jun 18 08:45:26 2015 : Debug: (8) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (8) authenticate { Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authenticate]: calling eap (rlm_eap) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) eap: Peer sent packet with method EAP Identity (1) Thu Jun 18 08:45:26 2015 : Debug: (8) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:26 2015 : Debug: (8) eap_tls: Initiating new EAP-TLS session Thu Jun 18 08:45:26 2015 : Debug: (8) eap_tls: Setting verify mode to require certificate from client Thu Jun 18 08:45:26 2015 : Debug: (8) eap_tls: [eaptls start] = request Thu Jun 18 08:45:26 2015 : Debug: (8) eap: Sending EAP Request (code 1) ID 2 length 6 Thu Jun 18 08:45:26 2015 : Debug: (8) eap: EAP session adding &reply:State = 0x3ea68ab73ea487b9 Thu Jun 18 08:45:26 2015 : Debug: (8) modsingle[authenticate]: returned from eap (rlm_eap) for request 8 Thu Jun 18 08:45:26 2015 : Debug: (8) [eap] = handled Thu Jun 18 08:45:26 2015 : Debug: (8) } # authenticate = handled Thu Jun 18 08:45:26 2015 : Debug: (8) Using Post-Auth-Type Challenge Thu Jun 18 08:45:26 2015 : Debug: (8) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:26 2015 : Debug: (8) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (8) session-state: Nothing to cache Thu Jun 18 08:45:26 2015 : Debug: (8) Sent Access-Challenge Id 247 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:26 2015 : Debug: (8) EAP-Message = 0x010200060d20 Thu Jun 18 08:45:26 2015 : Debug: (8) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:26 2015 : Debug: (8) State = 0x3ea68ab73ea487b975dec8f53419342d Thu Jun 18 08:45:26 2015 : Debug: (8) Finished request Thu Jun 18 08:45:26 2015 : Debug: Waking up in 4.9 seconds. Thu Jun 18 08:45:26 2015 : Debug: (9) Received Access-Request Id 248 from 192.168.104.80:32770 to 192.168.106.130:1812 length 448 Thu Jun 18 08:45:26 2015 : Debug: (9) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:26 2015 : Debug: (9) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:26 2015 : Debug: (9) Location-Capable = Civix-Location Thu Jun 18 08:45:26 2015 : Debug: (9) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:26 2015 : Debug: (9) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:26 2015 : Debug: (9) NAS-Port = 2 Thu Jun 18 08:45:26 2015 : Debug: (9) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:26 2015 : Debug: (9) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:26 2015 : Debug: (9) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:26 2015 : Debug: (9) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:26 2015 : Debug: (9) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:26 2015 : Debug: (9) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:26 2015 : Debug: (9) Service-Type = Framed-User Thu Jun 18 08:45:26 2015 : Debug: (9) Framed-MTU = 1300 Thu Jun 18 08:45:26 2015 : Debug: (9) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:26 2015 : Debug: (9) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:26 2015 : Debug: (9) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:26 2015 : Debug: (9) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:26 2015 : Debug: (9) EAP-Message = 0x0202008b0d8000000081160301007c01000078030155825af697ea4a4f30485dffcc48f59661ae42adc814b65271f9d2f0f374d809201152bd8cb3b437c001f6f035cd3027f3388b9f1aa1547ab53247fdbceb4df40a0018c014c013c00ac0090035002f00380032000a00130005000401000017000a00 Thu Jun 18 08:45:26 2015 : Debug: (9) State = 0x3ea68ab73ea487b975dec8f53419342d Thu Jun 18 08:45:26 2015 : Debug: (9) Message-Authenticator = 0xf54c7082013fa27765883956f0684532 Thu Jun 18 08:45:26 2015 : Debug: (9) session-state: No cached attributes Thu Jun 18 08:45:26 2015 : Debug: (9) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (9) authorize { Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [preprocess] = ok Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling auth_log (rlm_detail) for request 9 Thu Jun 18 08:45:26 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:26 2015 : Debug: if { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: else { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:26 2015 : Debug: percent --> Y Thu Jun 18 08:45:26 2015 : Debug: percent --> m Thu Jun 18 08:45:26 2015 : Debug: percent --> d Thu Jun 18 08:45:26 2015 : Debug: (9) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: (9) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: (9) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: %t Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: percent --> t Thu Jun 18 08:45:26 2015 : Debug: (9) auth_log: EXPAND %t Thu Jun 18 08:45:26 2015 : Debug: (9) auth_log: --> Thu Jun 18 08:45:26 2015 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from auth_log (rlm_detail) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [auth_log] = ok Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling chap (rlm_chap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from chap (rlm_chap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [chap] = noop Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling suffix (rlm_realm) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) suffix: Checking for suffix after "@" Thu Jun 18 08:45:26 2015 : Debug: (9) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:26 2015 : Debug: (9) suffix: No such realm "NULL" Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from suffix (rlm_realm) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [suffix] = noop Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling eap (rlm_eap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) eap: Peer sent EAP Response (code 2) ID 2 length 139 Thu Jun 18 08:45:26 2015 : Debug: (9) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from eap (rlm_eap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [eap] = updated Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling files (rlm_files) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from files (rlm_files) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [files] = noop Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling expiration (rlm_expiration) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from expiration (rlm_expiration) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [expiration] = noop Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling logintime (rlm_logintime) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from logintime (rlm_logintime) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [logintime] = noop Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: calling pap (rlm_pap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authorize]: returned from pap (rlm_pap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [pap] = noop Thu Jun 18 08:45:26 2015 : Debug: (9) } # authorize = updated Thu Jun 18 08:45:26 2015 : Debug: (9) Found Auth-Type = EAP Thu Jun 18 08:45:26 2015 : Debug: (9) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (9) authenticate { Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authenticate]: calling eap (rlm_eap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) eap: Expiring EAP session with state 0x3ea68ab73ea487b9 Thu Jun 18 08:45:26 2015 : Debug: (9) eap: Finished EAP session with state 0x3ea68ab73ea487b9 Thu Jun 18 08:45:26 2015 : Debug: (9) eap: Previous EAP request found for state 0x3ea68ab73ea487b9, released from the list Thu Jun 18 08:45:26 2015 : Debug: (9) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:26 2015 : Debug: (9) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: Peer sent flags --L Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: Peer indicated complete TLS record size will be 129 bytes Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: Got complete TLS record (129 bytes) Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: [eaptls verify] = length included Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: (other): before/accept initialization Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: before/accept initialization Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: <<< TLS 1.0 Handshake [length 007c], ClientHello Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: SSLv3 read client hello A Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: >>> TLS 1.0 Handshake [length 0059], ServerHello Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: SSLv3 write server hello A Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001] Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: SSLv3 write change cipher spec A Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: SSLv3 write finished A Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: SSLv3 flush data Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: Need to read more data: SSLv3 read finished A Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: TLS_accept: Need to read more data: SSLv3 read finished A Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: In SSL Handshake Phase Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: In SSL Accept mode Thu Jun 18 08:45:26 2015 : Debug: (9) eap_tls: [eaptls process] = handled Thu Jun 18 08:45:26 2015 : Debug: (9) eap: Sending EAP Request (code 1) ID 3 length 163 Thu Jun 18 08:45:26 2015 : Debug: (9) eap: EAP session adding &reply:State = 0x3ea68ab73fa587b9 Thu Jun 18 08:45:26 2015 : Debug: (9) modsingle[authenticate]: returned from eap (rlm_eap) for request 9 Thu Jun 18 08:45:26 2015 : Debug: (9) [eap] = handled Thu Jun 18 08:45:26 2015 : Debug: (9) } # authenticate = handled Thu Jun 18 08:45:26 2015 : Debug: (9) Using Post-Auth-Type Challenge Thu Jun 18 08:45:26 2015 : Debug: (9) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:26 2015 : Debug: (9) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (9) session-state: Nothing to cache Thu Jun 18 08:45:26 2015 : Debug: (9) Sent Access-Challenge Id 248 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:26 2015 : Debug: (9) EAP-Message = 0x010300a30d8000000099160301005902000055030155825af65601b4c180aea89b6e53bed0ed3e014796856d2e2f40467832ed28b1201152bd8cb3b437c001f6f035cd3027f3388b9f1aa1547ab53247fdbceb4df40ac01400000dff01000100000b0004030001021403010001011603010030941ae1d5 Thu Jun 18 08:45:26 2015 : Debug: (9) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:26 2015 : Debug: (9) State = 0x3ea68ab73fa587b975dec8f53419342d Thu Jun 18 08:45:26 2015 : Debug: (9) Finished request Thu Jun 18 08:45:26 2015 : Debug: Waking up in 4.9 seconds. Thu Jun 18 08:45:26 2015 : Debug: (10) Received Access-Request Id 249 from 192.168.104.80:32770 to 192.168.106.130:1812 length 378 Thu Jun 18 08:45:26 2015 : Debug: (10) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:26 2015 : Debug: (10) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:26 2015 : Debug: (10) Location-Capable = Civix-Location Thu Jun 18 08:45:26 2015 : Debug: (10) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:26 2015 : Debug: (10) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-Port = 2 Thu Jun 18 08:45:26 2015 : Debug: (10) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:26 2015 : Debug: (10) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:26 2015 : Debug: (10) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:26 2015 : Debug: (10) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:26 2015 : Debug: (10) Service-Type = Framed-User Thu Jun 18 08:45:26 2015 : Debug: (10) Framed-MTU = 1300 Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:26 2015 : Debug: (10) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:26 2015 : Debug: (10) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:26 2015 : Debug: (10) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:26 2015 : Debug: (10) EAP-Message = 0x020300450d800000003b14030100010116030100305df25863b7edb6f1e4900677dec023cc2c329120d3aefb96a6b1d59781655ef2506e898b8d4490d6f6399aaf0542e993 Thu Jun 18 08:45:26 2015 : Debug: (10) State = 0x3ea68ab73fa587b975dec8f53419342d Thu Jun 18 08:45:26 2015 : Debug: (10) Message-Authenticator = 0x0fa3d6a9b4f1b7407476fc6392c30089 Thu Jun 18 08:45:26 2015 : Debug: (10) session-state: No cached attributes Thu Jun 18 08:45:26 2015 : Debug: (10) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (10) authorize { Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [preprocess] = ok Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling auth_log (rlm_detail) for request 10 Thu Jun 18 08:45:26 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:26 2015 : Debug: if { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: else { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:26 2015 : Debug: percent --> Y Thu Jun 18 08:45:26 2015 : Debug: percent --> m Thu Jun 18 08:45:26 2015 : Debug: percent --> d Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: %t Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: percent --> t Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: EXPAND %t Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: --> Thu Jun 18 08:45:26 2015 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from auth_log (rlm_detail) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [auth_log] = ok Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling chap (rlm_chap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from chap (rlm_chap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [chap] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling suffix (rlm_realm) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) suffix: Checking for suffix after "@" Thu Jun 18 08:45:26 2015 : Debug: (10) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:26 2015 : Debug: (10) suffix: No such realm "NULL" Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from suffix (rlm_realm) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [suffix] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling eap (rlm_eap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Peer sent EAP Response (code 2) ID 3 length 69 Thu Jun 18 08:45:26 2015 : Debug: (10) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from eap (rlm_eap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [eap] = updated Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling files (rlm_files) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from files (rlm_files) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [files] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling expiration (rlm_expiration) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from expiration (rlm_expiration) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [expiration] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling logintime (rlm_logintime) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from logintime (rlm_logintime) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [logintime] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling pap (rlm_pap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from pap (rlm_pap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [pap] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) } # authorize = updated Thu Jun 18 08:45:26 2015 : Debug: (10) Found Auth-Type = EAP Thu Jun 18 08:45:26 2015 : Debug: (10) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (10) authenticate { Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authenticate]: calling eap (rlm_eap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Expiring EAP session with state 0x3ea68ab73fa587b9 Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Finished EAP session with state 0x3ea68ab73fa587b9 Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Previous EAP request found for state 0x3ea68ab73fa587b9, released from the list Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: Peer sent flags --L Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: Peer indicated complete TLS record size will be 59 bytes Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: Got complete TLS record (59 bytes) Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: [eaptls verify] = length included Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001] Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: TLS_accept: SSLv3 read finished A Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: (other): SSL negotiation finished successfully Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: SSL Connection Established Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: SSL Application Data Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: [eaptls process] = success Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: Validating certificate Thu Jun 18 08:45:26 2015 : Debug: (10) Virtual server check-eap-tls received request Thu Jun 18 08:45:26 2015 : Debug: (10) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:26 2015 : Debug: (10) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:26 2015 : Debug: (10) Location-Capable = Civix-Location Thu Jun 18 08:45:26 2015 : Debug: (10) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:26 2015 : Debug: (10) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-Port = 2 Thu Jun 18 08:45:26 2015 : Debug: (10) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:26 2015 : Debug: (10) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:26 2015 : Debug: (10) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:26 2015 : Debug: (10) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:26 2015 : Debug: (10) Service-Type = Framed-User Thu Jun 18 08:45:26 2015 : Debug: (10) Framed-MTU = 1300 Thu Jun 18 08:45:26 2015 : Debug: (10) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:26 2015 : Debug: (10) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:26 2015 : Debug: (10) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:26 2015 : Debug: (10) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:26 2015 : Debug: (10) EAP-Message = 0x020300450d800000003b14030100010116030100305df25863b7edb6f1e4900677dec023cc2c329120d3aefb96a6b1d59781655ef2506e898b8d4490d6f6399aaf0542e993 Thu Jun 18 08:45:26 2015 : Debug: (10) State = 0x3ea68ab73fa587b975dec8f53419342d Thu Jun 18 08:45:26 2015 : Debug: (10) Message-Authenticator = 0x0fa3d6a9b4f1b7407476fc6392c30089 Thu Jun 18 08:45:26 2015 : Debug: (10) Event-Timestamp = 'Jun 18 2015 08:45:26 EEST' Thu Jun 18 08:45:26 2015 : Debug: (10) EAP-Type = TLS Thu Jun 18 08:45:26 2015 : Debug: (10) server check-eap-tls { Thu Jun 18 08:45:26 2015 : Debug: (10) session-state: No cached attributes Thu Jun 18 08:45:26 2015 : Debug: (10) # Executing section authorize from file /etc/raddb/sites-enabled/check-eap-tls Thu Jun 18 08:45:26 2015 : Debug: (10) authorize { Thu Jun 18 08:45:26 2015 : Debug: (10) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@example\.com$/i) { Thu Jun 18 08:45:26 2015 : Debug: (10) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Upn} Thu Jun 18 08:45:26 2015 : Debug: (10) --> Thu Jun 18 08:45:26 2015 : Debug: (10) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@example\.com$/i) -> FALSE Thu Jun 18 08:45:26 2015 : Debug: (10) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.example\.com$/i) { Thu Jun 18 08:45:26 2015 : Debug: (10) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Dns} Thu Jun 18 08:45:26 2015 : Debug: (10) --> Thu Jun 18 08:45:26 2015 : Debug: (10) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.example\.com$/i) -> FALSE Thu Jun 18 08:45:26 2015 : Debug: (10) else { Thu Jun 18 08:45:26 2015 : Debug: (10) update config { Thu Jun 18 08:45:26 2015 : Debug: (10) Auth-Type := Reject Thu Jun 18 08:45:26 2015 : Debug: (10) } # update config = noop Thu Jun 18 08:45:26 2015 : Debug: (10) } # else = noop Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: calling auth_log (rlm_detail) for request 10 Thu Jun 18 08:45:26 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:26 2015 : Debug: if { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: else { Thu Jun 18 08:45:26 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:26 2015 : Debug: } Thu Jun 18 08:45:26 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:26 2015 : Debug: percent --> Y Thu Jun 18 08:45:26 2015 : Debug: percent --> m Thu Jun 18 08:45:26 2015 : Debug: percent --> d Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:26 2015 : Debug: %t Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: percent --> t Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: EXPAND %t Thu Jun 18 08:45:26 2015 : Debug: (10) auth_log: --> Thu Jun 18 08:45:26 2015 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authorize]: returned from auth_log (rlm_detail) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [auth_log] = ok Thu Jun 18 08:45:26 2015 : Debug: (10) } # authorize = ok Thu Jun 18 08:45:26 2015 : Debug: (10) Found Auth-Type = Reject Thu Jun 18 08:45:26 2015 : Debug: (10) Auth-Type = Reject, rejecting user Thu Jun 18 08:45:26 2015 : Debug: (10) Failed to authenticate the user Thu Jun 18 08:45:26 2015 : Auth: (10) Login incorrect: [host/workstation.example.com/] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38 via TLS tunnel) Thu Jun 18 08:45:26 2015 : Debug: (10) Using Post-Auth-Type Reject Thu Jun 18 08:45:26 2015 : Debug: (10) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:26 2015 : Debug: (10) } # server check-eap-tls Thu Jun 18 08:45:26 2015 : Debug: (10) Virtual server sending reply Thu Jun 18 08:45:26 2015 : Debug: (10) eap_tls: Certificate rejected by the virtual server Thu Jun 18 08:45:26 2015 : Debug: tls: Removing session 1152bd8cb3b437c001f6f035cd3027f3388b9f1aa1547ab53247fdbceb4df40a from the cache Thu Jun 18 08:45:26 2015 : ERROR: (10) eap: Failed continuing EAP TLS (13) session. EAP sub-module failed Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Sending EAP Failure (code 4) ID 3 length 4 Thu Jun 18 08:45:26 2015 : Debug: tls: Freeing cached session VPs Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Failed in EAP select Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[authenticate]: returned from eap (rlm_eap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [eap] = invalid Thu Jun 18 08:45:26 2015 : Debug: (10) } # authenticate = invalid Thu Jun 18 08:45:26 2015 : Debug: (10) Failed to authenticate the user Thu Jun 18 08:45:26 2015 : Auth: (10) Login incorrect (eap: Failed continuing EAP TLS (13) session. EAP sub-module failed): [host/workstation.example.com/] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38) Thu Jun 18 08:45:26 2015 : Debug: (10) Using Post-Auth-Type Reject Thu Jun 18 08:45:26 2015 : Debug: (10) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:26 2015 : Debug: (10) Post-Auth-Type REJECT { Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 10 Thu Jun 18 08:45:26 2015 : Debug: %{User-Name} Thu Jun 18 08:45:26 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:26 2015 : Debug: attribute --> User-Name Thu Jun 18 08:45:26 2015 : Debug: (10) attr_filter.access_reject: EXPAND %{User-Name} Thu Jun 18 08:45:26 2015 : Debug: (10) attr_filter.access_reject: --> host/workstation.example.com Thu Jun 18 08:45:26 2015 : Debug: (10) attr_filter.access_reject: Matched entry DEFAULT at line 18 Thu Jun 18 08:45:26 2015 : Debug: (10) attr_filter.access_reject: EAP-Message = 0x04030004 allowed by EAP-Message =* 0x Thu Jun 18 08:45:26 2015 : Debug: (10) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Thu Jun 18 08:45:26 2015 : Debug: (10) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Thu Jun 18 08:45:26 2015 : Debug: (10) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [attr_filter.access_reject] = updated Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[post-auth]: calling eap (rlm_eap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) eap: Reply already contained an EAP-Message, not inserting EAP-Failure Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[post-auth]: returned from eap (rlm_eap) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [eap] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) policy remove_reply_message_if_eap { Thu Jun 18 08:45:26 2015 : Debug: (10) if (&reply:EAP-Message && &reply:Reply-Message) { Thu Jun 18 08:45:26 2015 : Debug: (10) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Thu Jun 18 08:45:26 2015 : Debug: (10) else { Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[post-auth]: calling noop (rlm_always) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) modsingle[post-auth]: returned from noop (rlm_always) for request 10 Thu Jun 18 08:45:26 2015 : Debug: (10) [noop] = noop Thu Jun 18 08:45:26 2015 : Debug: (10) } # else = noop Thu Jun 18 08:45:26 2015 : Debug: (10) } # policy remove_reply_message_if_eap = noop Thu Jun 18 08:45:26 2015 : Debug: (10) } # Post-Auth-Type REJECT = updated Thu Jun 18 08:45:26 2015 : Debug: (10) Delaying response for 1.000000 seconds Thu Jun 18 08:45:26 2015 : Debug: Waking up in 0.6 seconds. Thu Jun 18 08:45:26 2015 : Debug: Waking up in 0.3 seconds. Thu Jun 18 08:45:27 2015 : Debug: (10) : Sending delayed response Thu Jun 18 08:45:27 2015 : Debug: (10) : Sent Access-Reject Id 249 from 192.168.106.130:1812 to 192.168.104.80:32770 length 44 Thu Jun 18 08:45:27 2015 : Debug: (10) : EAP-Message = 0x04030004 Thu Jun 18 08:45:27 2015 : Debug: (10) : Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:27 2015 : Debug: Waking up in 3.9 seconds. Thu Jun 18 08:45:30 2015 : Debug: (11) Received Access-Request Id 250 from 192.168.104.80:32770 to 192.168.106.130:1812 length 321 Thu Jun 18 08:45:30 2015 : Debug: (11) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (11) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (11) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (11) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (11) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (11) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (11) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (11) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (11) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (11) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (11) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (11) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (11) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (11) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (11) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (11) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (11) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (11) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (11) EAP-Message = 0x0202001e01686f73742f4b414c4a4f2d4c542e70616c6d6174696e2e6565 Thu Jun 18 08:45:30 2015 : Debug: (11) Message-Authenticator = 0x63cbe6e319a09464e1c24be0e87406d0 Thu Jun 18 08:45:30 2015 : Debug: (11) session-state: No State attribute Thu Jun 18 08:45:30 2015 : Debug: (11) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (11) authorize { Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: calling auth_log (rlm_detail) for request 11 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (11) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (11) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (11) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (11) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (11) auth_log: --> Thu Jun 18 08:45:30 2015 Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: returned from auth_log (rlm_detail) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: calling chap (rlm_chap) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: returned from chap (rlm_chap) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: calling suffix (rlm_realm) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (11) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (11) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: returned from suffix (rlm_realm) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: calling eap (rlm_eap) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) eap: Peer sent EAP Response (code 2) ID 2 length 30 Thu Jun 18 08:45:30 2015 : Debug: (11) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authorize]: returned from eap (rlm_eap) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) [eap] = ok Thu Jun 18 08:45:30 2015 : Debug: (11) } # authorize = ok Thu Jun 18 08:45:30 2015 : Debug: (11) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (11) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (11) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authenticate]: calling eap (rlm_eap) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) eap: Peer sent packet with method EAP Identity (1) Thu Jun 18 08:45:30 2015 : Debug: (11) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (11) eap_tls: Initiating new EAP-TLS session Thu Jun 18 08:45:30 2015 : Debug: (11) eap_tls: Setting verify mode to require certificate from client Thu Jun 18 08:45:30 2015 : Debug: (11) eap_tls: [eaptls start] = request Thu Jun 18 08:45:30 2015 : Debug: (11) eap: Sending EAP Request (code 1) ID 3 length 6 Thu Jun 18 08:45:30 2015 : Debug: (11) eap: EAP session adding &reply:State = 0x3a6e63843a6d6e71 Thu Jun 18 08:45:30 2015 : Debug: (11) modsingle[authenticate]: returned from eap (rlm_eap) for request 11 Thu Jun 18 08:45:30 2015 : Debug: (11) [eap] = handled Thu Jun 18 08:45:30 2015 : Debug: (11) } # authenticate = handled Thu Jun 18 08:45:30 2015 : Debug: (11) Using Post-Auth-Type Challenge Thu Jun 18 08:45:30 2015 : Debug: (11) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:30 2015 : Debug: (11) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (11) session-state: Nothing to cache Thu Jun 18 08:45:30 2015 : Debug: (11) Sent Access-Challenge Id 250 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:30 2015 : Debug: (11) EAP-Message = 0x010300060d20 Thu Jun 18 08:45:30 2015 : Debug: (11) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:30 2015 : Debug: (11) State = 0x3a6e63843a6d6e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (11) Finished request Thu Jun 18 08:45:30 2015 : Debug: (12) Received Access-Request Id 251 from 192.168.104.80:32770 to 192.168.106.130:1812 length 448 Thu Jun 18 08:45:30 2015 : Debug: (12) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (12) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (12) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (12) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (12) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (12) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (12) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (12) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (12) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (12) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (12) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (12) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (12) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (12) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (12) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (12) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (12) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (12) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (12) EAP-Message = 0x0203008b0d8000000081160301007c01000078030155825afa11bcb1a55b1b4afc2ddb54f3ff0f890e76781946c8e5c571b712552a201152bd8cb3b437c001f6f035cd3027f3388b9f1aa1547ab53247fdbceb4df40a0018c014c013c00ac0090035002f00380032000a00130005000401000017000a00 Thu Jun 18 08:45:30 2015 : Debug: (12) State = 0x3a6e63843a6d6e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (12) Message-Authenticator = 0xa15fd497433a7a1ca3d7604c595198b2 Thu Jun 18 08:45:30 2015 : Debug: (12) session-state: No cached attributes Thu Jun 18 08:45:30 2015 : Debug: (12) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (12) authorize { Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling auth_log (rlm_detail) for request 12 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (12) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (12) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (12) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (12) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (12) auth_log: --> Thu Jun 18 08:45:30 2015 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from auth_log (rlm_detail) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling chap (rlm_chap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from chap (rlm_chap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling suffix (rlm_realm) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (12) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (12) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from suffix (rlm_realm) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling eap (rlm_eap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) eap: Peer sent EAP Response (code 2) ID 3 length 139 Thu Jun 18 08:45:30 2015 : Debug: (12) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from eap (rlm_eap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [eap] = updated Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling files (rlm_files) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from files (rlm_files) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [files] = noop Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling expiration (rlm_expiration) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from expiration (rlm_expiration) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [expiration] = noop Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling logintime (rlm_logintime) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from logintime (rlm_logintime) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [logintime] = noop Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: calling pap (rlm_pap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authorize]: returned from pap (rlm_pap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [pap] = noop Thu Jun 18 08:45:30 2015 : Debug: (12) } # authorize = updated Thu Jun 18 08:45:30 2015 : Debug: (12) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (12) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (12) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authenticate]: calling eap (rlm_eap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) eap: Expiring EAP session with state 0x3a6e63843a6d6e71 Thu Jun 18 08:45:30 2015 : Debug: (12) eap: Finished EAP session with state 0x3a6e63843a6d6e71 Thu Jun 18 08:45:30 2015 : Debug: (12) eap: Previous EAP request found for state 0x3a6e63843a6d6e71, released from the list Thu Jun 18 08:45:30 2015 : Debug: (12) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:30 2015 : Debug: (12) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: Peer sent flags --L Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: Peer indicated complete TLS record size will be 129 bytes Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: Got complete TLS record (129 bytes) Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: [eaptls verify] = length included Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: (other): before/accept initialization Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: before/accept initialization Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: <<< TLS 1.0 Handshake [length 007c], ClientHello Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: Peer requested cached session: 1152bd8cb3b437c001f6f035cd3027f3388b9f1aa1547ab53247fdbceb4df40a Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: SSLv3 read client hello A Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: >>> TLS 1.0 Handshake [length 0059], ServerHello Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: SSLv3 write server hello A Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: >>> TLS 1.0 Handshake [length 0c46], Certificate Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: SSLv3 write certificate A Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: SSLv3 write key exchange A Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: >>> TLS 1.0 Handshake [length 005b], CertificateRequest Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: SSLv3 write certificate request A Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: SSLv3 flush data Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: TLS_accept: Need to read more data: SSLv3 read client certificate A Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: In SSL Handshake Phase Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: In SSL Accept mode Thu Jun 18 08:45:30 2015 : Debug: (12) eap_tls: [eaptls process] = handled Thu Jun 18 08:45:30 2015 : Debug: (12) eap: Sending EAP Request (code 1) ID 4 length 1024 Thu Jun 18 08:45:30 2015 : Debug: (12) eap: EAP session adding &reply:State = 0x3a6e63843b6a6e71 Thu Jun 18 08:45:30 2015 : Debug: (12) modsingle[authenticate]: returned from eap (rlm_eap) for request 12 Thu Jun 18 08:45:30 2015 : Debug: (12) [eap] = handled Thu Jun 18 08:45:30 2015 : Debug: (12) } # authenticate = handled Thu Jun 18 08:45:30 2015 : Debug: (12) Using Post-Auth-Type Challenge Thu Jun 18 08:45:30 2015 : Debug: (12) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:30 2015 : Debug: (12) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (12) session-state: Nothing to cache Thu Jun 18 08:45:30 2015 : Debug: (12) Sent Access-Challenge Id 251 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:30 2015 : Debug: (12) EAP-Message = 0x010404000dc000000e59160301005902000055030155825afae940a392a188c91afa3a6c4f7ab7e82de3a8cd3ffbc3e0df722cbfb520d41ba7452ab615ee7034d6eacf3507c298352a47d2399b2e266cc12fcdcdfe77c01400000dff01000100000b0004030001021603010c460b000c42000c3f0006c8 Thu Jun 18 08:45:30 2015 : Debug: (12) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:30 2015 : Debug: (12) State = 0x3a6e63843b6a6e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (12) Finished request Thu Jun 18 08:45:30 2015 : Debug: (13) Received Access-Request Id 252 from 192.168.104.80:32770 to 192.168.106.130:1812 length 315 Thu Jun 18 08:45:30 2015 : Debug: (13) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (13) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (13) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (13) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (13) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (13) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (13) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (13) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (13) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (13) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (13) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (13) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (13) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (13) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (13) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (13) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (13) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (13) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (13) EAP-Message = 0x020400060d00 Thu Jun 18 08:45:30 2015 : Debug: (13) State = 0x3a6e63843b6a6e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (13) Message-Authenticator = 0x4447fa0a1c8a8a1cd67cfe46df21786e Thu Jun 18 08:45:30 2015 : Debug: (13) session-state: No cached attributes Thu Jun 18 08:45:30 2015 : Debug: (13) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (13) authorize { Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling auth_log (rlm_detail) for request 13 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (13) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (13) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (13) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (13) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (13) auth_log: --> Thu Jun 18 08:45:30 2015 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from auth_log (rlm_detail) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling chap (rlm_chap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from chap (rlm_chap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling suffix (rlm_realm) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (13) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (13) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from suffix (rlm_realm) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling eap (rlm_eap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) eap: Peer sent EAP Response (code 2) ID 4 length 6 Thu Jun 18 08:45:30 2015 : Debug: (13) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from eap (rlm_eap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [eap] = updated Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling files (rlm_files) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from files (rlm_files) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [files] = noop Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling expiration (rlm_expiration) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from expiration (rlm_expiration) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [expiration] = noop Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling logintime (rlm_logintime) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from logintime (rlm_logintime) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [logintime] = noop Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: calling pap (rlm_pap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authorize]: returned from pap (rlm_pap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [pap] = noop Thu Jun 18 08:45:30 2015 : Debug: (13) } # authorize = updated Thu Jun 18 08:45:30 2015 : Debug: (13) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (13) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (13) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authenticate]: calling eap (rlm_eap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) eap: Expiring EAP session with state 0x3a6e63843b6a6e71 Thu Jun 18 08:45:30 2015 : Debug: (13) eap: Finished EAP session with state 0x3a6e63843b6a6e71 Thu Jun 18 08:45:30 2015 : Debug: (13) eap: Previous EAP request found for state 0x3a6e63843b6a6e71, released from the list Thu Jun 18 08:45:30 2015 : Debug: (13) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:30 2015 : Debug: (13) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (13) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:30 2015 : Debug: (13) eap_tls: Peer sent flags --- Thu Jun 18 08:45:30 2015 : Debug: (13) eap_tls: Peer ACKed our handshake fragment Thu Jun 18 08:45:30 2015 : Debug: (13) eap_tls: [eaptls verify] = request Thu Jun 18 08:45:30 2015 : Debug: (13) eap_tls: [eaptls process] = handled Thu Jun 18 08:45:30 2015 : Debug: (13) eap: Sending EAP Request (code 1) ID 5 length 1024 Thu Jun 18 08:45:30 2015 : Debug: (13) eap: EAP session adding &reply:State = 0x3a6e6384386b6e71 Thu Jun 18 08:45:30 2015 : Debug: (13) modsingle[authenticate]: returned from eap (rlm_eap) for request 13 Thu Jun 18 08:45:30 2015 : Debug: (13) [eap] = handled Thu Jun 18 08:45:30 2015 : Debug: (13) } # authenticate = handled Thu Jun 18 08:45:30 2015 : Debug: (13) Using Post-Auth-Type Challenge Thu Jun 18 08:45:30 2015 : Debug: (13) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:30 2015 : Debug: (13) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (13) session-state: Nothing to cache Thu Jun 18 08:45:30 2015 : Debug: (13) Sent Access-Challenge Id 252 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:30 2015 : Debug: (13) EAP-Message = 0x010504000dc000000e59050730028681a26c6461703a2f2f2f434e3d50616c6d6174696e4f59526f6f7443412c434e3d4149412c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d70616c6d6174696e Thu Jun 18 08:45:30 2015 : Debug: (13) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:30 2015 : Debug: (13) State = 0x3a6e6384386b6e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (13) Finished request Thu Jun 18 08:45:30 2015 : Debug: (14) Received Access-Request Id 253 from 192.168.104.80:32770 to 192.168.106.130:1812 length 315 Thu Jun 18 08:45:30 2015 : Debug: (14) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (14) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (14) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (14) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (14) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (14) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (14) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (14) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (14) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (14) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (14) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (14) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (14) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (14) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (14) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (14) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (14) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (14) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (14) EAP-Message = 0x020500060d00 Thu Jun 18 08:45:30 2015 : Debug: (14) State = 0x3a6e6384386b6e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (14) Message-Authenticator = 0x15d1360c7ddc4999719a88f30441105b Thu Jun 18 08:45:30 2015 : Debug: (14) session-state: No cached attributes Thu Jun 18 08:45:30 2015 : Debug: (14) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (14) authorize { Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling auth_log (rlm_detail) for request 14 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (14) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (14) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (14) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (14) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (14) auth_log: --> Thu Jun 18 08:45:30 2015 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from auth_log (rlm_detail) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling chap (rlm_chap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from chap (rlm_chap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling suffix (rlm_realm) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (14) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (14) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from suffix (rlm_realm) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling eap (rlm_eap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) eap: Peer sent EAP Response (code 2) ID 5 length 6 Thu Jun 18 08:45:30 2015 : Debug: (14) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from eap (rlm_eap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [eap] = updated Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling files (rlm_files) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from files (rlm_files) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [files] = noop Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling expiration (rlm_expiration) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from expiration (rlm_expiration) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [expiration] = noop Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling logintime (rlm_logintime) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from logintime (rlm_logintime) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [logintime] = noop Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: calling pap (rlm_pap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authorize]: returned from pap (rlm_pap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [pap] = noop Thu Jun 18 08:45:30 2015 : Debug: (14) } # authorize = updated Thu Jun 18 08:45:30 2015 : Debug: (14) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (14) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (14) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authenticate]: calling eap (rlm_eap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) eap: Expiring EAP session with state 0x3a6e6384386b6e71 Thu Jun 18 08:45:30 2015 : Debug: (14) eap: Finished EAP session with state 0x3a6e6384386b6e71 Thu Jun 18 08:45:30 2015 : Debug: (14) eap: Previous EAP request found for state 0x3a6e6384386b6e71, released from the list Thu Jun 18 08:45:30 2015 : Debug: (14) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:30 2015 : Debug: (14) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (14) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:30 2015 : Debug: (14) eap_tls: Peer sent flags --- Thu Jun 18 08:45:30 2015 : Debug: (14) eap_tls: Peer ACKed our handshake fragment Thu Jun 18 08:45:30 2015 : Debug: (14) eap_tls: [eaptls verify] = request Thu Jun 18 08:45:30 2015 : Debug: (14) eap_tls: [eaptls process] = handled Thu Jun 18 08:45:30 2015 : Debug: (14) eap: Sending EAP Request (code 1) ID 6 length 1024 Thu Jun 18 08:45:30 2015 : Debug: (14) eap: EAP session adding &reply:State = 0x3a6e638439686e71 Thu Jun 18 08:45:30 2015 : Debug: (14) modsingle[authenticate]: returned from eap (rlm_eap) for request 14 Thu Jun 18 08:45:30 2015 : Debug: (14) [eap] = handled Thu Jun 18 08:45:30 2015 : Debug: (14) } # authenticate = handled Thu Jun 18 08:45:30 2015 : Debug: (14) Using Post-Auth-Type Challenge Thu Jun 18 08:45:30 2015 : Debug: (14) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:30 2015 : Debug: (14) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (14) session-state: Nothing to cache Thu Jun 18 08:45:30 2015 : Debug: (14) Sent Access-Challenge Id 253 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:30 2015 : Debug: (14) EAP-Message = 0x010604000dc000000e590a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f74434130820222300d06092a864886f70d01010105000382020f003082020a0282020100be2fa5e0f143a4dc9eeab356d09c655afab7ab4b943a8ad2628a2952 Thu Jun 18 08:45:30 2015 : Debug: (14) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:30 2015 : Debug: (14) State = 0x3a6e638439686e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (14) Finished request Thu Jun 18 08:45:30 2015 : Debug: (15) Received Access-Request Id 254 from 192.168.104.80:32770 to 192.168.106.130:1812 length 315 Thu Jun 18 08:45:30 2015 : Debug: (15) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (15) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (15) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (15) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (15) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (15) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (15) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (15) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (15) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (15) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (15) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (15) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (15) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (15) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (15) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (15) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (15) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (15) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (15) EAP-Message = 0x020600060d00 Thu Jun 18 08:45:30 2015 : Debug: (15) State = 0x3a6e638439686e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (15) Message-Authenticator = 0x688ea21eb0b8581fe86a766cb6c20b37 Thu Jun 18 08:45:30 2015 : Debug: (15) session-state: No cached attributes Thu Jun 18 08:45:30 2015 : Debug: (15) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (15) authorize { Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling auth_log (rlm_detail) for request 15 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (15) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (15) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (15) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (15) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (15) auth_log: --> Thu Jun 18 08:45:30 2015 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from auth_log (rlm_detail) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling chap (rlm_chap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from chap (rlm_chap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling suffix (rlm_realm) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (15) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (15) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from suffix (rlm_realm) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling eap (rlm_eap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) eap: Peer sent EAP Response (code 2) ID 6 length 6 Thu Jun 18 08:45:30 2015 : Debug: (15) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from eap (rlm_eap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [eap] = updated Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling files (rlm_files) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from files (rlm_files) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [files] = noop Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling expiration (rlm_expiration) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from expiration (rlm_expiration) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [expiration] = noop Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling logintime (rlm_logintime) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from logintime (rlm_logintime) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [logintime] = noop Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: calling pap (rlm_pap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authorize]: returned from pap (rlm_pap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [pap] = noop Thu Jun 18 08:45:30 2015 : Debug: (15) } # authorize = updated Thu Jun 18 08:45:30 2015 : Debug: (15) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (15) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (15) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authenticate]: calling eap (rlm_eap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) eap: Expiring EAP session with state 0x3a6e638439686e71 Thu Jun 18 08:45:30 2015 : Debug: (15) eap: Finished EAP session with state 0x3a6e638439686e71 Thu Jun 18 08:45:30 2015 : Debug: (15) eap: Previous EAP request found for state 0x3a6e638439686e71, released from the list Thu Jun 18 08:45:30 2015 : Debug: (15) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:30 2015 : Debug: (15) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (15) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:30 2015 : Debug: (15) eap_tls: Peer sent flags --- Thu Jun 18 08:45:30 2015 : Debug: (15) eap_tls: Peer ACKed our handshake fragment Thu Jun 18 08:45:30 2015 : Debug: (15) eap_tls: [eaptls verify] = request Thu Jun 18 08:45:30 2015 : Debug: (15) eap_tls: [eaptls process] = handled Thu Jun 18 08:45:30 2015 : Debug: (15) eap: Sending EAP Request (code 1) ID 7 length 641 Thu Jun 18 08:45:30 2015 : Debug: (15) eap: EAP session adding &reply:State = 0x3a6e63843e696e71 Thu Jun 18 08:45:30 2015 : Debug: (15) modsingle[authenticate]: returned from eap (rlm_eap) for request 15 Thu Jun 18 08:45:30 2015 : Debug: (15) [eap] = handled Thu Jun 18 08:45:30 2015 : Debug: (15) } # authenticate = handled Thu Jun 18 08:45:30 2015 : Debug: (15) Using Post-Auth-Type Challenge Thu Jun 18 08:45:30 2015 : Debug: (15) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:30 2015 : Debug: (15) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (15) session-state: Nothing to cache Thu Jun 18 08:45:30 2015 : Debug: (15) Sent Access-Challenge Id 254 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:30 2015 : Debug: (15) EAP-Message = 0x010702810d8000000e591ad0249cf4e25319a8dc335ecf712f7dac90797bc30de6efffff3a3bb05e4d51cb5f09b3fffad4141f55c8ae6218827bd090e50761fd16aed2c49d94fa3a5015423ca228b95e2d093b916735efd9087f493b765d69e11e4b177aa3c917cd759791e7574327df45dd0c74daab55 Thu Jun 18 08:45:30 2015 : Debug: (15) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:30 2015 : Debug: (15) State = 0x3a6e63843e696e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (15) Finished request Thu Jun 18 08:45:30 2015 : Debug: (16) Received Access-Request Id 255 from 192.168.104.80:32770 to 192.168.106.130:1812 length 1811 Thu Jun 18 08:45:30 2015 : Debug: (16) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (16) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (16) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (16) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (16) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (16) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (16) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (16) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (16) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (16) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (16) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (16) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (16) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (16) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (16) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (16) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (16) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (16) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (16) EAP-Message = 0x020705d40dc00000082716030107e70b0006970006940006913082068d30820475a003020102021374000000528ce96f685e3bd5b2000000000052300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d61 Thu Jun 18 08:45:30 2015 : Debug: (16) State = 0x3a6e63843e696e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (16) Message-Authenticator = 0xdbdd2ebd64ce49c6d0733529c248ea3d Thu Jun 18 08:45:30 2015 : Debug: (16) session-state: No cached attributes Thu Jun 18 08:45:30 2015 : Debug: (16) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (16) authorize { Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling auth_log (rlm_detail) for request 16 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (16) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (16) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (16) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (16) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (16) auth_log: --> Thu Jun 18 08:45:30 2015 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from auth_log (rlm_detail) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling chap (rlm_chap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from chap (rlm_chap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling suffix (rlm_realm) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (16) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (16) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from suffix (rlm_realm) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling eap (rlm_eap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) eap: Peer sent EAP Response (code 2) ID 7 length 1492 Thu Jun 18 08:45:30 2015 : Debug: (16) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from eap (rlm_eap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [eap] = updated Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling files (rlm_files) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from files (rlm_files) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [files] = noop Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling expiration (rlm_expiration) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from expiration (rlm_expiration) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [expiration] = noop Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling logintime (rlm_logintime) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from logintime (rlm_logintime) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [logintime] = noop Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: calling pap (rlm_pap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authorize]: returned from pap (rlm_pap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [pap] = noop Thu Jun 18 08:45:30 2015 : Debug: (16) } # authorize = updated Thu Jun 18 08:45:30 2015 : Debug: (16) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (16) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (16) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authenticate]: calling eap (rlm_eap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) eap: Expiring EAP session with state 0x3a6e63843e696e71 Thu Jun 18 08:45:30 2015 : Debug: (16) eap: Finished EAP session with state 0x3a6e63843e696e71 Thu Jun 18 08:45:30 2015 : Debug: (16) eap: Previous EAP request found for state 0x3a6e63843e696e71, released from the list Thu Jun 18 08:45:30 2015 : Debug: (16) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:30 2015 : Debug: (16) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: Peer sent flags -ML Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: Peer indicated complete TLS record size will be 2087 bytes Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: Expecting 2 TLS record fragments Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: Got first TLS record fragment (1482 bytes). Peer indicated more fragments to follow Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: [eaptls verify] = first fragment Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: ACKing Peer's TLS record fragment Thu Jun 18 08:45:30 2015 : Debug: (16) eap_tls: [eaptls process] = handled Thu Jun 18 08:45:30 2015 : Debug: (16) eap: Sending EAP Request (code 1) ID 8 length 6 Thu Jun 18 08:45:30 2015 : Debug: (16) eap: EAP session adding &reply:State = 0x3a6e63843f666e71 Thu Jun 18 08:45:30 2015 : Debug: (16) modsingle[authenticate]: returned from eap (rlm_eap) for request 16 Thu Jun 18 08:45:30 2015 : Debug: (16) [eap] = handled Thu Jun 18 08:45:30 2015 : Debug: (16) } # authenticate = handled Thu Jun 18 08:45:30 2015 : Debug: (16) Using Post-Auth-Type Challenge Thu Jun 18 08:45:30 2015 : Debug: (16) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:30 2015 : Debug: (16) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (16) session-state: Nothing to cache Thu Jun 18 08:45:30 2015 : Debug: (16) Sent Access-Challenge Id 255 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:30 2015 : Debug: (16) EAP-Message = 0x010800060d00 Thu Jun 18 08:45:30 2015 : Debug: (16) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:30 2015 : Debug: (16) State = 0x3a6e63843f666e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (16) Finished request Thu Jun 18 08:45:30 2015 : Debug: (17) Received Access-Request Id 0 from 192.168.104.80:32770 to 192.168.106.130:1812 length 924 Thu Jun 18 08:45:30 2015 : Debug: (17) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (17) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (17) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (17) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (17) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (17) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (17) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (17) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (17) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (17) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (17) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (17) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (17) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (17) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (17) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (17) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (17) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (17) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (17) EAP-Message = 0x020802630d00fe607eb5a7e8ccac163a23d897db9fae64f37a203141a3f9ef158b6be5b7b008eb1f681313fd71561250d00fc583e5855be1687ed8dd809290b5ba8941b1261b5762e1fc5f74ea44330ddfe677480cd84ce98cb38ed18ecf75afd7339756508087210f9d15e5841f515273177fe8f8b674 Thu Jun 18 08:45:30 2015 : Debug: (17) State = 0x3a6e63843f666e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (17) Message-Authenticator = 0xd82d45cfcd0f9cfff8c33f4cdb7208e2 Thu Jun 18 08:45:30 2015 : Debug: (17) session-state: No cached attributes Thu Jun 18 08:45:30 2015 : Debug: (17) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (17) authorize { Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling auth_log (rlm_detail) for request 17 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (17) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (17) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (17) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (17) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (17) auth_log: --> Thu Jun 18 08:45:30 2015 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from auth_log (rlm_detail) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling chap (rlm_chap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from chap (rlm_chap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling suffix (rlm_realm) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (17) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (17) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from suffix (rlm_realm) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling eap (rlm_eap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) eap: Peer sent EAP Response (code 2) ID 8 length 611 Thu Jun 18 08:45:30 2015 : Debug: (17) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from eap (rlm_eap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [eap] = updated Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling files (rlm_files) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from files (rlm_files) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [files] = noop Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling expiration (rlm_expiration) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from expiration (rlm_expiration) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [expiration] = noop Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling logintime (rlm_logintime) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from logintime (rlm_logintime) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [logintime] = noop Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: calling pap (rlm_pap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authorize]: returned from pap (rlm_pap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [pap] = noop Thu Jun 18 08:45:30 2015 : Debug: (17) } # authorize = updated Thu Jun 18 08:45:30 2015 : Debug: (17) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (17) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (17) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authenticate]: calling eap (rlm_eap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) eap: Expiring EAP session with state 0x3a6e63843f666e71 Thu Jun 18 08:45:30 2015 : Debug: (17) eap: Finished EAP session with state 0x3a6e63843f666e71 Thu Jun 18 08:45:30 2015 : Debug: (17) eap: Previous EAP request found for state 0x3a6e63843f666e71, released from the list Thu Jun 18 08:45:30 2015 : Debug: (17) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:30 2015 : Debug: (17) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Peer sent flags --- Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Got final TLS record fragment (605 bytes) Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: [eaptls verify] = ok Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Done initial handshake Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: <<< TLS 1.0 Handshake [length 069b], Certificate Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Creating attributes from certificate OIDs Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Cert-Serial := '497342570ec0c19f459efdaf66ca76cb' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Cert-Expiration := '230901102449Z' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Cert-Subject := '/DC=com/DC=example/CN=RootCA' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Cert-Issuer := '/DC=com/DC=example/CN=RootCA' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Cert-Common-Name := 'RootCA' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: chain-depth : 1 Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: error : 0 Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: identity : host/workstation.example.com Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: common name : RootCA Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: subject : /DC=com/DC=example/CN=RootCA Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: issuer : /DC=com/DC=example/CN=RootCA Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: verify return : 1 Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Creating attributes from certificate OIDs Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-Serial := '74000000528ce96f685e3bd5b2000000000052' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-Expiration := '160523124059Z' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-Subject := '/CN=workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-Issuer := '/DC=com/DC=example/CN=RootCA' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-Common-Name := 'workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-Subject-Alt-Name-Dns := 'workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-X509v3-Extended-Key-Usage += 'TLS Web Server Authentication, TLS Web Client Authentication' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Skipping TLS-Client-Cert-X509v3-Key-Usage += 'Digital Signature, Key Encipherment'. Please check that both the attribute and value are defined in the dictionaries Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-X509v3-Subject-Key-Identifier += '2B:28:8E:20:64:71:34:8A:77:CA:DE:5B:3D:B9:6E:46:E8:AE:99:06' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS-Client-Cert-X509v3-Authority-Key-Identifier += 'keyid:71:FC:8C:7D:7C:8E:3B:F7:F1:99:98:65:C9:E2:E4:21:5C:B9:EE:49 ' Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Skipping TLS-Client-Cert-X509v3-CRL-Distribution-Points += ' Full Name: URI:ldap:///CN=RootCA,CN=srv-wmr-01,CN=CDP,CN=Public%20Key%20Services,CN=Services,CN=Configuration,DC=example,DC=com?certificateRevocationList?base?objectClass=cRLDistributionPoint '. Please check that both the attribute and value are defined in the dictionaries Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Skipping TLS-Client-Cert-Authority-Information-Access += 'CA Issuers - URI:ldap:///CN=RootCA,CN=AIA,CN=Public%20Key%20Services,CN=Services,CN=Configuration,DC=example,DC=com?cACertificate?base?objectClass=certificationAuthority '. Please check that both the attribute and value are defined in the dictionaries Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Skipping TLS-Client-Cert-X509v3-Subject-Alternative-Name += 'DNS:workstation.example.com'. Please check that both the attribute and value are defined in the dictionaries Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: chain-depth : 0 Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: error : 0 Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: identity : host/workstation.example.com Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: common name : workstation.example.com Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: subject : /CN=workstation.example.com Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: issuer : /DC=com/DC=example/CN=RootCA Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: verify return : 1 Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS_accept: SSLv3 read client certificate A Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS_accept: SSLv3 read client key exchange A Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: <<< TLS 1.0 Handshake [length 0106], CertificateVerify Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS_accept: SSLv3 read certificate verify A Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: <<< TLS 1.0 ChangeCipherSpec [length 0001] Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: <<< TLS 1.0 Handshake [length 0010], Finished Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS_accept: SSLv3 read finished A Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: >>> TLS 1.0 ChangeCipherSpec [length 0001] Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS_accept: SSLv3 write change cipher spec A Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: >>> TLS 1.0 Handshake [length 0010], Finished Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS_accept: SSLv3 write finished A Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: TLS_accept: SSLv3 flush data Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: Serialising session d41ba7452ab615ee7034d6eacf3507c298352a47d2399b2e266cc12fcdcdfe77, and storing in cache Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: (other): SSL negotiation finished successfully Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: SSL Connection Established Thu Jun 18 08:45:30 2015 : Debug: (17) eap_tls: [eaptls process] = handled Thu Jun 18 08:45:30 2015 : Debug: (17) eap: Sending EAP Request (code 1) ID 9 length 69 Thu Jun 18 08:45:30 2015 : Debug: (17) eap: EAP session adding &reply:State = 0x3a6e63843c676e71 Thu Jun 18 08:45:30 2015 : Debug: (17) modsingle[authenticate]: returned from eap (rlm_eap) for request 17 Thu Jun 18 08:45:30 2015 : Debug: (17) [eap] = handled Thu Jun 18 08:45:30 2015 : Debug: (17) } # authenticate = handled Thu Jun 18 08:45:30 2015 : Debug: (17) Using Post-Auth-Type Challenge Thu Jun 18 08:45:30 2015 : Debug: (17) Post-Auth-Type sub-section not found. Ignoring. Thu Jun 18 08:45:30 2015 : Debug: (17) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (17) session-state: Nothing to cache Thu Jun 18 08:45:30 2015 : Debug: (17) Sent Access-Challenge Id 0 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:30 2015 : Debug: (17) EAP-Message = 0x010900450d800000003b1403010001011603010030b9c58742902557a5a424866184ed97447d7903ecd5e798ecf9424d985332812dc23f9acd68335ad3b018df656468f0e4 Thu Jun 18 08:45:30 2015 : Debug: (17) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:30 2015 : Debug: (17) State = 0x3a6e63843c676e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (17) Finished request Thu Jun 18 08:45:30 2015 : Debug: (18) Received Access-Request Id 1 from 192.168.104.80:32770 to 192.168.106.130:1812 length 315 Thu Jun 18 08:45:30 2015 : Debug: (18) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (18) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (18) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (18) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (18) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (18) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (18) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (18) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (18) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (18) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (18) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (18) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (18) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (18) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (18) EAP-Message = 0x020900060d00 Thu Jun 18 08:45:30 2015 : Debug: (18) State = 0x3a6e63843c676e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (18) Message-Authenticator = 0x2b586170883a9280b9170bf00dbbb5de Thu Jun 18 08:45:30 2015 : Debug: (18) session-state: No cached attributes Thu Jun 18 08:45:30 2015 : Debug: (18) # Executing section authorize from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (18) authorize { Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [preprocess] = ok Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling auth_log (rlm_detail) for request 18 Thu Jun 18 08:45:30 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:30 2015 : Debug: if { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: else { Thu Jun 18 08:45:30 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:30 2015 : Debug: } Thu Jun 18 08:45:30 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:30 2015 : Debug: percent --> Y Thu Jun 18 08:45:30 2015 : Debug: percent --> m Thu Jun 18 08:45:30 2015 : Debug: percent --> d Thu Jun 18 08:45:30 2015 : Debug: (18) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:30 2015 : Debug: (18) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: (18) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:30 2015 : Debug: %t Thu Jun 18 08:45:30 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:30 2015 : Debug: percent --> t Thu Jun 18 08:45:30 2015 : Debug: (18) auth_log: EXPAND %t Thu Jun 18 08:45:30 2015 : Debug: (18) auth_log: --> Thu Jun 18 08:45:31 2015 Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from auth_log (rlm_detail) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [auth_log] = ok Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling chap (rlm_chap) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from chap (rlm_chap) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [chap] = noop Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling suffix (rlm_realm) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) suffix: Checking for suffix after "@" Thu Jun 18 08:45:30 2015 : Debug: (18) suffix: No '@' in User-Name = "host/workstation.example.com", looking up realm NULL Thu Jun 18 08:45:30 2015 : Debug: (18) suffix: No such realm "NULL" Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from suffix (rlm_realm) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [suffix] = noop Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling eap (rlm_eap) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) eap: Peer sent EAP Response (code 2) ID 9 length 6 Thu Jun 18 08:45:30 2015 : Debug: (18) eap: No EAP Start, assuming it's an on-going EAP conversation Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from eap (rlm_eap) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [eap] = updated Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling files (rlm_files) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from files (rlm_files) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [files] = noop Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling expiration (rlm_expiration) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from expiration (rlm_expiration) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [expiration] = noop Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling logintime (rlm_logintime) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from logintime (rlm_logintime) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [logintime] = noop Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: calling pap (rlm_pap) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authorize]: returned from pap (rlm_pap) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) [pap] = noop Thu Jun 18 08:45:30 2015 : Debug: (18) } # authorize = updated Thu Jun 18 08:45:30 2015 : Debug: (18) Found Auth-Type = EAP Thu Jun 18 08:45:30 2015 : Debug: (18) # Executing group from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:30 2015 : Debug: (18) authenticate { Thu Jun 18 08:45:30 2015 : Debug: (18) modsingle[authenticate]: calling eap (rlm_eap) for request 18 Thu Jun 18 08:45:30 2015 : Debug: (18) eap: Expiring EAP session with state 0x3a6e63843c676e71 Thu Jun 18 08:45:30 2015 : Debug: (18) eap: Finished EAP session with state 0x3a6e63843c676e71 Thu Jun 18 08:45:30 2015 : Debug: (18) eap: Previous EAP request found for state 0x3a6e63843c676e71, released from the list Thu Jun 18 08:45:30 2015 : Debug: (18) eap: Peer sent packet with method EAP TLS (13) Thu Jun 18 08:45:30 2015 : Debug: (18) eap: Calling submodule eap_tls to process data Thu Jun 18 08:45:30 2015 : Debug: (18) eap_tls: Continuing EAP-TLS Thu Jun 18 08:45:30 2015 : Debug: (18) eap_tls: Peer sent flags --- Thu Jun 18 08:45:30 2015 : Debug: (18) eap_tls: Peer ACKed our handshake fragment. handshake is finished Thu Jun 18 08:45:30 2015 : Debug: (18) eap_tls: [eaptls verify] = success Thu Jun 18 08:45:30 2015 : Debug: (18) eap_tls: [eaptls process] = success Thu Jun 18 08:45:30 2015 : Debug: (18) eap_tls: Validating certificate Thu Jun 18 08:45:30 2015 : Debug: (18) Virtual server check-eap-tls received request Thu Jun 18 08:45:30 2015 : Debug: (18) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (18) Chargeable-User-Identity = 0x00 Thu Jun 18 08:45:30 2015 : Debug: (18) Location-Capable = Civix-Location Thu Jun 18 08:45:30 2015 : Debug: (18) Calling-Station-Id = '00-24-d7-03-2b-38' Thu Jun 18 08:45:30 2015 : Debug: (18) Called-Station-Id = 'a4-6c-2a-ea-9b-70:LOGDOM-S' Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-Port = 2 Thu Jun 18 08:45:30 2015 : Debug: (18) Cisco-AVPair = 'audit-session-id=c0a868500000041f55813267' Thu Jun 18 08:45:30 2015 : Debug: (18) Acct-Session-Id = '55813267/00:24:d7:03:2b:38/1070' Thu Jun 18 08:45:30 2015 : Debug: (18) Cisco-AVPair = 'mDNS=true' Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-IP-Address = 192.168.104.80 Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-Identifier = 'wc-s1-01' Thu Jun 18 08:45:30 2015 : Debug: (18) Airespace-Wlan-Id = 2 Thu Jun 18 08:45:30 2015 : Debug: (18) Service-Type = Framed-User Thu Jun 18 08:45:30 2015 : Debug: (18) Framed-MTU = 1300 Thu Jun 18 08:45:30 2015 : Debug: (18) NAS-Port-Type = Wireless-802.11 Thu Jun 18 08:45:30 2015 : Debug: (18) Tunnel-Type:0 = VLAN Thu Jun 18 08:45:30 2015 : Debug: (18) Tunnel-Medium-Type:0 = IEEE-802 Thu Jun 18 08:45:30 2015 : Debug: (18) Tunnel-Private-Group-Id:0 = '101' Thu Jun 18 08:45:30 2015 : Debug: (18) EAP-Message = 0x020900060d00 Thu Jun 18 08:45:30 2015 : Debug: (18) State = 0x3a6e63843c676e7107bd248a4e7da9b5 Thu Jun 18 08:45:30 2015 : Debug: (18) Message-Authenticator = 0x2b586170883a9280b9170bf00dbbb5de Thu Jun 18 08:45:30 2015 : Debug: (18) Event-Timestamp = 'Jun 18 2015 08:45:31 EEST' Thu Jun 18 08:45:30 2015 : Debug: (18) EAP-Type = TLS Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Cert-Serial := '497342570ec0c19f459efdaf66ca76cb' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Cert-Expiration := '230901102449Z' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Cert-Subject := '/DC=com/DC=example/CN=RootCA' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Cert-Issuer := '/DC=com/DC=example/CN=RootCA' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Cert-Common-Name := 'RootCA' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-Serial := '74000000528ce96f685e3bd5b2000000000052' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-Expiration := '160523124059Z' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-Subject := '/CN=workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-Issuer := '/DC=com/DC=example/CN=RootCA' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-Common-Name := 'workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-Subject-Alt-Name-Dns := 'workstation.example.com' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-X509v3-Extended-Key-Usage += 'TLS Web Server Authentication, TLS Web Client Authentication' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-X509v3-Subject-Key-Identifier += '2B:28:8E:20:64:71:34:8A:77:CA:DE:5B:3D:B9:6E:46:E8:AE:99:06' Thu Jun 18 08:45:30 2015 : Debug: (18) TLS-Client-Cert-X509v3-Authority-Key-Identifier += 'keyid:71:FC:8C:7D:7C:8E:3B:F7:F1:99:98:65:C9:E2:E4:21:5C:B9:EE:49 ' Thu Jun 18 08:45:30 2015 : Debug: (18) server check-eap-tls { Thu Jun 18 08:45:30 2015 : Debug: (18) session-state: No cached attributes Thu Jun 18 08:45:31 2015 : Debug: (18) # Executing section authorize from file /etc/raddb/sites-enabled/check-eap-tls Thu Jun 18 08:45:31 2015 : Debug: (18) authorize { Thu Jun 18 08:45:31 2015 : Debug: (18) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@example\.com$/i) { Thu Jun 18 08:45:31 2015 : Debug: (18) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Upn} Thu Jun 18 08:45:31 2015 : Debug: (18) --> Thu Jun 18 08:45:31 2015 : Debug: (18) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@example\.com$/i) -> FALSE Thu Jun 18 08:45:31 2015 : Debug: (18) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.example\.com$/i) { Thu Jun 18 08:45:31 2015 : Debug: (18) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Dns} Thu Jun 18 08:45:31 2015 : Debug: (18) --> workstation.example.com Thu Jun 18 08:45:31 2015 : Debug: (18) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.example\.com$/i) -> TRUE Thu Jun 18 08:45:31 2015 : Debug: (18) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.example\.com$/i) { Thu Jun 18 08:45:31 2015 : Debug: (18) update config { Thu Jun 18 08:45:31 2015 : Debug: (18) Auth-Type := Accept Thu Jun 18 08:45:31 2015 : Debug: (18) } # update config = noop Thu Jun 18 08:45:31 2015 : Debug: (18) } # elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.example\.com$/i) = noop Thu Jun 18 08:45:31 2015 : Debug: (18) ... skipping else for request 18: Preceding "if" was taken Thu Jun 18 08:45:31 2015 : Debug: (18) modsingle[authorize]: calling auth_log (rlm_detail) for request 18 Thu Jun 18 08:45:31 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:31 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:31 2015 : Debug: literal --> /var/log/radius/radacct/ Thu Jun 18 08:45:31 2015 : Debug: if { Thu Jun 18 08:45:31 2015 : Debug: attribute --> Packet-Src-IP-Address Thu Jun 18 08:45:31 2015 : Debug: } Thu Jun 18 08:45:31 2015 : Debug: else { Thu Jun 18 08:45:31 2015 : Debug: attribute --> Packet-Src-IPv6-Address Thu Jun 18 08:45:31 2015 : Debug: } Thu Jun 18 08:45:31 2015 : Debug: literal --> /auth-detail- Thu Jun 18 08:45:31 2015 : Debug: percent --> Y Thu Jun 18 08:45:31 2015 : Debug: percent --> m Thu Jun 18 08:45:31 2015 : Debug: percent --> d Thu Jun 18 08:45:31 2015 : Debug: (18) auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Thu Jun 18 08:45:31 2015 : Debug: (18) auth_log: --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:31 2015 : Debug: (18) auth_log: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150618 Thu Jun 18 08:45:31 2015 : Debug: %t Thu Jun 18 08:45:31 2015 : Debug: Parsed xlat tree: Thu Jun 18 08:45:31 2015 : Debug: percent --> t Thu Jun 18 08:45:31 2015 : Debug: (18) auth_log: EXPAND %t Thu Jun 18 08:45:31 2015 : Debug: (18) auth_log: --> Thu Jun 18 08:45:31 2015 Thu Jun 18 08:45:31 2015 : Debug: (18) modsingle[authorize]: returned from auth_log (rlm_detail) for request 18 Thu Jun 18 08:45:31 2015 : Debug: (18) [auth_log] = ok Thu Jun 18 08:45:31 2015 : Debug: (18) } # authorize = ok Thu Jun 18 08:45:31 2015 : Debug: (18) Found Auth-Type = Accept Thu Jun 18 08:45:31 2015 : Debug: (18) Auth-Type = Accept, accepting the user Thu Jun 18 08:45:31 2015 : Debug: (18) Empty post-auth section. Using default return values. Thu Jun 18 08:45:31 2015 : Auth: (18) Login OK: [host/workstation.example.com] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38 via TLS tunnel) Thu Jun 18 08:45:31 2015 : Debug: (18) } # server check-eap-tls Thu Jun 18 08:45:31 2015 : Debug: (18) Virtual server sending reply Thu Jun 18 08:45:31 2015 : Debug: (18) eap_tls: Saving session d41ba7452ab615ee7034d6eacf3507c298352a47d2399b2e266cc12fcdcdfe77 vps 0x27e2a90 in the cache Thu Jun 18 08:45:31 2015 : Debug: (18) eap: Sending EAP Success (code 3) ID 9 length 4 Thu Jun 18 08:45:31 2015 : Debug: (18) eap: Freeing handler Thu Jun 18 08:45:31 2015 : Debug: (18) modsingle[authenticate]: returned from eap (rlm_eap) for request 18 Thu Jun 18 08:45:31 2015 : Debug: (18) [eap] = ok Thu Jun 18 08:45:31 2015 : Debug: (18) } # authenticate = ok Thu Jun 18 08:45:31 2015 : Debug: (18) # Executing section post-auth from file /etc/raddb/sites-enabled/default Thu Jun 18 08:45:31 2015 : Debug: (18) post-auth { Thu Jun 18 08:45:31 2015 : Debug: (18) modsingle[post-auth]: calling exec (rlm_exec) for request 18 Thu Jun 18 08:45:31 2015 : Debug: (18) modsingle[post-auth]: returned from exec (rlm_exec) for request 18 Thu Jun 18 08:45:31 2015 : Debug: (18) [exec] = noop Thu Jun 18 08:45:31 2015 : Debug: (18) update { Thu Jun 18 08:45:31 2015 : Debug: (18) No attributes updated Thu Jun 18 08:45:31 2015 : Debug: (18) } # update = noop Thu Jun 18 08:45:31 2015 : Debug: (18) policy remove_reply_message_if_eap { Thu Jun 18 08:45:31 2015 : Debug: (18) if (&reply:EAP-Message && &reply:Reply-Message) { Thu Jun 18 08:45:31 2015 : Debug: (18) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Thu Jun 18 08:45:31 2015 : Debug: (18) else { Thu Jun 18 08:45:31 2015 : Debug: (18) modsingle[post-auth]: calling noop (rlm_always) for request 18 Thu Jun 18 08:45:31 2015 : Debug: (18) modsingle[post-auth]: returned from noop (rlm_always) for request 18 Thu Jun 18 08:45:31 2015 : Debug: (18) [noop] = noop Thu Jun 18 08:45:31 2015 : Debug: (18) } # else = noop Thu Jun 18 08:45:31 2015 : Debug: (18) } # policy remove_reply_message_if_eap = noop Thu Jun 18 08:45:31 2015 : Debug: (18) } # post-auth = noop Thu Jun 18 08:45:31 2015 : Auth: (18) Login OK: [host/workstation.example.com] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38) Thu Jun 18 08:45:31 2015 : Debug: (18) Sent Access-Accept Id 1 from 192.168.106.130:1812 to 192.168.104.80:32770 length 0 Thu Jun 18 08:45:31 2015 : Debug: (18) MS-MPPE-Recv-Key = 0x7f5f42afb5007fe3ba03baa2908e5e379d6093dd412f918f5c7e921e09a23c41 Thu Jun 18 08:45:31 2015 : Debug: (18) MS-MPPE-Send-Key = 0xe565e4326720473780d14aa80c9ba6ea042dffae80dd72ff134b99b5accf2f21 Thu Jun 18 08:45:31 2015 : Debug: (18) EAP-Message = 0x03090004 Thu Jun 18 08:45:31 2015 : Debug: (18) Message-Authenticator = 0x00000000000000000000000000000000 Thu Jun 18 08:45:31 2015 : Debug: (18) User-Name = 'host/workstation.example.com' Thu Jun 18 08:45:31 2015 : Debug: (18) Finished request Thu Jun 18 08:45:31 2015 : Debug: (8) : Cleaning up request packet ID 247 with timestamp +2053 Thu Jun 18 08:45:31 2015 : Debug: (9) : Cleaning up request packet ID 248 with timestamp +2053 Thu Jun 18 08:45:31 2015 : Debug: (10) : Cleaning up request packet ID 249 with timestamp +2053 Thu Jun 18 08:45:31 2015 : Debug: Waking up in 4.9 seconds. Thu Jun 18 08:45:35 2015 : Debug: (11) : Cleaning up request packet ID 250 with timestamp +2057 Thu Jun 18 08:45:35 2015 : Debug: (12) : Cleaning up request packet ID 251 with timestamp +2057 Thu Jun 18 08:45:35 2015 : Debug: (13) : Cleaning up request packet ID 252 with timestamp +2057 Thu Jun 18 08:45:35 2015 : Debug: (14) : Cleaning up request packet ID 253 with timestamp +2057 Thu Jun 18 08:45:35 2015 : Debug: (15) : Cleaning up request packet ID 254 with timestamp +2057 Thu Jun 18 08:45:35 2015 : Debug: (16) : Cleaning up request packet ID 255 with timestamp +2057 Thu Jun 18 08:45:35 2015 : Debug: (17) : Cleaning up request packet ID 0 with timestamp +2057 Thu Jun 18 08:45:36 2015 : Debug: (18) : Cleaning up request packet ID 1 with timestamp +2057 Thu Jun 18 08:45:36 2015 : Info: Ready to process requests