Received Access-Request Id 208 from 192.168.104.80:32770 to 192.168.106.130:1812 length 320 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x0201001e01686f73742f4b414c4a4f2d4c542e70616c6d6174696e2e6565 Message-Authenticator = 0x6dbf23afcbaaa6bd53dc543b04df5e21 Mon Jun 15 08:59:42 2015 : Debug: (21) Received Access-Request packet from host 192.168.104.80 port 32770, id=208, length=320 Mon Jun 15 08:59:42 2015 : Debug: (21) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:42 2015 : Debug: (21) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:42 2015 : Debug: (21) Location-Capable = Civix-Location Mon Jun 15 08:59:42 2015 : Debug: (21) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:42 2015 : Debug: (21) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:42 2015 : Debug: (21) NAS-Port = 2 Mon Jun 15 08:59:42 2015 : Debug: (21) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:42 2015 : Debug: (21) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:42 2015 : Debug: (21) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:42 2015 : Debug: (21) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:42 2015 : Debug: (21) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:42 2015 : Debug: (21) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:42 2015 : Debug: (21) Service-Type = Framed-User Mon Jun 15 08:59:42 2015 : Debug: (21) Framed-MTU = 1300 Mon Jun 15 08:59:42 2015 : Debug: (21) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:42 2015 : Debug: (21) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:42 2015 : Debug: (21) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:42 2015 : Debug: (21) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:42 2015 : Debug: (21) EAP-Message = 0x0201001e01686f73742f4b414c4a4f2d4c542e70616c6d6174696e2e6565 Mon Jun 15 08:59:42 2015 : Debug: (21) Message-Authenticator = 0x6dbf23afcbaaa6bd53dc543b04df5e21 Mon Jun 15 08:59:42 2015 : Debug: (21) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:42 2015 : Debug: (21) authorize { Mon Jun 15 08:59:42 2015 : Debug: (21) filter_username filter_username { Mon Jun 15 08:59:42 2015 : Debug: (21) if (!&User-Name) Mon Jun 15 08:59:42 2015 : Debug: (21) if (!&User-Name) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ / /) Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (21) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:42 2015 : Debug: (21) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:42 2015 : Debug: (21) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (21) } # filter_username filter_username = notfound Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) [preprocess] = ok Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: calling auth_log (rlm_detail) for request 21 Mon Jun 15 08:59:42 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:42 2015 : Debug: if { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: else { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:42 2015 : Debug: percent --> Y Mon Jun 15 08:59:42 2015 : Debug: percent --> m Mon Jun 15 08:59:42 2015 : Debug: percent --> d Mon Jun 15 08:59:42 2015 : Debug: (21) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: (21) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:42 2015 : Debug: (21) 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-20150615 Mon Jun 15 08:59:42 2015 : Debug: %t Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: percent --> t Mon Jun 15 08:59:42 2015 : Debug: (21) auth_log : EXPAND %t Mon Jun 15 08:59:42 2015 : Debug: (21) auth_log : --> Mon Jun 15 08:59:42 2015 Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: returned from auth_log (rlm_detail) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) [auth_log] = ok Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: calling chap (rlm_chap) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: returned from chap (rlm_chap) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) [chap] = noop Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: calling suffix (rlm_realm) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) suffix : Checking for suffix after "@" Mon Jun 15 08:59:42 2015 : Debug: (21) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:42 2015 : Debug: (21) suffix : No such realm "NULL" Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: returned from suffix (rlm_realm) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) [suffix] = noop Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: calling eap (rlm_eap) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) eap : Peer sent code Response (2) ID 1 length 30 Mon Jun 15 08:59:42 2015 : Debug: (21) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authorize]: returned from eap (rlm_eap) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) [eap] = ok Mon Jun 15 08:59:42 2015 : Debug: (21) } # authorize = ok Mon Jun 15 08:59:42 2015 : Debug: (21) Found Auth-Type = EAP Mon Jun 15 08:59:42 2015 : Debug: (21) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:42 2015 : Debug: (21) authenticate { Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authenticate]: calling eap (rlm_eap) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) eap : Peer sent method Identity (1) Mon Jun 15 08:59:42 2015 : Debug: (21) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:42 2015 : Debug: (21) eap_tls : Requiring client certificate Mon Jun 15 08:59:42 2015 : Debug: (21) eap_tls : Initiate Mon Jun 15 08:59:42 2015 : Debug: (21) eap_tls : Requiring client certificate Mon Jun 15 08:59:42 2015 : Debug: (21) eap_tls : Start returned 1 Mon Jun 15 08:59:42 2015 : Debug: (21) eap : New EAP session, adding 'State' attribute to reply 0xc97c8fffc97e82af Mon Jun 15 08:59:42 2015 : Debug: (21) modsingle[authenticate]: returned from eap (rlm_eap) for request 21 Mon Jun 15 08:59:42 2015 : Debug: (21) [eap] = handled Mon Jun 15 08:59:42 2015 : Debug: (21) } # authenticate = handled Mon Jun 15 08:59:42 2015 : Debug: (21) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=208, length=0 Mon Jun 15 08:59:42 2015 : Debug: (21) EAP-Message = 0x010200060d20 Mon Jun 15 08:59:42 2015 : Debug: (21) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:42 2015 : Debug: (21) State = 0xc97c8fffc97e82af3c53c4c79ea03253 Sending Access-Challenge Id 208 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010200060d20 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc97c8fffc97e82af3c53c4c79ea03253 Mon Jun 15 08:59:42 2015 : Debug: (21) Finished request Mon Jun 15 08:59:42 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 209 from 192.168.104.80:32770 to 192.168.106.130:1812 length 447 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x0202008b0d8000000081160301007c010000780301557e69ce1ab78fcf60ecf0a141a78815434f997b475763b42103deb8008dfaac205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e90018c014c013c00ac0090035002f00380032000a00130005000401000017000a00080006001900170018000b00020100ff01000100 State = 0xc97c8fffc97e82af3c53c4c79ea03253 Message-Authenticator = 0x0841fae4defe5526d33a4c5f4333c3bc Mon Jun 15 08:59:42 2015 : Debug: (22) Received Access-Request packet from host 192.168.104.80 port 32770, id=209, length=447 Mon Jun 15 08:59:42 2015 : Debug: (22) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:42 2015 : Debug: (22) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:42 2015 : Debug: (22) Location-Capable = Civix-Location Mon Jun 15 08:59:42 2015 : Debug: (22) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:42 2015 : Debug: (22) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:42 2015 : Debug: (22) NAS-Port = 2 Mon Jun 15 08:59:42 2015 : Debug: (22) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:42 2015 : Debug: (22) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:42 2015 : Debug: (22) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:42 2015 : Debug: (22) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:42 2015 : Debug: (22) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:42 2015 : Debug: (22) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:42 2015 : Debug: (22) Service-Type = Framed-User Mon Jun 15 08:59:42 2015 : Debug: (22) Framed-MTU = 1300 Mon Jun 15 08:59:42 2015 : Debug: (22) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:42 2015 : Debug: (22) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:42 2015 : Debug: (22) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:42 2015 : Debug: (22) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:42 2015 : Debug: (22) EAP-Message = 0x0202008b0d8000000081160301007c010000780301557e69ce1ab78fcf60ecf0a141a78815434f997b475763b42103deb8008dfaac205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e90018c014c013c00ac0090035002f00380032000a00130005000401000017000a00080006001900170018000b00020100ff01000100 Mon Jun 15 08:59:42 2015 : Debug: (22) State = 0xc97c8fffc97e82af3c53c4c79ea03253 Mon Jun 15 08:59:42 2015 : Debug: (22) Message-Authenticator = 0x0841fae4defe5526d33a4c5f4333c3bc Mon Jun 15 08:59:42 2015 : Debug: (22) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:42 2015 : Debug: (22) authorize { Mon Jun 15 08:59:42 2015 : Debug: (22) filter_username filter_username { Mon Jun 15 08:59:42 2015 : Debug: (22) if (!&User-Name) Mon Jun 15 08:59:42 2015 : Debug: (22) if (!&User-Name) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ / /) Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (22) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:42 2015 : Debug: (22) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:42 2015 : Debug: (22) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (22) } # filter_username filter_username = notfound Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [preprocess] = ok Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling auth_log (rlm_detail) for request 22 Mon Jun 15 08:59:42 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:42 2015 : Debug: if { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: else { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:42 2015 : Debug: percent --> Y Mon Jun 15 08:59:42 2015 : Debug: percent --> m Mon Jun 15 08:59:42 2015 : Debug: percent --> d Mon Jun 15 08:59:42 2015 : Debug: (22) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: (22) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:42 2015 : Debug: (22) 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-20150615 Mon Jun 15 08:59:42 2015 : Debug: %t Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: percent --> t Mon Jun 15 08:59:42 2015 : Debug: (22) auth_log : EXPAND %t Mon Jun 15 08:59:42 2015 : Debug: (22) auth_log : --> Mon Jun 15 08:59:42 2015 Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from auth_log (rlm_detail) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [auth_log] = ok Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling chap (rlm_chap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from chap (rlm_chap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [chap] = noop Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling suffix (rlm_realm) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) suffix : Checking for suffix after "@" Mon Jun 15 08:59:42 2015 : Debug: (22) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:42 2015 : Debug: (22) suffix : No such realm "NULL" Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from suffix (rlm_realm) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [suffix] = noop Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling eap (rlm_eap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) eap : Peer sent code Response (2) ID 2 length 139 Mon Jun 15 08:59:42 2015 : Debug: (22) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from eap (rlm_eap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [eap] = updated Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling files (rlm_files) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from files (rlm_files) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [files] = noop Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling expiration (rlm_expiration) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from expiration (rlm_expiration) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [expiration] = noop Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling logintime (rlm_logintime) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from logintime (rlm_logintime) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [logintime] = noop Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: calling pap (rlm_pap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authorize]: returned from pap (rlm_pap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [pap] = noop Mon Jun 15 08:59:42 2015 : Debug: (22) } # authorize = updated Mon Jun 15 08:59:42 2015 : Debug: (22) Found Auth-Type = EAP Mon Jun 15 08:59:42 2015 : Debug: (22) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:42 2015 : Debug: (22) authenticate { Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authenticate]: calling eap (rlm_eap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) eap : Expiring EAP session with state 0xc97c8fffc97e82af Mon Jun 15 08:59:42 2015 : Debug: (22) eap : Finished EAP session with state 0xc97c8fffc97e82af Mon Jun 15 08:59:42 2015 : Debug: (22) eap : Previous EAP request found for state 0xc97c8fffc97e82af, released from the list Mon Jun 15 08:59:42 2015 : Debug: (22) eap : Peer sent method TLS (13) Mon Jun 15 08:59:42 2015 : Debug: (22) eap : EAP TLS (13) Mon Jun 15 08:59:42 2015 : Debug: (22) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : Authenticate Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : processing EAP-TLS Mon Jun 15 08:59:42 2015 : Debug: TLS Length 129 Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : Length Included Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : eaptls_verify returned 11 Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : (other): before/accept initialization Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : TLS_accept: before/accept initialization Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : <<< TLS 1.0 Handshake [length 007c], ClientHello Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : TLS_accept: SSLv3 read client hello A Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : >>> TLS 1.0 Handshake [length 0059], ServerHello Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : TLS_accept: SSLv3 write server hello A Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : >>> TLS 1.0 ChangeCipherSpec [length 0001] Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : TLS_accept: SSLv3 write change cipher spec A Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : >>> TLS 1.0 Handshake [length 0010], Finished Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : TLS_accept: SSLv3 write finished A Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : TLS_accept: SSLv3 flush data Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : TLS_accept: Need to read more data: SSLv3 read finished A Mon Jun 15 08:59:42 2015 : Debug: In SSL Handshake Phase Mon Jun 15 08:59:42 2015 : Debug: In SSL Accept mode Mon Jun 15 08:59:42 2015 : Debug: (22) eap_tls : eaptls_process returned 13 Mon Jun 15 08:59:42 2015 : Debug: (22) eap : New EAP session, adding 'State' attribute to reply 0xc97c8fffc87f82af Mon Jun 15 08:59:42 2015 : Debug: (22) modsingle[authenticate]: returned from eap (rlm_eap) for request 22 Mon Jun 15 08:59:42 2015 : Debug: (22) [eap] = handled Mon Jun 15 08:59:42 2015 : Debug: (22) } # authenticate = handled Mon Jun 15 08:59:42 2015 : Debug: (22) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=209, length=0 Mon Jun 15 08:59:42 2015 : Debug: (22) EAP-Message = 0x010300a30d80000000991603010059020000550301557e69ce7c823bc16a8fd919800aa7afee1b3f280c512be95407552e1845990b205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9c01400000dff01000100000b00040300010214030100010116030100305bbfad4bd98747cc1b6f6968080314cbb9d9107b8c2ba6ebc36381688d996ca11f362c2e2c79082dfd77d7697406a06a Mon Jun 15 08:59:42 2015 : Debug: (22) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:42 2015 : Debug: (22) State = 0xc97c8fffc87f82af3c53c4c79ea03253 Sending Access-Challenge Id 209 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010300a30d80000000991603010059020000550301557e69ce7c823bc16a8fd919800aa7afee1b3f280c512be95407552e1845990b205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9c01400000dff01000100000b00040300010214030100010116030100305bbfad4bd98747cc1b6f6968080314cbb9d9107b8c2ba6ebc36381688d996ca11f362c2e2c79082dfd77d7697406a06a Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc97c8fffc87f82af3c53c4c79ea03253 Mon Jun 15 08:59:42 2015 : Debug: (22) Finished request Mon Jun 15 08:59:42 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 210 from 192.168.104.80:32770 to 192.168.106.130:1812 length 377 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020300450d800000003b1403010001011603010030a3aed1854bf053eea4213ba6c49e59e717796a0a422e900354109588544d11f006c69e27752b5910e29d478f853bfc8f State = 0xc97c8fffc87f82af3c53c4c79ea03253 Message-Authenticator = 0xd495ada01077e7582c7f215b1b6d13ba Mon Jun 15 08:59:42 2015 : Debug: (23) Received Access-Request packet from host 192.168.104.80 port 32770, id=210, length=377 Mon Jun 15 08:59:42 2015 : Debug: (23) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:42 2015 : Debug: (23) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:42 2015 : Debug: (23) Location-Capable = Civix-Location Mon Jun 15 08:59:42 2015 : Debug: (23) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:42 2015 : Debug: (23) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:42 2015 : Debug: (23) NAS-Port = 2 Mon Jun 15 08:59:42 2015 : Debug: (23) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:42 2015 : Debug: (23) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:42 2015 : Debug: (23) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:42 2015 : Debug: (23) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:42 2015 : Debug: (23) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:42 2015 : Debug: (23) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:42 2015 : Debug: (23) Service-Type = Framed-User Mon Jun 15 08:59:42 2015 : Debug: (23) Framed-MTU = 1300 Mon Jun 15 08:59:42 2015 : Debug: (23) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:42 2015 : Debug: (23) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:42 2015 : Debug: (23) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:42 2015 : Debug: (23) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:42 2015 : Debug: (23) EAP-Message = 0x020300450d800000003b1403010001011603010030a3aed1854bf053eea4213ba6c49e59e717796a0a422e900354109588544d11f006c69e27752b5910e29d478f853bfc8f Mon Jun 15 08:59:42 2015 : Debug: (23) State = 0xc97c8fffc87f82af3c53c4c79ea03253 Mon Jun 15 08:59:42 2015 : Debug: (23) Message-Authenticator = 0xd495ada01077e7582c7f215b1b6d13ba Mon Jun 15 08:59:42 2015 : Debug: (23) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:42 2015 : Debug: (23) authorize { Mon Jun 15 08:59:42 2015 : Debug: (23) filter_username filter_username { Mon Jun 15 08:59:42 2015 : Debug: (23) if (!&User-Name) Mon Jun 15 08:59:42 2015 : Debug: (23) if (!&User-Name) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ / /) Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:42 2015 : Debug: (23) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:42 2015 : Debug: (23) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) } # filter_username filter_username = notfound Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [preprocess] = ok Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling auth_log (rlm_detail) for request 23 Mon Jun 15 08:59:42 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:42 2015 : Debug: if { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: else { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:42 2015 : Debug: percent --> Y Mon Jun 15 08:59:42 2015 : Debug: percent --> m Mon Jun 15 08:59:42 2015 : Debug: percent --> d Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:42 2015 : Debug: (23) 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-20150615 Mon Jun 15 08:59:42 2015 : Debug: %t Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: percent --> t Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : EXPAND %t Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : --> Mon Jun 15 08:59:42 2015 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from auth_log (rlm_detail) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [auth_log] = ok Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling chap (rlm_chap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from chap (rlm_chap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [chap] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling suffix (rlm_realm) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) suffix : Checking for suffix after "@" Mon Jun 15 08:59:42 2015 : Debug: (23) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:42 2015 : Debug: (23) suffix : No such realm "NULL" Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from suffix (rlm_realm) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [suffix] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling eap (rlm_eap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Peer sent code Response (2) ID 3 length 69 Mon Jun 15 08:59:42 2015 : Debug: (23) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from eap (rlm_eap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [eap] = updated Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling files (rlm_files) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from files (rlm_files) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [files] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling expiration (rlm_expiration) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from expiration (rlm_expiration) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [expiration] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling logintime (rlm_logintime) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from logintime (rlm_logintime) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [logintime] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling pap (rlm_pap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from pap (rlm_pap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [pap] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) } # authorize = updated Mon Jun 15 08:59:42 2015 : Debug: (23) Found Auth-Type = EAP Mon Jun 15 08:59:42 2015 : Debug: (23) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:42 2015 : Debug: (23) authenticate { Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authenticate]: calling eap (rlm_eap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Expiring EAP session with state 0xc97c8fffc87f82af Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Finished EAP session with state 0xc97c8fffc87f82af Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Previous EAP request found for state 0xc97c8fffc87f82af, released from the list Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Peer sent method TLS (13) Mon Jun 15 08:59:42 2015 : Debug: (23) eap : EAP TLS (13) Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : Authenticate Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : processing EAP-TLS Mon Jun 15 08:59:42 2015 : Debug: TLS Length 59 Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : Length Included Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : eaptls_verify returned 11 Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : <<< TLS 1.0 ChangeCipherSpec [length 0001] Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : <<< TLS 1.0 Handshake [length 0010], Finished Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : TLS_accept: SSLv3 read finished A Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : (other): SSL negotiation finished successfully Mon Jun 15 08:59:42 2015 : Debug: SSL Connection Established Mon Jun 15 08:59:42 2015 : Debug: SSL Application Data Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : eaptls_process returned 3 Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : Processing EAP-TLS Certificate check: Mon Jun 15 08:59:42 2015 : Debug: (23) server check-eap-tls { Mon Jun 15 08:59:42 2015 : Debug: (23) Request: User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020300450d800000003b1403010001011603010030a3aed1854bf053eea4213ba6c49e59e717796a0a422e900354109588544d11f006c69e27752b5910e29d478f853bfc8f State = 0xc97c8fffc87f82af3c53c4c79ea03253 Message-Authenticator = 0xd495ada01077e7582c7f215b1b6d13ba Event-Timestamp = 'Jun 15 2015 08:59:42 EEST' EAP-Type = TLS Mon Jun 15 08:59:42 2015 : Debug: (23) # Executing section authorize from file /etc/raddb/sites-enabled/check-eap-tls Mon Jun 15 08:59:42 2015 : Debug: (23) authorize { Mon Jun 15 08:59:42 2015 : Debug: (23) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@private\.com$/i) Mon Jun 15 08:59:42 2015 : Debug: (23) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Upn} Mon Jun 15 08:59:42 2015 : Debug: (23) --> Mon Jun 15 08:59:42 2015 : Debug: (23) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@private\.com$/i) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) Mon Jun 15 08:59:42 2015 : Debug: (23) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Dns} Mon Jun 15 08:59:42 2015 : Debug: (23) --> Mon Jun 15 08:59:42 2015 : Debug: (23) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) else else { Mon Jun 15 08:59:42 2015 : Debug: (23) update config { Mon Jun 15 08:59:42 2015 : Debug: (23) Auth-Type := Reject Mon Jun 15 08:59:42 2015 : Debug: (23) } # update config = noop Mon Jun 15 08:59:42 2015 : Debug: (23) } # else else = noop Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: calling auth_log (rlm_detail) for request 23 Mon Jun 15 08:59:42 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:42 2015 : Debug: if { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: else { Mon Jun 15 08:59:42 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:42 2015 : Debug: } Mon Jun 15 08:59:42 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:42 2015 : Debug: percent --> Y Mon Jun 15 08:59:42 2015 : Debug: percent --> m Mon Jun 15 08:59:42 2015 : Debug: percent --> d Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:42 2015 : Debug: (23) 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-20150615 Mon Jun 15 08:59:42 2015 : Debug: %t Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: percent --> t Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : EXPAND %t Mon Jun 15 08:59:42 2015 : Debug: (23) auth_log : --> Mon Jun 15 08:59:42 2015 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authorize]: returned from auth_log (rlm_detail) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [auth_log] = ok Mon Jun 15 08:59:42 2015 : Debug: (23) } # authorize = ok Mon Jun 15 08:59:42 2015 : Debug: (23) Found Auth-Type = Reject Mon Jun 15 08:59:42 2015 : Debug: (23) Auth-Type = Reject, rejecting user Mon Jun 15 08:59:42 2015 : Debug: (23) Failed to authenticate the user Mon Jun 15 08:59:42 2015 : Auth: (23) Login incorrect: [host/user_host.private.com/] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38 via TLS tunnel) Mon Jun 15 08:59:42 2015 : Debug: (23) Using Post-Auth-Type Reject Mon Jun 15 08:59:42 2015 : Debug: (23) Post-Auth-Type sub-section not found. Ignoring. Mon Jun 15 08:59:42 2015 : Debug: (23) Reply: Mon Jun 15 08:59:42 2015 : Debug: (23) } # server check-eap-tls Mon Jun 15 08:59:42 2015 : Debug: (23) eap_tls : Certificates were rejected by the virtual server Mon Jun 15 08:59:42 2015 : Debug: SSL: Removing session 5bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9 from the cache Mon Jun 15 08:59:42 2015 : ERROR: (23) eap : Failed continuing EAP TLS (13) session. EAP sub-module failed Mon Jun 15 08:59:42 2015 : Debug: Freeing cached session VPs Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Failed in EAP select Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[authenticate]: returned from eap (rlm_eap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [eap] = invalid Mon Jun 15 08:59:42 2015 : Debug: (23) } # authenticate = invalid Mon Jun 15 08:59:42 2015 : Debug: (23) Failed to authenticate the user Mon Jun 15 08:59:42 2015 : Auth: (23) Login incorrect (eap: Failed continuing EAP TLS (13) session. EAP sub-module failed): [host/user_host.private.com/] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38) Mon Jun 15 08:59:42 2015 : Debug: (23) Using Post-Auth-Type Reject Mon Jun 15 08:59:42 2015 : Debug: (23) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:42 2015 : Debug: (23) Post-Auth-Type REJECT { Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 23 Mon Jun 15 08:59:42 2015 : Debug: %{User-Name} Mon Jun 15 08:59:42 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:42 2015 : Debug: attribute --> User-Name Mon Jun 15 08:59:42 2015 : Debug: (23) attr_filter.access_reject : EXPAND %{User-Name} Mon Jun 15 08:59:42 2015 : Debug: (23) attr_filter.access_reject : --> host/user_host.private.com Mon Jun 15 08:59:42 2015 : Debug: (23) attr_filter.access_reject : Matched entry DEFAULT at line 11 Mon Jun 15 08:59:42 2015 : Debug: (23) attr_filter.access_reject : EAP-Message = 0x04030004 allowed by EAP-Message =* 0x Mon Jun 15 08:59:42 2015 : Debug: (23) attr_filter.access_reject : Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Mon Jun 15 08:59:42 2015 : Debug: (23) attr_filter.access_reject : Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Mon Jun 15 08:59:42 2015 : Debug: (23) attr_filter.access_reject : Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [attr_filter.access_reject] = updated Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[post-auth]: calling eap (rlm_eap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) eap : Reply already contained an EAP-Message, not inserting EAP-Failure Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[post-auth]: returned from eap (rlm_eap) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [eap] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) remove_reply_message_if_eap remove_reply_message_if_eap { Mon Jun 15 08:59:42 2015 : Debug: (23) if (&reply:EAP-Message && &reply:Reply-Message) Mon Jun 15 08:59:42 2015 : Debug: (23) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Mon Jun 15 08:59:42 2015 : Debug: (23) else else { Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[post-auth]: calling noop (rlm_always) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) modsingle[post-auth]: returned from noop (rlm_always) for request 23 Mon Jun 15 08:59:42 2015 : Debug: (23) [noop] = noop Mon Jun 15 08:59:42 2015 : Debug: (23) } # else else = noop Mon Jun 15 08:59:42 2015 : Debug: (23) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop Mon Jun 15 08:59:42 2015 : Debug: (23) } # Post-Auth-Type REJECT = updated Mon Jun 15 08:59:42 2015 : Debug: (23) Delaying response for 1 seconds Mon Jun 15 08:59:42 2015 : Debug: Waking up in 0.6 seconds. Mon Jun 15 08:59:43 2015 : Debug: Waking up in 0.3 seconds. Mon Jun 15 08:59:43 2015 : Debug: (23) Sending delayed response Mon Jun 15 08:59:43 2015 : Debug: (23) Sending Access-Reject packet to host 192.168.104.80 port 32770, id=210, length=0 Mon Jun 15 08:59:43 2015 : Debug: (23) EAP-Message = 0x04030004 Mon Jun 15 08:59:43 2015 : Debug: (23) Message-Authenticator = 0x00000000000000000000000000000000 Sending Access-Reject Id 210 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x04030004 Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:43 2015 : Debug: Waking up in 3.9 seconds. Mon Jun 15 08:59:47 2015 : Debug: (21) Cleaning up request packet ID 208 with timestamp +3333 Mon Jun 15 08:59:47 2015 : Debug: (22) Cleaning up request packet ID 209 with timestamp +3333 Mon Jun 15 08:59:47 2015 : Debug: (23) Cleaning up request packet ID 210 with timestamp +3333 Mon Jun 15 08:59:47 2015 : Info: Ready to process requests Received Access-Request Id 211 from 192.168.104.80:32770 to 192.168.106.130:1812 length 320 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x0202001e01686f73742f4b414c4a4f2d4c542e70616c6d6174696e2e6565 Message-Authenticator = 0x41cc96ed9003f857a1345b4689fb4488 Mon Jun 15 08:59:47 2015 : Debug: (24) Received Access-Request packet from host 192.168.104.80 port 32770, id=211, length=320 Mon Jun 15 08:59:47 2015 : Debug: (24) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (24) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (24) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (24) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (24) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (24) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (24) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (24) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (24) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (24) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (24) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (24) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (24) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (24) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (24) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (24) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (24) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (24) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (24) EAP-Message = 0x0202001e01686f73742f4b414c4a4f2d4c542e70616c6d6174696e2e6565 Mon Jun 15 08:59:47 2015 : Debug: (24) Message-Authenticator = 0x41cc96ed9003f857a1345b4689fb4488 Mon Jun 15 08:59:47 2015 : Debug: (24) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (24) authorize { Mon Jun 15 08:59:47 2015 : Debug: (24) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (24) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (24) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (24) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (24) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (24) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (24) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: calling auth_log (rlm_detail) for request 24 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (24) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (24) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (24) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (24) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (24) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: returned from auth_log (rlm_detail) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: calling chap (rlm_chap) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: returned from chap (rlm_chap) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: calling suffix (rlm_realm) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (24) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (24) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: returned from suffix (rlm_realm) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: calling eap (rlm_eap) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) eap : Peer sent code Response (2) ID 2 length 30 Mon Jun 15 08:59:47 2015 : Debug: (24) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authorize]: returned from eap (rlm_eap) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) [eap] = ok Mon Jun 15 08:59:47 2015 : Debug: (24) } # authorize = ok Mon Jun 15 08:59:47 2015 : Debug: (24) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (24) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (24) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authenticate]: calling eap (rlm_eap) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) eap : Peer sent method Identity (1) Mon Jun 15 08:59:47 2015 : Debug: (24) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (24) eap_tls : Requiring client certificate Mon Jun 15 08:59:47 2015 : Debug: (24) eap_tls : Initiate Mon Jun 15 08:59:47 2015 : Debug: (24) eap_tls : Requiring client certificate Mon Jun 15 08:59:47 2015 : Debug: (24) eap_tls : Start returned 1 Mon Jun 15 08:59:47 2015 : Debug: (24) eap : New EAP session, adding 'State' attribute to reply 0x4db356524db05b14 Mon Jun 15 08:59:47 2015 : Debug: (24) modsingle[authenticate]: returned from eap (rlm_eap) for request 24 Mon Jun 15 08:59:47 2015 : Debug: (24) [eap] = handled Mon Jun 15 08:59:47 2015 : Debug: (24) } # authenticate = handled Mon Jun 15 08:59:47 2015 : Debug: (24) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=211, length=0 Mon Jun 15 08:59:47 2015 : Debug: (24) EAP-Message = 0x010300060d20 Mon Jun 15 08:59:47 2015 : Debug: (24) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (24) State = 0x4db356524db05b14caf657079e75e95d Sending Access-Challenge Id 211 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010300060d20 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4db356524db05b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (24) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 212 from 192.168.104.80:32770 to 192.168.106.130:1812 length 447 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x0203008b0d8000000081160301007c010000780301557e69d3b30ecf962fa7180a413aee2df562d140a4f9caf2aa5d457669a82581205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e90018c014c013c00ac0090035002f00380032000a00130005000401000017000a00080006001900170018000b00020100ff01000100 State = 0x4db356524db05b14caf657079e75e95d Message-Authenticator = 0xeb3cc119e7e2a133ee1c697e7b4c25dd Mon Jun 15 08:59:47 2015 : Debug: (25) Received Access-Request packet from host 192.168.104.80 port 32770, id=212, length=447 Mon Jun 15 08:59:47 2015 : Debug: (25) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (25) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (25) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (25) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (25) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (25) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (25) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (25) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (25) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (25) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (25) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (25) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (25) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (25) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (25) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (25) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (25) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (25) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (25) EAP-Message = 0x0203008b0d8000000081160301007c010000780301557e69d3b30ecf962fa7180a413aee2df562d140a4f9caf2aa5d457669a82581205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e90018c014c013c00ac0090035002f00380032000a00130005000401000017000a00080006001900170018000b00020100ff01000100 Mon Jun 15 08:59:47 2015 : Debug: (25) State = 0x4db356524db05b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (25) Message-Authenticator = 0xeb3cc119e7e2a133ee1c697e7b4c25dd Mon Jun 15 08:59:47 2015 : Debug: (25) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (25) authorize { Mon Jun 15 08:59:47 2015 : Debug: (25) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (25) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (25) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (25) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (25) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (25) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (25) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling auth_log (rlm_detail) for request 25 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (25) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (25) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (25) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (25) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (25) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from auth_log (rlm_detail) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling chap (rlm_chap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from chap (rlm_chap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling suffix (rlm_realm) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (25) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (25) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from suffix (rlm_realm) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling eap (rlm_eap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) eap : Peer sent code Response (2) ID 3 length 139 Mon Jun 15 08:59:47 2015 : Debug: (25) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from eap (rlm_eap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [eap] = updated Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling files (rlm_files) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from files (rlm_files) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [files] = noop Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling expiration (rlm_expiration) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from expiration (rlm_expiration) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [expiration] = noop Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling logintime (rlm_logintime) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from logintime (rlm_logintime) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [logintime] = noop Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: calling pap (rlm_pap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authorize]: returned from pap (rlm_pap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [pap] = noop Mon Jun 15 08:59:47 2015 : Debug: (25) } # authorize = updated Mon Jun 15 08:59:47 2015 : Debug: (25) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (25) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (25) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authenticate]: calling eap (rlm_eap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) eap : Expiring EAP session with state 0x4db356524db05b14 Mon Jun 15 08:59:47 2015 : Debug: (25) eap : Finished EAP session with state 0x4db356524db05b14 Mon Jun 15 08:59:47 2015 : Debug: (25) eap : Previous EAP request found for state 0x4db356524db05b14, released from the list Mon Jun 15 08:59:47 2015 : Debug: (25) eap : Peer sent method TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (25) eap : EAP TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (25) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : Authenticate Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : processing EAP-TLS Mon Jun 15 08:59:47 2015 : Debug: TLS Length 129 Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : Length Included Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : eaptls_verify returned 11 Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : (other): before/accept initialization Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: before/accept initialization Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : <<< TLS 1.0 Handshake [length 007c], ClientHello Mon Jun 15 08:59:47 2015 : Debug: SSL: Client requested cached session 5bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9 Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: SSLv3 read client hello A Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : >>> TLS 1.0 Handshake [length 0059], ServerHello Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: SSLv3 write server hello A Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : >>> TLS 1.0 Handshake [length 0c46], Certificate Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: SSLv3 write certificate A Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: SSLv3 write key exchange A Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : >>> TLS 1.0 Handshake [length 005b], CertificateRequest Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: SSLv3 write certificate request A Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: SSLv3 flush data Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : TLS_accept: Need to read more data: SSLv3 read client certificate A Mon Jun 15 08:59:47 2015 : Debug: In SSL Handshake Phase Mon Jun 15 08:59:47 2015 : Debug: In SSL Accept mode Mon Jun 15 08:59:47 2015 : Debug: (25) eap_tls : eaptls_process returned 13 Mon Jun 15 08:59:47 2015 : Debug: (25) eap : New EAP session, adding 'State' attribute to reply 0x4db356524cb75b14 Mon Jun 15 08:59:47 2015 : Debug: (25) modsingle[authenticate]: returned from eap (rlm_eap) for request 25 Mon Jun 15 08:59:47 2015 : Debug: (25) [eap] = handled Mon Jun 15 08:59:47 2015 : Debug: (25) } # authenticate = handled Mon Jun 15 08:59:47 2015 : Debug: (25) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=212, length=0 Mon Jun 15 08:59:47 2015 : Debug: (25) EAP-Message = 0x010404000dc000000e591603010059020000550301557e69d3a8e918720d241d37dbaa6cf0c55ab708732442249f1386d698c5006320898ec6938e09dcb3a158c6386fdf3ef3c891156ac05960b9be6be1692600a937c01400000dff01000100000b0004030001021603010c460b000c42000c3f0006c8308206c4308204aca0030201020213740000006a74a572c34ebbf02c00000000006a300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532393035333830345a170d3137303532393035343830345a30818c310b30090603550406130245453111300f060355040813084861726a756d61613111300f060355040713085461626173616c7531143012060355040a130b50616c6d6174696e204f59311b3019060355040313127261646975732e70616c6d6174696e2e65653124302206092a864886f70d010901161573797361646d696e734070616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100f4d7d99606c770826ca1e9944fe8ca7690cc7d59d57bf554ce4b4351322553554a5302235a9b524371d3ba4b034efdde15acabe5 Mon Jun 15 08:59:47 2015 : Debug: (25) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (25) State = 0x4db356524cb75b14caf657079e75e95d Sending Access-Challenge Id 212 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010404000dc000000e591603010059020000550301557e69d3a8e918720d241d37dbaa6cf0c55ab708732442249f1386d698c5006320898ec6938e09dcb3a158c6386fdf3ef3c891156ac05960b9be6be1692600a937c01400000dff01000100000b0004030001021603010c460b000c42000c3f0006c8308206c4308204aca0030201020213740000006a74a572c34ebbf02c00000000006a300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532393035333830345a170d3137303532393035343830345a30818c310b30090603550406130245453111300f060355040813084861726a756d61613111300f060355040713085461626173616c7531143012060355040a130b50616c6d6174696e204f59311b3019060355040313127261646975732e70616c6d6174696e2e65653124302206092a864886f70d010901161573797361646d696e734070616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100f4d7d99606c770826ca1e9944fe8ca7690cc7d59d57bf554ce4b4351322553554a5302235a9b524371d3ba4b034efdde15acabe Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4db356524cb75b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (25) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 213 from 192.168.104.80:32770 to 192.168.106.130:1812 length 314 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020400060d00 State = 0x4db356524cb75b14caf657079e75e95d Message-Authenticator = 0x13a848babf5b16153fdc801e1255399e Mon Jun 15 08:59:47 2015 : Debug: (26) Received Access-Request packet from host 192.168.104.80 port 32770, id=213, length=314 Mon Jun 15 08:59:47 2015 : Debug: (26) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (26) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (26) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (26) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (26) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (26) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (26) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (26) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (26) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (26) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (26) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (26) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (26) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (26) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (26) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (26) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (26) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (26) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (26) EAP-Message = 0x020400060d00 Mon Jun 15 08:59:47 2015 : Debug: (26) State = 0x4db356524cb75b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (26) Message-Authenticator = 0x13a848babf5b16153fdc801e1255399e Mon Jun 15 08:59:47 2015 : Debug: (26) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (26) authorize { Mon Jun 15 08:59:47 2015 : Debug: (26) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (26) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (26) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (26) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (26) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (26) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (26) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling auth_log (rlm_detail) for request 26 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (26) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (26) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (26) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (26) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (26) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from auth_log (rlm_detail) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling chap (rlm_chap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from chap (rlm_chap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling suffix (rlm_realm) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (26) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (26) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from suffix (rlm_realm) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling eap (rlm_eap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) eap : Peer sent code Response (2) ID 4 length 6 Mon Jun 15 08:59:47 2015 : Debug: (26) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from eap (rlm_eap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [eap] = updated Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling files (rlm_files) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from files (rlm_files) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [files] = noop Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling expiration (rlm_expiration) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from expiration (rlm_expiration) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [expiration] = noop Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling logintime (rlm_logintime) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from logintime (rlm_logintime) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [logintime] = noop Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: calling pap (rlm_pap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authorize]: returned from pap (rlm_pap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [pap] = noop Mon Jun 15 08:59:47 2015 : Debug: (26) } # authorize = updated Mon Jun 15 08:59:47 2015 : Debug: (26) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (26) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (26) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authenticate]: calling eap (rlm_eap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) eap : Expiring EAP session with state 0x4db356524cb75b14 Mon Jun 15 08:59:47 2015 : Debug: (26) eap : Finished EAP session with state 0x4db356524cb75b14 Mon Jun 15 08:59:47 2015 : Debug: (26) eap : Previous EAP request found for state 0x4db356524cb75b14, released from the list Mon Jun 15 08:59:47 2015 : Debug: (26) eap : Peer sent method TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (26) eap : EAP TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (26) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (26) eap_tls : Authenticate Mon Jun 15 08:59:47 2015 : Debug: (26) eap_tls : processing EAP-TLS Mon Jun 15 08:59:47 2015 : Debug: (26) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (26) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (26) eap_tls : ACK handshake fragment handler Mon Jun 15 08:59:47 2015 : Debug: (26) eap_tls : eaptls_verify returned 1 Mon Jun 15 08:59:47 2015 : Debug: (26) eap_tls : eaptls_process returned 13 Mon Jun 15 08:59:47 2015 : Debug: (26) eap : New EAP session, adding 'State' attribute to reply 0x4db356524fb65b14 Mon Jun 15 08:59:47 2015 : Debug: (26) modsingle[authenticate]: returned from eap (rlm_eap) for request 26 Mon Jun 15 08:59:47 2015 : Debug: (26) [eap] = handled Mon Jun 15 08:59:47 2015 : Debug: (26) } # authenticate = handled Mon Jun 15 08:59:47 2015 : Debug: (26) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=213, length=0 Mon Jun 15 08:59:47 2015 : Debug: (26) EAP-Message = 0x010504000dc000000e59050730028681a26c6461703a2f2f2f434e3d50616c6d6174696e4f59526f6f7443412c434e3d4149412c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d70616c6d6174696e2c44433d65653f634143657274696669636174653f626173653f6f626a656374436c6173733d63657274696669636174696f6e417574686f72697479300e0603551d0f0101ff0404030205a0303e06092b06010401823715070431302f06272b06010401823715088398af2881ddf91a87fd9f1983f0ef4084c3d31e810981818b4585e8c57702016402010330130603551d25040c300a06082b06010505070301301b06092b060104018237150a040e300c300a06082b06010505070301300d06092a864886f70d01010505000382020100603588f4deba0a7bcb1dda8405f9fa0904a52ee5c808399869ba2576dcc859b7a43fb757d4535f91183e920dc4ee02a9d93a635ac2f1f85f622f21ad494f651c51ae4a09fbbb6cd3cd99da39d1ce87cda127b6912ebaa4c7d435428e7d67e89be94f5868f23b91016543abdd882423e4f365d8400d0145adad5a7e123ebb74c8bfae12e3fa5e3c6c45a520f1d3ed63797a10efebb47286432b981924f887f6a59e3dae92ae94bd484c619df729e9 Mon Jun 15 08:59:47 2015 : Debug: (26) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (26) State = 0x4db356524fb65b14caf657079e75e95d Sending Access-Challenge Id 213 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010504000dc000000e59050730028681a26c6461703a2f2f2f434e3d50616c6d6174696e4f59526f6f7443412c434e3d4149412c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d70616c6d6174696e2c44433d65653f634143657274696669636174653f626173653f6f626a656374436c6173733d63657274696669636174696f6e417574686f72697479300e0603551d0f0101ff0404030205a0303e06092b06010401823715070431302f06272b06010401823715088398af2881ddf91a87fd9f1983f0ef4084c3d31e810981818b4585e8c57702016402010330130603551d25040c300a06082b06010505070301301b06092b060104018237150a040e300c300a06082b06010505070301300d06092a864886f70d01010505000382020100603588f4deba0a7bcb1dda8405f9fa0904a52ee5c808399869ba2576dcc859b7a43fb757d4535f91183e920dc4ee02a9d93a635ac2f1f85f622f21ad494f651c51ae4a09fbbb6cd3cd99da39d1ce87cda127b6912ebaa4c7d435428e7d67e89be94f5868f23b91016543abdd882423e4f365d8400d0145adad5a7e123ebb74c8bfae12e3fa5e3c6c45a520f1d3ed63797a10efebb47286432b981924f887f6a59e3dae92ae94bd484c619df729e Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4db356524fb65b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (26) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 214 from 192.168.104.80:32770 to 192.168.106.130:1812 length 314 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020500060d00 State = 0x4db356524fb65b14caf657079e75e95d Message-Authenticator = 0x4596f4bbfd1295e7c5ccfd2d6f71ec91 Mon Jun 15 08:59:47 2015 : Debug: (27) Received Access-Request packet from host 192.168.104.80 port 32770, id=214, length=314 Mon Jun 15 08:59:47 2015 : Debug: (27) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (27) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (27) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (27) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (27) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (27) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (27) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (27) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (27) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (27) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (27) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (27) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (27) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (27) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (27) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (27) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (27) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (27) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (27) EAP-Message = 0x020500060d00 Mon Jun 15 08:59:47 2015 : Debug: (27) State = 0x4db356524fb65b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (27) Message-Authenticator = 0x4596f4bbfd1295e7c5ccfd2d6f71ec91 Mon Jun 15 08:59:47 2015 : Debug: (27) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (27) authorize { Mon Jun 15 08:59:47 2015 : Debug: (27) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (27) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (27) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (27) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (27) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (27) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (27) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling auth_log (rlm_detail) for request 27 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (27) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (27) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (27) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (27) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (27) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from auth_log (rlm_detail) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling chap (rlm_chap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from chap (rlm_chap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling suffix (rlm_realm) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (27) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (27) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from suffix (rlm_realm) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling eap (rlm_eap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) eap : Peer sent code Response (2) ID 5 length 6 Mon Jun 15 08:59:47 2015 : Debug: (27) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from eap (rlm_eap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [eap] = updated Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling files (rlm_files) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from files (rlm_files) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [files] = noop Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling expiration (rlm_expiration) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from expiration (rlm_expiration) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [expiration] = noop Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling logintime (rlm_logintime) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from logintime (rlm_logintime) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [logintime] = noop Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: calling pap (rlm_pap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authorize]: returned from pap (rlm_pap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [pap] = noop Mon Jun 15 08:59:47 2015 : Debug: (27) } # authorize = updated Mon Jun 15 08:59:47 2015 : Debug: (27) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (27) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (27) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authenticate]: calling eap (rlm_eap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) eap : Expiring EAP session with state 0x4db356524fb65b14 Mon Jun 15 08:59:47 2015 : Debug: (27) eap : Finished EAP session with state 0x4db356524fb65b14 Mon Jun 15 08:59:47 2015 : Debug: (27) eap : Previous EAP request found for state 0x4db356524fb65b14, released from the list Mon Jun 15 08:59:47 2015 : Debug: (27) eap : Peer sent method TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (27) eap : EAP TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (27) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (27) eap_tls : Authenticate Mon Jun 15 08:59:47 2015 : Debug: (27) eap_tls : processing EAP-TLS Mon Jun 15 08:59:47 2015 : Debug: (27) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (27) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (27) eap_tls : ACK handshake fragment handler Mon Jun 15 08:59:47 2015 : Debug: (27) eap_tls : eaptls_verify returned 1 Mon Jun 15 08:59:47 2015 : Debug: (27) eap_tls : eaptls_process returned 13 Mon Jun 15 08:59:47 2015 : Debug: (27) eap : New EAP session, adding 'State' attribute to reply 0x4db356524eb55b14 Mon Jun 15 08:59:47 2015 : Debug: (27) modsingle[authenticate]: returned from eap (rlm_eap) for request 27 Mon Jun 15 08:59:47 2015 : Debug: (27) [eap] = handled Mon Jun 15 08:59:47 2015 : Debug: (27) } # authenticate = handled Mon Jun 15 08:59:47 2015 : Debug: (27) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=214, length=0 Mon Jun 15 08:59:47 2015 : Debug: (27) EAP-Message = 0x010604000dc000000e590a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f74434130820222300d06092a864886f70d01010105000382020f003082020a0282020100be2fa5e0f143a4dc9eeab356d09c655afab7ab4b943a8ad2628a295209553063875750d90e3296deab425182385389a75061b22501b90a6329d20cc61fbf4efb3f05f93674a912b346503e9e74038f76185a48de7fdad6a2f8d61c742597e059404548193895754e9991a450f0e5b0aceca5c3e17e86a126f4bc5789b256925ecd65cb14d797caa107b6854d29ef1f6aebd773f9ea0ca2c82244f0c7365faa212c87403e6019c4a5455726e4f05d058ab2ab7b962052e00b6b8c2fed642733598595aadcd44219e52df35f4b49e14fef61e32f04311d87a5bcea2d3e67be930b497ca4995350a226b09ef76481b8fa5b439d96624356013c5309d14b79d0a7ca3a4424a12ddcfcab088155237e2d21f2c029e9416fc57c0fe25d47e0a8e28228c5877b28e5d947d5e26a12eb31e1eb758478bef96e9d960b0eabd3eeffee50eb59db04b8ac9a8e08cac7c2b65db5d0180c50521797018804f6d3cce6b7ed51e3e4d138fd28f193aa4b1ba4878bed41bf4fd6c8b14f283018c0d71ea23f4c5671f6e46a526c662cfbbb3e35a2173a584f9193f604a3e5fac383bb0967 Mon Jun 15 08:59:47 2015 : Debug: (27) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (27) State = 0x4db356524eb55b14caf657079e75e95d Sending Access-Challenge Id 214 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010604000dc000000e590a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f74434130820222300d06092a864886f70d01010105000382020f003082020a0282020100be2fa5e0f143a4dc9eeab356d09c655afab7ab4b943a8ad2628a295209553063875750d90e3296deab425182385389a75061b22501b90a6329d20cc61fbf4efb3f05f93674a912b346503e9e74038f76185a48de7fdad6a2f8d61c742597e059404548193895754e9991a450f0e5b0aceca5c3e17e86a126f4bc5789b256925ecd65cb14d797caa107b6854d29ef1f6aebd773f9ea0ca2c82244f0c7365faa212c87403e6019c4a5455726e4f05d058ab2ab7b962052e00b6b8c2fed642733598595aadcd44219e52df35f4b49e14fef61e32f04311d87a5bcea2d3e67be930b497ca4995350a226b09ef76481b8fa5b439d96624356013c5309d14b79d0a7ca3a4424a12ddcfcab088155237e2d21f2c029e9416fc57c0fe25d47e0a8e28228c5877b28e5d947d5e26a12eb31e1eb758478bef96e9d960b0eabd3eeffee50eb59db04b8ac9a8e08cac7c2b65db5d0180c50521797018804f6d3cce6b7ed51e3e4d138fd28f193aa4b1ba4878bed41bf4fd6c8b14f283018c0d71ea23f4c5671f6e46a526c662cfbbb3e35a2173a584f9193f604a3e5fac383bb096 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4db356524eb55b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (27) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 215 from 192.168.104.80:32770 to 192.168.106.130:1812 length 314 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020600060d00 State = 0x4db356524eb55b14caf657079e75e95d Message-Authenticator = 0x4ed2653362fd937878001a60bf420eb8 Mon Jun 15 08:59:47 2015 : Debug: (28) Received Access-Request packet from host 192.168.104.80 port 32770, id=215, length=314 Mon Jun 15 08:59:47 2015 : Debug: (28) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (28) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (28) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (28) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (28) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (28) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (28) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (28) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (28) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (28) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (28) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (28) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (28) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (28) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (28) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (28) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (28) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (28) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (28) EAP-Message = 0x020600060d00 Mon Jun 15 08:59:47 2015 : Debug: (28) State = 0x4db356524eb55b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (28) Message-Authenticator = 0x4ed2653362fd937878001a60bf420eb8 Mon Jun 15 08:59:47 2015 : Debug: (28) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (28) authorize { Mon Jun 15 08:59:47 2015 : Debug: (28) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (28) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (28) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (28) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (28) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (28) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (28) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling auth_log (rlm_detail) for request 28 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (28) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (28) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (28) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (28) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (28) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from auth_log (rlm_detail) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling chap (rlm_chap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from chap (rlm_chap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling suffix (rlm_realm) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (28) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (28) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from suffix (rlm_realm) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling eap (rlm_eap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) eap : Peer sent code Response (2) ID 6 length 6 Mon Jun 15 08:59:47 2015 : Debug: (28) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from eap (rlm_eap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [eap] = updated Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling files (rlm_files) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from files (rlm_files) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [files] = noop Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling expiration (rlm_expiration) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from expiration (rlm_expiration) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [expiration] = noop Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling logintime (rlm_logintime) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from logintime (rlm_logintime) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [logintime] = noop Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: calling pap (rlm_pap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authorize]: returned from pap (rlm_pap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [pap] = noop Mon Jun 15 08:59:47 2015 : Debug: (28) } # authorize = updated Mon Jun 15 08:59:47 2015 : Debug: (28) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (28) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (28) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authenticate]: calling eap (rlm_eap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) eap : Expiring EAP session with state 0x4db356524eb55b14 Mon Jun 15 08:59:47 2015 : Debug: (28) eap : Finished EAP session with state 0x4db356524eb55b14 Mon Jun 15 08:59:47 2015 : Debug: (28) eap : Previous EAP request found for state 0x4db356524eb55b14, released from the list Mon Jun 15 08:59:47 2015 : Debug: (28) eap : Peer sent method TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (28) eap : EAP TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (28) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (28) eap_tls : Authenticate Mon Jun 15 08:59:47 2015 : Debug: (28) eap_tls : processing EAP-TLS Mon Jun 15 08:59:47 2015 : Debug: (28) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (28) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (28) eap_tls : ACK handshake fragment handler Mon Jun 15 08:59:47 2015 : Debug: (28) eap_tls : eaptls_verify returned 1 Mon Jun 15 08:59:47 2015 : Debug: (28) eap_tls : eaptls_process returned 13 Mon Jun 15 08:59:47 2015 : Debug: (28) eap : New EAP session, adding 'State' attribute to reply 0x4db3565249b45b14 Mon Jun 15 08:59:47 2015 : Debug: (28) modsingle[authenticate]: returned from eap (rlm_eap) for request 28 Mon Jun 15 08:59:47 2015 : Debug: (28) [eap] = handled Mon Jun 15 08:59:47 2015 : Debug: (28) } # authenticate = handled Mon Jun 15 08:59:47 2015 : Debug: (28) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=215, length=0 Mon Jun 15 08:59:47 2015 : Debug: (28) EAP-Message = 0x010702810d8000000e591ad0249cf4e25319a8dc335ecf712f7dac90797bc30de6efffff3a3bb05e4d51cb5f09b3fffad4141f55c8ae6218827bd090e50761fd16aed2c49d94fa3a5015423ca228b95e2d093b916735efd9087f493b765d69e11e4b177aa3c917cd759791e7574327df45dd0c74daab55d6cc3261738baef1b239e1f77bbcd8cadb14c4ac41f3dc8f07d89e6b4d297823fcb7be5d8d89a82239ea4ae458958cde04ebc257663a853a2d5a9276121af5190483b53e49ecf544f1eaeff183d2c60957a44ae1ca7bc101f79e160301014b0c00014703001741046681886fed6fbdfc114a37500d4460fecb78eea0ca25e47400830fcf45d5b88809b972d681fbf1ed768a948f26a6efd78dfcb9b20003acc50f6758be263c87f40100be716b04721597d468bb637ebea6d00abea54dbb79dba04a93bd11de21da0d9b248d7bd79aaba4e80ddcf55b284e6ee840b853bdf14050b584b1ba71992be204bd1b0f5831a083869cb5afbd4593a03b8f0cf3c97263f31ad4543d68375e021f5e9bfbed05f58a07b7d27290daaaf946bf8cac947e98d01c224bfd8ba04d2a00da1f884e952f0c39976b17356b126d0cc497de5f1042a63d73e4e36c8f594119bef1eb853601822e7a31fedd5b5a0e0811bad414eaf7a55272920248f09e523c1473408a5120bbd29a75a379dd2a7fb44da182a687d9 Mon Jun 15 08:59:47 2015 : Debug: (28) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (28) State = 0x4db3565249b45b14caf657079e75e95d Sending Access-Challenge Id 215 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010702810d8000000e591ad0249cf4e25319a8dc335ecf712f7dac90797bc30de6efffff3a3bb05e4d51cb5f09b3fffad4141f55c8ae6218827bd090e50761fd16aed2c49d94fa3a5015423ca228b95e2d093b916735efd9087f493b765d69e11e4b177aa3c917cd759791e7574327df45dd0c74daab55d6cc3261738baef1b239e1f77bbcd8cadb14c4ac41f3dc8f07d89e6b4d297823fcb7be5d8d89a82239ea4ae458958cde04ebc257663a853a2d5a9276121af5190483b53e49ecf544f1eaeff183d2c60957a44ae1ca7bc101f79e160301014b0c00014703001741046681886fed6fbdfc114a37500d4460fecb78eea0ca25e47400830fcf45d5b88809b972d681fbf1ed768a948f26a6efd78dfcb9b20003acc50f6758be263c87f40100be716b04721597d468bb637ebea6d00abea54dbb79dba04a93bd11de21da0d9b248d7bd79aaba4e80ddcf55b284e6ee840b853bdf14050b584b1ba71992be204bd1b0f5831a083869cb5afbd4593a03b8f0cf3c97263f31ad4543d68375e021f5e9bfbed05f58a07b7d27290daaaf946bf8cac947e98d01c224bfd8ba04d2a00da1f884e952f0c39976b17356b126d0cc497de5f1042a63d73e4e36c8f594119bef1eb853601822e7a31fedd5b5a0e0811bad414eaf7a55272920248f09e523c1473408a5120bbd29a75a379dd2a7fb44da182a687d Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4db3565249b45b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (28) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 216 from 192.168.104.80:32770 to 192.168.106.130:1812 length 1810 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020705d40dc00000082716030107e70b0006970006940006913082068d30820475a003020102021374000000528ce96f685e3bd5b2000000000052300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532343132343035395a170d3136303532333132343035395a301f311d301b060355040313144b414c4a4f2d4c542e70616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100c92346d9e0dd249f908cbffd877a1b4d87556a6bcf4395be9f949aa889e2fccd58003fc1289dd2f05afb880d58ad2ba160f47cb1f9121b973a0a843939e9c236277c2beeb138b8676ff8f0f923231e91bb0a70690342767fd8b47f605747b201274d3ffc8ae7f7387028d74ee29edc071f7ce5a7fbfc44845419aa92c6bf06979d7757b09fae99458416afea9121f7d456a127f4eba897379526df960544a011d31fc5cef56de8c45ab4b03505d82913b159d5d5feadf23f2d4bd3770c92a51e4c07f8430f8cfeddaa0ad7b446d3a68377ad76ee4ac6f2dc454808649fbbded2b8a6ec2b9e54315c3c8b75e59d9266c8102bf965bcb1679bc7ac75660c2e87c State = 0x4db3565249b45b14caf657079e75e95d Message-Authenticator = 0xbd51bc7a47de4f31b182863c7ba8bb91 Mon Jun 15 08:59:47 2015 : Debug: (29) Received Access-Request packet from host 192.168.104.80 port 32770, id=216, length=1810 Mon Jun 15 08:59:47 2015 : Debug: (29) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (29) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (29) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (29) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (29) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (29) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (29) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (29) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (29) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (29) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (29) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (29) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (29) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (29) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (29) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (29) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (29) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (29) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (29) EAP-Message = 0x020705d40dc00000082716030107e70b0006970006940006913082068d30820475a003020102021374000000528ce96f685e3bd5b2000000000052300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532343132343035395a170d3136303532333132343035395a301f311d301b060355040313144b414c4a4f2d4c542e70616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100c92346d9e0dd249f908cbffd877a1b4d87556a6bcf4395be9f949aa889e2fccd58003fc1289dd2f05afb880d58ad2ba160f47cb1f9121b973a0a843939e9c236277c2beeb138b8676ff8f0f923231e91bb0a70690342767fd8b47f605747b201274d3ffc8ae7f7387028d74ee29edc071f7ce5a7fbfc44845419aa92c6bf06979d7757b09fae99458416afea9121f7d456a127f4eba897379526df960544a011d31fc5cef56de8c45ab4b03505d82913b159d5d5feadf23f2d4bd3770c92a51e4c07f8430f8cfeddaa0ad7b446d3a68377ad76ee4ac6f2dc454808649fbbded2b8a6ec2b9e54315c3c8b75e59d9266c8102bf965bcb1679bc7ac75660c2e87cd Mon Jun 15 08:59:47 2015 : Debug: (29) State = 0x4db3565249b45b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (29) Message-Authenticator = 0xbd51bc7a47de4f31b182863c7ba8bb91 Mon Jun 15 08:59:47 2015 : Debug: (29) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (29) authorize { Mon Jun 15 08:59:47 2015 : Debug: (29) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (29) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (29) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (29) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (29) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (29) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (29) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling auth_log (rlm_detail) for request 29 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (29) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (29) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (29) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (29) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (29) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from auth_log (rlm_detail) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling chap (rlm_chap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from chap (rlm_chap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling suffix (rlm_realm) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (29) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (29) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from suffix (rlm_realm) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling eap (rlm_eap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) eap : Peer sent code Response (2) ID 7 length 1492 Mon Jun 15 08:59:47 2015 : Debug: (29) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from eap (rlm_eap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [eap] = updated Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling files (rlm_files) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from files (rlm_files) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [files] = noop Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling expiration (rlm_expiration) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from expiration (rlm_expiration) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [expiration] = noop Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling logintime (rlm_logintime) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from logintime (rlm_logintime) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [logintime] = noop Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: calling pap (rlm_pap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authorize]: returned from pap (rlm_pap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [pap] = noop Mon Jun 15 08:59:47 2015 : Debug: (29) } # authorize = updated Mon Jun 15 08:59:47 2015 : Debug: (29) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (29) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (29) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authenticate]: calling eap (rlm_eap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) eap : Expiring EAP session with state 0x4db3565249b45b14 Mon Jun 15 08:59:47 2015 : Debug: (29) eap : Finished EAP session with state 0x4db3565249b45b14 Mon Jun 15 08:59:47 2015 : Debug: (29) eap : Previous EAP request found for state 0x4db3565249b45b14, released from the list Mon Jun 15 08:59:47 2015 : Debug: (29) eap : Peer sent method TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (29) eap : EAP TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (29) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (29) eap_tls : Authenticate Mon Jun 15 08:59:47 2015 : Debug: (29) eap_tls : processing EAP-TLS Mon Jun 15 08:59:47 2015 : Debug: TLS Length 2087 Mon Jun 15 08:59:47 2015 : Debug: (29) eap_tls : Received EAP-TLS First Fragment of the message Mon Jun 15 08:59:47 2015 : Debug: (29) eap_tls : eaptls_verify returned 9 Mon Jun 15 08:59:47 2015 : Debug: (29) eap_tls : eaptls_process returned 13 Mon Jun 15 08:59:47 2015 : Debug: (29) eap : New EAP session, adding 'State' attribute to reply 0x4db3565248bb5b14 Mon Jun 15 08:59:47 2015 : Debug: (29) modsingle[authenticate]: returned from eap (rlm_eap) for request 29 Mon Jun 15 08:59:47 2015 : Debug: (29) [eap] = handled Mon Jun 15 08:59:47 2015 : Debug: (29) } # authenticate = handled Mon Jun 15 08:59:47 2015 : Debug: (29) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=216, length=0 Mon Jun 15 08:59:47 2015 : Debug: (29) EAP-Message = 0x010800060d00 Mon Jun 15 08:59:47 2015 : Debug: (29) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (29) State = 0x4db3565248bb5b14caf657079e75e95d Sending Access-Challenge Id 216 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010800060d00 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4db3565248bb5b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (29) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 217 from 192.168.104.80:32770 to 192.168.106.130:1812 length 923 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020802630d00fe607eb5a7e8ccac163a23d897db9fae64f37a203141a3f9ef158b6be5b7b008eb1f681313fd71561250d00fc583e5855be1687ed8dd809290b5ba8941b1261b5762e1fc5f74ea44330ddfe677480cd84ce98cb38ed18ecf75afd7339756508087210f9d15e5841f515273177fe8f8b6744dfef08426a7d147192a6c039801b31822627f2387322008acd8ce659574635479474a60557180e349d8635a320247806c83f6135430f1a6314da4fdbfe912b841e5b36a1e441fe5c8bb37952a72411d2f0879fedbb9ea9e3c68f20ef21f24577125dcbfb71000004241042a761e007936117c6a64c9bc8c5f7d6543718e04c04f68a1462e0ea1d3d63099cd8c8bc0cca7d5a060f92062c7d1ec5a221c3e4879a1cc349fa1468ad983fd810f00010201001107560a1d8748cb11669d5509830b83af653d80de8419dff0acc83018d73d80655f7d769350e57253925de8dd2a85c2b85b1f3c567a8180a3c1b9b7edd03066b89b14ee8c640c04332846514dd729a2fe837772b45888e43cc8c70ffe79d7b4a89afa66f6e78fb5c2372aa1b63db540235873b9ad496faa982161b45406a13381597e515c05feeff916041a6f9ac888e18f06cd4e210f1b087a61e4c767f7a37cf5a09a533c5d0b713fc8b8c49fd49adf7446359124ae1caba662ea4c5be89fe57b8fae7fe54d138b6f50ad4f9c8 State = 0x4db3565248bb5b14caf657079e75e95d Message-Authenticator = 0x441ec2515c737df2489f85c845b13b3b Mon Jun 15 08:59:47 2015 : Debug: (30) Received Access-Request packet from host 192.168.104.80 port 32770, id=217, length=923 Mon Jun 15 08:59:47 2015 : Debug: (30) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (30) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (30) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (30) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (30) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (30) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (30) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (30) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (30) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (30) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (30) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (30) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (30) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (30) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (30) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (30) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (30) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (30) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (30) EAP-Message = 0x020802630d00fe607eb5a7e8ccac163a23d897db9fae64f37a203141a3f9ef158b6be5b7b008eb1f681313fd71561250d00fc583e5855be1687ed8dd809290b5ba8941b1261b5762e1fc5f74ea44330ddfe677480cd84ce98cb38ed18ecf75afd7339756508087210f9d15e5841f515273177fe8f8b6744dfef08426a7d147192a6c039801b31822627f2387322008acd8ce659574635479474a60557180e349d8635a320247806c83f6135430f1a6314da4fdbfe912b841e5b36a1e441fe5c8bb37952a72411d2f0879fedbb9ea9e3c68f20ef21f24577125dcbfb71000004241042a761e007936117c6a64c9bc8c5f7d6543718e04c04f68a1462e0ea1d3d63099cd8c8bc0cca7d5a060f92062c7d1ec5a221c3e4879a1cc349fa1468ad983fd810f00010201001107560a1d8748cb11669d5509830b83af653d80de8419dff0acc83018d73d80655f7d769350e57253925de8dd2a85c2b85b1f3c567a8180a3c1b9b7edd03066b89b14ee8c640c04332846514dd729a2fe837772b45888e43cc8c70ffe79d7b4a89afa66f6e78fb5c2372aa1b63db540235873b9ad496faa982161b45406a13381597e515c05feeff916041a6f9ac888e18f06cd4e210f1b087a61e4c767f7a37cf5a09a533c5d0b713fc8b8c49fd49adf7446359124ae1caba662ea4c5be89fe57b8fae7fe54d138b6f50ad4f9c8f Mon Jun 15 08:59:47 2015 : Debug: (30) State = 0x4db3565248bb5b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (30) Message-Authenticator = 0x441ec2515c737df2489f85c845b13b3b Mon Jun 15 08:59:47 2015 : Debug: (30) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (30) authorize { Mon Jun 15 08:59:47 2015 : Debug: (30) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (30) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (30) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (30) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (30) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (30) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (30) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling auth_log (rlm_detail) for request 30 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (30) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (30) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (30) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (30) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (30) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from auth_log (rlm_detail) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling chap (rlm_chap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from chap (rlm_chap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling suffix (rlm_realm) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (30) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (30) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from suffix (rlm_realm) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling eap (rlm_eap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) eap : Peer sent code Response (2) ID 8 length 611 Mon Jun 15 08:59:47 2015 : Debug: (30) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from eap (rlm_eap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [eap] = updated Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling files (rlm_files) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from files (rlm_files) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [files] = noop Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling expiration (rlm_expiration) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from expiration (rlm_expiration) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [expiration] = noop Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling logintime (rlm_logintime) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from logintime (rlm_logintime) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [logintime] = noop Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: calling pap (rlm_pap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authorize]: returned from pap (rlm_pap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [pap] = noop Mon Jun 15 08:59:47 2015 : Debug: (30) } # authorize = updated Mon Jun 15 08:59:47 2015 : Debug: (30) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (30) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (30) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authenticate]: calling eap (rlm_eap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) eap : Expiring EAP session with state 0x4db3565248bb5b14 Mon Jun 15 08:59:47 2015 : Debug: (30) eap : Finished EAP session with state 0x4db3565248bb5b14 Mon Jun 15 08:59:47 2015 : Debug: (30) eap : Previous EAP request found for state 0x4db3565248bb5b14, released from the list Mon Jun 15 08:59:47 2015 : Debug: (30) eap : Peer sent method TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (30) eap : EAP TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (30) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : Authenticate Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : processing EAP-TLS Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : eaptls_verify returned 7 Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : Done initial handshake Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : <<< TLS 1.0 Handshake [length 069b], Certificate Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : chain-depth=1, Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : error=0 Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> User-Name = host/user_host.private.com Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> BUF-Name = RootCA Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> subject = /DC=com/DC=private/CN=RootCA Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> issuer = /DC=com/DC=private/CN=RootCA Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> verify return:1 Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : chain-depth=0, Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : error=0 Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> User-Name = host/user_host.private.com Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> BUF-Name = user_host.private.com Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> subject = /CN=user_host.private.com Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> issuer = /DC=com/DC=private/CN=RootCA Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : --> verify return:1 Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : TLS_accept: SSLv3 read client certificate A Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : TLS_accept: SSLv3 read client key exchange A Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : <<< TLS 1.0 Handshake [length 0106], CertificateVerify Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : TLS_accept: SSLv3 read certificate verify A Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : <<< TLS 1.0 ChangeCipherSpec [length 0001] Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : <<< TLS 1.0 Handshake [length 0010], Finished Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : TLS_accept: SSLv3 read finished A Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : >>> TLS 1.0 ChangeCipherSpec [length 0001] Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : TLS_accept: SSLv3 write change cipher spec A Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : >>> TLS 1.0 Handshake [length 0010], Finished Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : TLS_accept: SSLv3 write finished A Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : TLS_accept: SSLv3 flush data Mon Jun 15 08:59:47 2015 : Debug: SSL: adding session 898ec6938e09dcb3a158c6386fdf3ef3c891156ac05960b9be6be1692600a937 to cache Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : (other): SSL negotiation finished successfully Mon Jun 15 08:59:47 2015 : Debug: SSL Connection Established Mon Jun 15 08:59:47 2015 : Debug: (30) eap_tls : eaptls_process returned 13 Mon Jun 15 08:59:47 2015 : Debug: (30) eap : New EAP session, adding 'State' attribute to reply 0x4db356524bba5b14 Mon Jun 15 08:59:47 2015 : Debug: (30) modsingle[authenticate]: returned from eap (rlm_eap) for request 30 Mon Jun 15 08:59:47 2015 : Debug: (30) [eap] = handled Mon Jun 15 08:59:47 2015 : Debug: (30) } # authenticate = handled Mon Jun 15 08:59:47 2015 : Debug: (30) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=217, length=0 Mon Jun 15 08:59:47 2015 : Debug: (30) EAP-Message = 0x010900450d800000003b1403010001011603010030736091ec457ded02abe812f2e754195b67d92349521d9d9123355b1ff3a8bf042402fb9fdf91dead2b829d73cd75abe0 Mon Jun 15 08:59:47 2015 : Debug: (30) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (30) State = 0x4db356524bba5b14caf657079e75e95d Sending Access-Challenge Id 217 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010900450d800000003b1403010001011603010030736091ec457ded02abe812f2e754195b67d92349521d9d9123355b1ff3a8bf042402fb9fdf91dead2b829d73cd75abe0 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x4db356524bba5b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (30) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 218 from 192.168.104.80:32770 to 192.168.106.130:1812 length 314 User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020900060d00 State = 0x4db356524bba5b14caf657079e75e95d Message-Authenticator = 0xf53737e3fe69b578ce32a2f53de4744a Mon Jun 15 08:59:47 2015 : Debug: (31) Received Access-Request packet from host 192.168.104.80 port 32770, id=218, length=314 Mon Jun 15 08:59:47 2015 : Debug: (31) User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (31) Chargeable-User-Identity = 0x00 Mon Jun 15 08:59:47 2015 : Debug: (31) Location-Capable = Civix-Location Mon Jun 15 08:59:47 2015 : Debug: (31) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:59:47 2015 : Debug: (31) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:59:47 2015 : Debug: (31) NAS-Port = 2 Mon Jun 15 08:59:47 2015 : Debug: (31) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:59:47 2015 : Debug: (31) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:59:47 2015 : Debug: (31) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:59:47 2015 : Debug: (31) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:59:47 2015 : Debug: (31) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:59:47 2015 : Debug: (31) Airespace-Wlan-Id = 2 Mon Jun 15 08:59:47 2015 : Debug: (31) Service-Type = Framed-User Mon Jun 15 08:59:47 2015 : Debug: (31) Framed-MTU = 1300 Mon Jun 15 08:59:47 2015 : Debug: (31) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:59:47 2015 : Debug: (31) Tunnel-Type:0 = VLAN Mon Jun 15 08:59:47 2015 : Debug: (31) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:59:47 2015 : Debug: (31) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:59:47 2015 : Debug: (31) EAP-Message = 0x020900060d00 Mon Jun 15 08:59:47 2015 : Debug: (31) State = 0x4db356524bba5b14caf657079e75e95d Mon Jun 15 08:59:47 2015 : Debug: (31) Message-Authenticator = 0xf53737e3fe69b578ce32a2f53de4744a Mon Jun 15 08:59:47 2015 : Debug: (31) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (31) authorize { Mon Jun 15 08:59:47 2015 : Debug: (31) filter_username filter_username { Mon Jun 15 08:59:47 2015 : Debug: (31) if (!&User-Name) Mon Jun 15 08:59:47 2015 : Debug: (31) if (!&User-Name) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ / /) Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:59:47 2015 : Debug: (31) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /\\.$/) Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /@\\./) Mon Jun 15 08:59:47 2015 : Debug: (31) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) } # filter_username filter_username = notfound Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [preprocess] = ok Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling auth_log (rlm_detail) for request 31 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (31) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from auth_log (rlm_detail) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling chap (rlm_chap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from chap (rlm_chap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [chap] = noop Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling suffix (rlm_realm) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) suffix : Checking for suffix after "@" Mon Jun 15 08:59:47 2015 : Debug: (31) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:59:47 2015 : Debug: (31) suffix : No such realm "NULL" Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from suffix (rlm_realm) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [suffix] = noop Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling eap (rlm_eap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) eap : Peer sent code Response (2) ID 9 length 6 Mon Jun 15 08:59:47 2015 : Debug: (31) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from eap (rlm_eap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [eap] = updated Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling files (rlm_files) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from files (rlm_files) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [files] = noop Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling expiration (rlm_expiration) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from expiration (rlm_expiration) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [expiration] = noop Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling logintime (rlm_logintime) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from logintime (rlm_logintime) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [logintime] = noop Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling pap (rlm_pap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from pap (rlm_pap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [pap] = noop Mon Jun 15 08:59:47 2015 : Debug: (31) } # authorize = updated Mon Jun 15 08:59:47 2015 : Debug: (31) Found Auth-Type = EAP Mon Jun 15 08:59:47 2015 : Debug: (31) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (31) authenticate { Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authenticate]: calling eap (rlm_eap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) eap : Expiring EAP session with state 0x4db356524bba5b14 Mon Jun 15 08:59:47 2015 : Debug: (31) eap : Finished EAP session with state 0x4db356524bba5b14 Mon Jun 15 08:59:47 2015 : Debug: (31) eap : Previous EAP request found for state 0x4db356524bba5b14, released from the list Mon Jun 15 08:59:47 2015 : Debug: (31) eap : Peer sent method TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (31) eap : EAP TLS (13) Mon Jun 15 08:59:47 2015 : Debug: (31) eap : Calling eap_tls to process EAP data Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : Authenticate Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : processing EAP-TLS Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : Received TLS ACK Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : ACK handshake is finished Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : eaptls_verify returned 3 Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : eaptls_process returned 3 Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : Processing EAP-TLS Certificate check: Mon Jun 15 08:59:47 2015 : Debug: (31) server check-eap-tls { Mon Jun 15 08:59:47 2015 : Debug: (31) Request: User-Name = 'host/user_host.private.com' Chargeable-User-Identity = 0x00 Location-Capable = Civix-Location Calling-Station-Id = '00-24-d7-03-2b-38' Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' NAS-Port = 2 Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Cisco-AVPair = 'mDNS=true' NAS-IP-Address = 192.168.104.80 NAS-Identifier = 'wc-s1-01' Airespace-Wlan-Id = 2 Service-Type = Framed-User Framed-MTU = 1300 NAS-Port-Type = Wireless-802.11 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = '101' EAP-Message = 0x020900060d00 State = 0x4db356524bba5b14caf657079e75e95d Message-Authenticator = 0xf53737e3fe69b578ce32a2f53de4744a Event-Timestamp = 'Jun 15 2015 08:59:47 EEST' EAP-Type = TLS TLS-Cert-Serial := '497342570ec0c19f459efdaf66ca76cb' TLS-Cert-Expiration := '230901102449Z' TLS-Cert-Subject := '/DC=com/DC=private/CN=RootCA' TLS-Cert-Issuer := '/DC=com/DC=private/CN=RootCA' TLS-Cert-Common-Name := 'RootCA' TLS-Client-Cert-Serial := '74000000528ce96f685e3bd5b2000000000052' TLS-Client-Cert-Expiration := '160523124059Z' TLS-Client-Cert-Subject := '/CN=user_host.private.com' TLS-Client-Cert-Issuer := '/DC=com/DC=private/CN=RootCA' TLS-Client-Cert-Common-Name := 'user_host.private.com' TLS-Client-Cert-Subject-Alt-Name-Dns := 'user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (31) # Executing section authorize from file /etc/raddb/sites-enabled/check-eap-tls Mon Jun 15 08:59:47 2015 : Debug: (31) authorize { Mon Jun 15 08:59:47 2015 : Debug: (31) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@private\.com$/i) Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Upn} Mon Jun 15 08:59:47 2015 : Debug: (31) --> Mon Jun 15 08:59:47 2015 : Debug: (31) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@private\.com$/i) -> FALSE Mon Jun 15 08:59:47 2015 : Debug: (31) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Dns} Mon Jun 15 08:59:47 2015 : Debug: (31) --> user_host.private.com Mon Jun 15 08:59:47 2015 : Debug: (31) %{0}: Inserting new value "user_host.private.com" Mon Jun 15 08:59:47 2015 : Debug: (31) %{1}: Inserting new value "" Mon Jun 15 08:59:47 2015 : Debug: (31) %{2}: Was empty Mon Jun 15 08:59:47 2015 : Debug: (31) %{3}: Was empty Mon Jun 15 08:59:47 2015 : Debug: (31) %{4}: Was empty Mon Jun 15 08:59:47 2015 : Debug: (31) %{5}: Was empty Mon Jun 15 08:59:47 2015 : Debug: (31) %{6}: Was empty Mon Jun 15 08:59:47 2015 : Debug: (31) %{7}: Was empty Mon Jun 15 08:59:47 2015 : Debug: (31) %{8}: Was empty Mon Jun 15 08:59:47 2015 : Debug: (31) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) -> TRUE Mon Jun 15 08:59:47 2015 : Debug: (31) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) { Mon Jun 15 08:59:47 2015 : Debug: (31) update config { Mon Jun 15 08:59:47 2015 : Debug: (31) Auth-Type := Accept Mon Jun 15 08:59:47 2015 : Debug: (31) } # update config = noop Mon Jun 15 08:59:47 2015 : Debug: (31) } # elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) = noop Mon Jun 15 08:59:47 2015 : Debug: (31) ... skipping else for request 31: Preceding "if" was taken Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: calling auth_log (rlm_detail) for request 31 Mon Jun 15 08:59:47 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:59:47 2015 : Debug: if { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: else { Mon Jun 15 08:59:47 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:59:47 2015 : Debug: } Mon Jun 15 08:59:47 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:59:47 2015 : Debug: percent --> Y Mon Jun 15 08:59:47 2015 : Debug: percent --> m Mon Jun 15 08:59:47 2015 : Debug: percent --> d Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:59:47 2015 : Debug: (31) 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-20150615 Mon Jun 15 08:59:47 2015 : Debug: %t Mon Jun 15 08:59:47 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:59:47 2015 : Debug: percent --> t Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : EXPAND %t Mon Jun 15 08:59:47 2015 : Debug: (31) auth_log : --> Mon Jun 15 08:59:47 2015 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authorize]: returned from auth_log (rlm_detail) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [auth_log] = ok Mon Jun 15 08:59:47 2015 : Debug: (31) } # authorize = ok Mon Jun 15 08:59:47 2015 : Debug: (31) Found Auth-Type = Accept Mon Jun 15 08:59:47 2015 : Debug: (31) Auth-Type = Accept, accepting the user Mon Jun 15 08:59:47 2015 : Auth: (31) Login OK: [host/user_host.private.com] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38 via TLS tunnel) Mon Jun 15 08:59:47 2015 : Debug: (31) Empty post-auth section. Using default return values. Mon Jun 15 08:59:47 2015 : Debug: (31) Reply: Mon Jun 15 08:59:47 2015 : Debug: (31) } # server check-eap-tls Mon Jun 15 08:59:47 2015 : Debug: (31) eap_tls : Saving session 898ec6938e09dcb3a158c6386fdf3ef3c891156ac05960b9be6be1692600a937 vps 0x7fcd179668c0 in the cache Mon Jun 15 08:59:47 2015 : Debug: (31) eap : Freeing handler Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[authenticate]: returned from eap (rlm_eap) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [eap] = ok Mon Jun 15 08:59:47 2015 : Debug: (31) } # authenticate = ok Mon Jun 15 08:59:47 2015 : Auth: (31) Login OK: [host/user_host.private.com] (from client wc-s1-01 port 2 cli 00-24-d7-03-2b-38) Mon Jun 15 08:59:47 2015 : Debug: (31) # Executing section post-auth from file /etc/raddb/sites-enabled/default Mon Jun 15 08:59:47 2015 : Debug: (31) post-auth { Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[post-auth]: calling exec (rlm_exec) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) modsingle[post-auth]: returned from exec (rlm_exec) for request 31 Mon Jun 15 08:59:47 2015 : Debug: (31) [exec] = noop Mon Jun 15 08:59:47 2015 : Debug: (31) update reply { Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Cert-Serial} Mon Jun 15 08:59:47 2015 : Debug: (31) --> 497342570ec0c19f459efdaf66ca76cb Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "497342570ec0c19f459efdaf66ca76cb" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Cert-Expiration} Mon Jun 15 08:59:47 2015 : Debug: (31) --> 230901102449Z Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "230901102449Z" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Cert-Subject} Mon Jun 15 08:59:47 2015 : Debug: (31) --> /DC=com/DC=private/CN=RootCA Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "/DC=com/DC=private/CN=RootCA" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Cert-Issuer} Mon Jun 15 08:59:47 2015 : Debug: (31) --> /DC=com/DC=private/CN=RootCA Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "/DC=com/DC=private/CN=RootCA" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Cert-Common-Name} Mon Jun 15 08:59:47 2015 : Debug: (31) --> RootCA Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "RootCA" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Cert-Subject-Alt-Name-Email} Mon Jun 15 08:59:47 2015 : Debug: (31) --> Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Serial} Mon Jun 15 08:59:47 2015 : Debug: (31) --> 74000000528ce96f685e3bd5b2000000000052 Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "74000000528ce96f685e3bd5b2000000000052" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Expiration} Mon Jun 15 08:59:47 2015 : Debug: (31) --> 160523124059Z Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "160523124059Z" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Subject} Mon Jun 15 08:59:47 2015 : Debug: (31) --> /CN=user_host.private.com Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "/CN=user_host.private.com" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Issuer} Mon Jun 15 08:59:47 2015 : Debug: (31) --> /DC=com/DC=private/CN=RootCA Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "/DC=com/DC=private/CN=RootCA" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Common-Name} Mon Jun 15 08:59:47 2015 : Debug: (31) --> user_host.private.com Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "user_host.private.com" Mon Jun 15 08:59:47 2015 : Debug: (31) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Email} Mon Jun 15 08:59:47 2015 : Debug: (31) --> Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message += "" Mon Jun 15 08:59:47 2015 : Debug: (31) } # update reply = noop Mon Jun 15 08:59:47 2015 : Debug: (31) remove_reply_message_if_eap remove_reply_message_if_eap { Mon Jun 15 08:59:47 2015 : Debug: (31) if (&reply:EAP-Message && &reply:Reply-Message) Mon Jun 15 08:59:47 2015 : Debug: (31) if (&reply:EAP-Message && &reply:Reply-Message) -> TRUE Mon Jun 15 08:59:47 2015 : Debug: (31) if (&reply:EAP-Message && &reply:Reply-Message) { Mon Jun 15 08:59:47 2015 : Debug: (31) update reply { Mon Jun 15 08:59:47 2015 : Debug: (31) Reply-Message !* ANY Mon Jun 15 08:59:47 2015 : Debug: (31) } # update reply = noop Mon Jun 15 08:59:47 2015 : Debug: (31) } # if (&reply:EAP-Message && &reply:Reply-Message) = noop Mon Jun 15 08:59:47 2015 : Debug: (31) ... skipping else for request 31: Preceding "if" was taken Mon Jun 15 08:59:47 2015 : Debug: (31) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop Mon Jun 15 08:59:47 2015 : Debug: (31) } # post-auth = noop Mon Jun 15 08:59:47 2015 : Debug: (31) Sending Access-Accept packet to host 192.168.104.80 port 32770, id=218, length=0 Mon Jun 15 08:59:47 2015 : Debug: (31) MS-MPPE-Recv-Key = 0x35ad1911f3ee2c20356f8dc42147a3ba9f17f4a1cddff1e7577bf29bc5e6444f Mon Jun 15 08:59:47 2015 : Debug: (31) MS-MPPE-Send-Key = 0x0e6cf70c3f1cd56a5d92453bd842ce91115c6754241f1c4652fb2e66e8f70d1b Mon Jun 15 08:59:47 2015 : Debug: (31) EAP-MSK = 0x35ad1911f3ee2c20356f8dc42147a3ba9f17f4a1cddff1e7577bf29bc5e6444f0e6cf70c3f1cd56a5d92453bd842ce91115c6754241f1c4652fb2e66e8f70d1b Mon Jun 15 08:59:47 2015 : Debug: (31) EAP-EMSK = 0x1d40c60b14f2e8da8ae1104b3815afe3dc1e180b926eca938815213558c59cb804b0f8223b9165e30196bc99dfb090f75aa83896db05720ea68a4d46b72be5d5 Mon Jun 15 08:59:47 2015 : Debug: (31) EAP-Session-Id = 0x0d557e69d3b30ecf962fa7180a413aee2df562d140a4f9caf2aa5d457669a82581557e69d3a8e918720d241d37dbaa6cf0c55ab708732442249f1386d698c50063 Mon Jun 15 08:59:47 2015 : Debug: (31) EAP-Message = 0x03090004 Mon Jun 15 08:59:47 2015 : Debug: (31) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:59:47 2015 : Debug: (31) User-Name = 'host/user_host.private.com' Sending Access-Accept Id 218 from 192.168.106.130:1812 to 192.168.104.80:32770 MS-MPPE-Recv-Key = 0x35ad1911f3ee2c20356f8dc42147a3ba9f17f4a1cddff1e7577bf29bc5e6444f MS-MPPE-Send-Key = 0x0e6cf70c3f1cd56a5d92453bd842ce91115c6754241f1c4652fb2e66e8f70d1b EAP-Message = 0x03090004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = 'host/user_host.private.com' Mon Jun 15 08:59:47 2015 : Debug: (31) Finished request Mon Jun 15 08:59:47 2015 : Debug: Waking up in 0.6 seconds. Mon Jun 15 08:59:48 2015 : Debug: Waking up in 4.2 seconds. Mon Jun 15 08:59:52 2015 : Debug: (24) Cleaning up request packet ID 211 with timestamp +3338 Mon Jun 15 08:59:52 2015 : Debug: (25) Cleaning up request packet ID 212 with timestamp +3338 Mon Jun 15 08:59:52 2015 : Debug: (26) Cleaning up request packet ID 213 with timestamp +3338 Mon Jun 15 08:59:52 2015 : Debug: (27) Cleaning up request packet ID 214 with timestamp +3338 Mon Jun 15 08:59:52 2015 : Debug: (28) Cleaning up request packet ID 215 with timestamp +3338 Mon Jun 15 08:59:52 2015 : Debug: (29) Cleaning up request packet ID 216 with timestamp +3338 Mon Jun 15 08:59:52 2015 : Debug: (30) Cleaning up request packet ID 217 with timestamp +3338 Mon Jun 15 08:59:52 2015 : Debug: (31) Cleaning up request packet ID 218 with timestamp +3338