Received Access-Request Id 200 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 = 0x20100a8348f47675feb75119295383bb Mon Jun 15 08:29:23 2015 : Debug: (8) Received Access-Request packet from host 192.168.104.80 port 32770, id=200, length=320 Mon Jun 15 08:29:23 2015 : Debug: (8) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (8) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (8) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (8) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (8) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (8) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (8) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (8) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (8) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (8) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (8) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (8) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (8) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (8) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (8) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (8) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (8) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (8) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (8) EAP-Message = 0x0201001e01686f73742f4b414c4a4f2d4c542e70616c6d6174696e2e6565 Mon Jun 15 08:29:23 2015 : Debug: (8) Message-Authenticator = 0x20100a8348f47675feb75119295383bb Mon Jun 15 08:29:23 2015 : Debug: (8) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (8) authorize { Mon Jun 15 08:29:23 2015 : Debug: (8) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (8) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (8) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (8) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (8) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: calling auth_log (rlm_detail) for request 8 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (8) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (8) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (8) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (8) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (8) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: returned from auth_log (rlm_detail) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: calling chap (rlm_chap) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: returned from chap (rlm_chap) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: calling suffix (rlm_realm) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (8) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (8) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: returned from suffix (rlm_realm) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: calling eap (rlm_eap) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) eap : Peer sent code Response (2) ID 1 length 30 Mon Jun 15 08:29:23 2015 : Debug: (8) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authorize]: returned from eap (rlm_eap) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) [eap] = ok Mon Jun 15 08:29:23 2015 : Debug: (8) } # authorize = ok Mon Jun 15 08:29:23 2015 : Debug: (8) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (8) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (8) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authenticate]: calling eap (rlm_eap) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) eap : Peer sent method Identity (1) Mon Jun 15 08:29:23 2015 : Debug: (8) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (8) eap_tls : Flushing SSL sessions (of #0) Mon Jun 15 08:29:23 2015 : Debug: (8) eap_tls : Requiring client certificate Mon Jun 15 08:29:23 2015 : Debug: (8) eap_tls : Initiate Mon Jun 15 08:29:23 2015 : Debug: (8) eap_tls : Requiring client certificate Mon Jun 15 08:29:23 2015 : Debug: (8) eap_tls : Start returned 1 Mon Jun 15 08:29:23 2015 : Debug: (8) eap : New EAP session, adding 'State' attribute to reply 0x2ff6fec32ff4f38a Mon Jun 15 08:29:23 2015 : Debug: (8) modsingle[authenticate]: returned from eap (rlm_eap) for request 8 Mon Jun 15 08:29:23 2015 : Debug: (8) [eap] = handled Mon Jun 15 08:29:23 2015 : Debug: (8) } # authenticate = handled Mon Jun 15 08:29:23 2015 : Debug: (8) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=200, length=0 Mon Jun 15 08:29:23 2015 : Debug: (8) EAP-Message = 0x010200060d20 Mon Jun 15 08:29:23 2015 : Debug: (8) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (8) State = 0x2ff6fec32ff4f38a47a41edf3f78c64e Sending Access-Challenge Id 200 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010200060d20 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2ff6fec32ff4f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (8) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 201 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 = 0x0202008b0d8000000081160301007c010000780301557e62b345b223d0569417f5ad6c0de03cbc7a20c5d5efd1c4fbab8d1b3e448420887383309dd3da2d81845e05203c8ee9d4362c5f9cf7984a4cdb2e81e8633f630018c014c013c00ac0090035002f00380032000a00130005000401000017000a00080006001900170018000b00020100ff01000100 State = 0x2ff6fec32ff4f38a47a41edf3f78c64e Message-Authenticator = 0x3fe3ccf41e0e3faf4099bd187dbd57ec Mon Jun 15 08:29:23 2015 : Debug: (9) Received Access-Request packet from host 192.168.104.80 port 32770, id=201, length=447 Mon Jun 15 08:29:23 2015 : Debug: (9) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (9) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (9) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (9) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (9) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (9) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (9) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (9) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (9) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (9) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (9) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (9) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (9) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (9) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (9) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (9) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (9) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (9) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (9) EAP-Message = 0x0202008b0d8000000081160301007c010000780301557e62b345b223d0569417f5ad6c0de03cbc7a20c5d5efd1c4fbab8d1b3e448420887383309dd3da2d81845e05203c8ee9d4362c5f9cf7984a4cdb2e81e8633f630018c014c013c00ac0090035002f00380032000a00130005000401000017000a00080006001900170018000b00020100ff01000100 Mon Jun 15 08:29:23 2015 : Debug: (9) State = 0x2ff6fec32ff4f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (9) Message-Authenticator = 0x3fe3ccf41e0e3faf4099bd187dbd57ec Mon Jun 15 08:29:23 2015 : Debug: (9) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (9) authorize { Mon Jun 15 08:29:23 2015 : Debug: (9) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (9) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (9) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (9) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (9) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling auth_log (rlm_detail) for request 9 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (9) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (9) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (9) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (9) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (9) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from auth_log (rlm_detail) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling chap (rlm_chap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from chap (rlm_chap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling suffix (rlm_realm) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (9) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (9) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from suffix (rlm_realm) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling eap (rlm_eap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) eap : Peer sent code Response (2) ID 2 length 139 Mon Jun 15 08:29:23 2015 : Debug: (9) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from eap (rlm_eap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [eap] = updated Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling files (rlm_files) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from files (rlm_files) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [files] = noop Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling expiration (rlm_expiration) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from expiration (rlm_expiration) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [expiration] = noop Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling logintime (rlm_logintime) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from logintime (rlm_logintime) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [logintime] = noop Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: calling pap (rlm_pap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authorize]: returned from pap (rlm_pap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [pap] = noop Mon Jun 15 08:29:23 2015 : Debug: (9) } # authorize = updated Mon Jun 15 08:29:23 2015 : Debug: (9) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (9) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (9) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authenticate]: calling eap (rlm_eap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) eap : Expiring EAP session with state 0x2ff6fec32ff4f38a Mon Jun 15 08:29:23 2015 : Debug: (9) eap : Finished EAP session with state 0x2ff6fec32ff4f38a Mon Jun 15 08:29:23 2015 : Debug: (9) eap : Previous EAP request found for state 0x2ff6fec32ff4f38a, released from the list Mon Jun 15 08:29:23 2015 : Debug: (9) eap : Peer sent method TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (9) eap : EAP TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (9) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : Authenticate Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : processing EAP-TLS Mon Jun 15 08:29:23 2015 : Debug: TLS Length 129 Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : Length Included Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : eaptls_verify returned 11 Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : (other): before/accept initialization Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: before/accept initialization Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : <<< TLS 1.0 Handshake [length 007c], ClientHello Mon Jun 15 08:29:23 2015 : Debug: SSL: Client requested cached session 887383309dd3da2d81845e05203c8ee9d4362c5f9cf7984a4cdb2e81e8633f63 Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: SSLv3 read client hello A Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : >>> TLS 1.0 Handshake [length 0059], ServerHello Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: SSLv3 write server hello A Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : >>> TLS 1.0 Handshake [length 0c46], Certificate Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: SSLv3 write certificate A Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: SSLv3 write key exchange A Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : >>> TLS 1.0 Handshake [length 005b], CertificateRequest Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: SSLv3 write certificate request A Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: SSLv3 flush data Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : TLS_accept: Need to read more data: SSLv3 read client certificate A Mon Jun 15 08:29:23 2015 : Debug: In SSL Handshake Phase Mon Jun 15 08:29:23 2015 : Debug: In SSL Accept mode Mon Jun 15 08:29:23 2015 : Debug: (9) eap_tls : eaptls_process returned 13 Mon Jun 15 08:29:23 2015 : Debug: (9) eap : New EAP session, adding 'State' attribute to reply 0x2ff6fec32ef5f38a Mon Jun 15 08:29:23 2015 : Debug: (9) modsingle[authenticate]: returned from eap (rlm_eap) for request 9 Mon Jun 15 08:29:23 2015 : Debug: (9) [eap] = handled Mon Jun 15 08:29:23 2015 : Debug: (9) } # authenticate = handled Mon Jun 15 08:29:23 2015 : Debug: (9) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=201, length=0 Mon Jun 15 08:29:23 2015 : Debug: (9) EAP-Message = 0x010304000dc000000e591603010059020000550301557e62b321a4be97e0cbac1a0a6804725285353b46d83c89e338c13292c34e79205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9c01400000dff01000100000b0004030001021603010c460b000c42000c3f0006c8308206c4308204aca0030201020213740000006a74a572c34ebbf02c00000000006a300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532393035333830345a170d3137303532393035343830345a30818c310b30090603550406130245453111300f060355040813084861726a756d61613111300f060355040713085461626173616c7531143012060355040a130b50616c6d6174696e204f59311b3019060355040313127261646975732e70616c6d6174696e2e65653124302206092a864886f70d010901161573797361646d696e734070616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100f4d7d99606c770826ca1e9944fe8ca7690cc7d59d57bf554ce4b4351322553554a5302235a9b524371d3ba4b034efdde15acabe5 Mon Jun 15 08:29:23 2015 : Debug: (9) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (9) State = 0x2ff6fec32ef5f38a47a41edf3f78c64e Sending Access-Challenge Id 201 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010304000dc000000e591603010059020000550301557e62b321a4be97e0cbac1a0a6804725285353b46d83c89e338c13292c34e79205bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9c01400000dff01000100000b0004030001021603010c460b000c42000c3f0006c8308206c4308204aca0030201020213740000006a74a572c34ebbf02c00000000006a300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532393035333830345a170d3137303532393035343830345a30818c310b30090603550406130245453111300f060355040813084861726a756d61613111300f060355040713085461626173616c7531143012060355040a130b50616c6d6174696e204f59311b3019060355040313127261646975732e70616c6d6174696e2e65653124302206092a864886f70d010901161573797361646d696e734070616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100f4d7d99606c770826ca1e9944fe8ca7690cc7d59d57bf554ce4b4351322553554a5302235a9b524371d3ba4b034efdde15acabe Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2ff6fec32ef5f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (9) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 202 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 = 0x020300060d00 State = 0x2ff6fec32ef5f38a47a41edf3f78c64e Message-Authenticator = 0xb56dbbbac72723f8214bfc825f1a7e0c Mon Jun 15 08:29:23 2015 : Debug: (10) Received Access-Request packet from host 192.168.104.80 port 32770, id=202, length=314 Mon Jun 15 08:29:23 2015 : Debug: (10) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (10) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (10) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (10) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (10) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (10) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (10) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (10) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (10) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (10) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (10) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (10) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (10) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (10) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (10) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (10) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (10) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (10) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (10) EAP-Message = 0x020300060d00 Mon Jun 15 08:29:23 2015 : Debug: (10) State = 0x2ff6fec32ef5f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (10) Message-Authenticator = 0xb56dbbbac72723f8214bfc825f1a7e0c Mon Jun 15 08:29:23 2015 : Debug: (10) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (10) authorize { Mon Jun 15 08:29:23 2015 : Debug: (10) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (10) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (10) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (10) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (10) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling auth_log (rlm_detail) for request 10 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (10) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (10) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (10) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (10) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (10) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from auth_log (rlm_detail) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling chap (rlm_chap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from chap (rlm_chap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling suffix (rlm_realm) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (10) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (10) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from suffix (rlm_realm) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling eap (rlm_eap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) eap : Peer sent code Response (2) ID 3 length 6 Mon Jun 15 08:29:23 2015 : Debug: (10) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from eap (rlm_eap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [eap] = updated Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling files (rlm_files) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from files (rlm_files) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [files] = noop Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling expiration (rlm_expiration) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from expiration (rlm_expiration) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [expiration] = noop Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling logintime (rlm_logintime) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from logintime (rlm_logintime) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [logintime] = noop Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: calling pap (rlm_pap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authorize]: returned from pap (rlm_pap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [pap] = noop Mon Jun 15 08:29:23 2015 : Debug: (10) } # authorize = updated Mon Jun 15 08:29:23 2015 : Debug: (10) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (10) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (10) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authenticate]: calling eap (rlm_eap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) eap : Expiring EAP session with state 0x2ff6fec32ef5f38a Mon Jun 15 08:29:23 2015 : Debug: (10) eap : Finished EAP session with state 0x2ff6fec32ef5f38a Mon Jun 15 08:29:23 2015 : Debug: (10) eap : Previous EAP request found for state 0x2ff6fec32ef5f38a, released from the list Mon Jun 15 08:29:23 2015 : Debug: (10) eap : Peer sent method TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (10) eap : EAP TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (10) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (10) eap_tls : Authenticate Mon Jun 15 08:29:23 2015 : Debug: (10) eap_tls : processing EAP-TLS Mon Jun 15 08:29:23 2015 : Debug: (10) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (10) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (10) eap_tls : ACK handshake fragment handler Mon Jun 15 08:29:23 2015 : Debug: (10) eap_tls : eaptls_verify returned 1 Mon Jun 15 08:29:23 2015 : Debug: (10) eap_tls : eaptls_process returned 13 Mon Jun 15 08:29:23 2015 : Debug: (10) eap : New EAP session, adding 'State' attribute to reply 0x2ff6fec32df2f38a Mon Jun 15 08:29:23 2015 : Debug: (10) modsingle[authenticate]: returned from eap (rlm_eap) for request 10 Mon Jun 15 08:29:23 2015 : Debug: (10) [eap] = handled Mon Jun 15 08:29:23 2015 : Debug: (10) } # authenticate = handled Mon Jun 15 08:29:23 2015 : Debug: (10) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=202, length=0 Mon Jun 15 08:29:23 2015 : Debug: (10) EAP-Message = 0x010404000dc000000e59050730028681a26c6461703a2f2f2f434e3d50616c6d6174696e4f59526f6f7443412c434e3d4149412c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d70616c6d6174696e2c44433d65653f634143657274696669636174653f626173653f6f626a656374436c6173733d63657274696669636174696f6e417574686f72697479300e0603551d0f0101ff0404030205a0303e06092b06010401823715070431302f06272b06010401823715088398af2881ddf91a87fd9f1983f0ef4084c3d31e810981818b4585e8c57702016402010330130603551d25040c300a06082b06010505070301301b06092b060104018237150a040e300c300a06082b06010505070301300d06092a864886f70d01010505000382020100603588f4deba0a7bcb1dda8405f9fa0904a52ee5c808399869ba2576dcc859b7a43fb757d4535f91183e920dc4ee02a9d93a635ac2f1f85f622f21ad494f651c51ae4a09fbbb6cd3cd99da39d1ce87cda127b6912ebaa4c7d435428e7d67e89be94f5868f23b91016543abdd882423e4f365d8400d0145adad5a7e123ebb74c8bfae12e3fa5e3c6c45a520f1d3ed63797a10efebb47286432b981924f887f6a59e3dae92ae94bd484c619df729e9 Mon Jun 15 08:29:23 2015 : Debug: (10) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (10) State = 0x2ff6fec32df2f38a47a41edf3f78c64e Sending Access-Challenge Id 202 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010404000dc000000e59050730028681a26c6461703a2f2f2f434e3d50616c6d6174696e4f59526f6f7443412c434e3d4149412c434e3d5075626c69632532304b657925323053657276696365732c434e3d53657276696365732c434e3d436f6e66696775726174696f6e2c44433d70616c6d6174696e2c44433d65653f634143657274696669636174653f626173653f6f626a656374436c6173733d63657274696669636174696f6e417574686f72697479300e0603551d0f0101ff0404030205a0303e06092b06010401823715070431302f06272b06010401823715088398af2881ddf91a87fd9f1983f0ef4084c3d31e810981818b4585e8c57702016402010330130603551d25040c300a06082b06010505070301301b06092b060104018237150a040e300c300a06082b06010505070301300d06092a864886f70d01010505000382020100603588f4deba0a7bcb1dda8405f9fa0904a52ee5c808399869ba2576dcc859b7a43fb757d4535f91183e920dc4ee02a9d93a635ac2f1f85f622f21ad494f651c51ae4a09fbbb6cd3cd99da39d1ce87cda127b6912ebaa4c7d435428e7d67e89be94f5868f23b91016543abdd882423e4f365d8400d0145adad5a7e123ebb74c8bfae12e3fa5e3c6c45a520f1d3ed63797a10efebb47286432b981924f887f6a59e3dae92ae94bd484c619df729e Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2ff6fec32df2f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (10) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 203 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 = 0x2ff6fec32df2f38a47a41edf3f78c64e Message-Authenticator = 0x4f1767fe572b83a99cd178b148dba55a Mon Jun 15 08:29:23 2015 : Debug: (11) Received Access-Request packet from host 192.168.104.80 port 32770, id=203, length=314 Mon Jun 15 08:29:23 2015 : Debug: (11) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (11) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (11) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (11) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (11) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (11) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (11) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (11) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (11) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (11) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (11) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (11) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (11) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (11) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (11) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (11) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (11) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (11) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (11) EAP-Message = 0x020400060d00 Mon Jun 15 08:29:23 2015 : Debug: (11) State = 0x2ff6fec32df2f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (11) Message-Authenticator = 0x4f1767fe572b83a99cd178b148dba55a Mon Jun 15 08:29:23 2015 : Debug: (11) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (11) authorize { Mon Jun 15 08:29:23 2015 : Debug: (11) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (11) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (11) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (11) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (11) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (11) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (11) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling auth_log (rlm_detail) for request 11 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (11) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (11) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (11) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (11) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (11) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from auth_log (rlm_detail) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling chap (rlm_chap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from chap (rlm_chap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling suffix (rlm_realm) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (11) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (11) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from suffix (rlm_realm) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling eap (rlm_eap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) eap : Peer sent code Response (2) ID 4 length 6 Mon Jun 15 08:29:23 2015 : Debug: (11) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from eap (rlm_eap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [eap] = updated Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling files (rlm_files) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from files (rlm_files) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [files] = noop Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling expiration (rlm_expiration) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from expiration (rlm_expiration) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [expiration] = noop Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling logintime (rlm_logintime) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from logintime (rlm_logintime) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [logintime] = noop Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: calling pap (rlm_pap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authorize]: returned from pap (rlm_pap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [pap] = noop Mon Jun 15 08:29:23 2015 : Debug: (11) } # authorize = updated Mon Jun 15 08:29:23 2015 : Debug: (11) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (11) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (11) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authenticate]: calling eap (rlm_eap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) eap : Expiring EAP session with state 0x2ff6fec32df2f38a Mon Jun 15 08:29:23 2015 : Debug: (11) eap : Finished EAP session with state 0x2ff6fec32df2f38a Mon Jun 15 08:29:23 2015 : Debug: (11) eap : Previous EAP request found for state 0x2ff6fec32df2f38a, released from the list Mon Jun 15 08:29:23 2015 : Debug: (11) eap : Peer sent method TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (11) eap : EAP TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (11) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (11) eap_tls : Authenticate Mon Jun 15 08:29:23 2015 : Debug: (11) eap_tls : processing EAP-TLS Mon Jun 15 08:29:23 2015 : Debug: (11) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (11) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (11) eap_tls : ACK handshake fragment handler Mon Jun 15 08:29:23 2015 : Debug: (11) eap_tls : eaptls_verify returned 1 Mon Jun 15 08:29:23 2015 : Debug: (11) eap_tls : eaptls_process returned 13 Mon Jun 15 08:29:23 2015 : Debug: (11) eap : New EAP session, adding 'State' attribute to reply 0x2ff6fec32cf3f38a Mon Jun 15 08:29:23 2015 : Debug: (11) modsingle[authenticate]: returned from eap (rlm_eap) for request 11 Mon Jun 15 08:29:23 2015 : Debug: (11) [eap] = handled Mon Jun 15 08:29:23 2015 : Debug: (11) } # authenticate = handled Mon Jun 15 08:29:23 2015 : Debug: (11) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=203, length=0 Mon Jun 15 08:29:23 2015 : Debug: (11) EAP-Message = 0x010504000dc000000e590a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f74434130820222300d06092a864886f70d01010105000382020f003082020a0282020100be2fa5e0f143a4dc9eeab356d09c655afab7ab4b943a8ad2628a295209553063875750d90e3296deab425182385389a75061b22501b90a6329d20cc61fbf4efb3f05f93674a912b346503e9e74038f76185a48de7fdad6a2f8d61c742597e059404548193895754e9991a450f0e5b0aceca5c3e17e86a126f4bc5789b256925ecd65cb14d797caa107b6854d29ef1f6aebd773f9ea0ca2c82244f0c7365faa212c87403e6019c4a5455726e4f05d058ab2ab7b962052e00b6b8c2fed642733598595aadcd44219e52df35f4b49e14fef61e32f04311d87a5bcea2d3e67be930b497ca4995350a226b09ef76481b8fa5b439d96624356013c5309d14b79d0a7ca3a4424a12ddcfcab088155237e2d21f2c029e9416fc57c0fe25d47e0a8e28228c5877b28e5d947d5e26a12eb31e1eb758478bef96e9d960b0eabd3eeffee50eb59db04b8ac9a8e08cac7c2b65db5d0180c50521797018804f6d3cce6b7ed51e3e4d138fd28f193aa4b1ba4878bed41bf4fd6c8b14f283018c0d71ea23f4c5671f6e46a526c662cfbbb3e35a2173a584f9193f604a3e5fac383bb0967 Mon Jun 15 08:29:23 2015 : Debug: (11) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (11) State = 0x2ff6fec32cf3f38a47a41edf3f78c64e Sending Access-Challenge Id 203 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010504000dc000000e590a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f74434130820222300d06092a864886f70d01010105000382020f003082020a0282020100be2fa5e0f143a4dc9eeab356d09c655afab7ab4b943a8ad2628a295209553063875750d90e3296deab425182385389a75061b22501b90a6329d20cc61fbf4efb3f05f93674a912b346503e9e74038f76185a48de7fdad6a2f8d61c742597e059404548193895754e9991a450f0e5b0aceca5c3e17e86a126f4bc5789b256925ecd65cb14d797caa107b6854d29ef1f6aebd773f9ea0ca2c82244f0c7365faa212c87403e6019c4a5455726e4f05d058ab2ab7b962052e00b6b8c2fed642733598595aadcd44219e52df35f4b49e14fef61e32f04311d87a5bcea2d3e67be930b497ca4995350a226b09ef76481b8fa5b439d96624356013c5309d14b79d0a7ca3a4424a12ddcfcab088155237e2d21f2c029e9416fc57c0fe25d47e0a8e28228c5877b28e5d947d5e26a12eb31e1eb758478bef96e9d960b0eabd3eeffee50eb59db04b8ac9a8e08cac7c2b65db5d0180c50521797018804f6d3cce6b7ed51e3e4d138fd28f193aa4b1ba4878bed41bf4fd6c8b14f283018c0d71ea23f4c5671f6e46a526c662cfbbb3e35a2173a584f9193f604a3e5fac383bb096 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2ff6fec32cf3f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (11) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 204 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 = 0x2ff6fec32cf3f38a47a41edf3f78c64e Message-Authenticator = 0x58cb3c2337d71eff86d54859627d8973 Mon Jun 15 08:29:23 2015 : Debug: (12) Received Access-Request packet from host 192.168.104.80 port 32770, id=204, length=314 Mon Jun 15 08:29:23 2015 : Debug: (12) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (12) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (12) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (12) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (12) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (12) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (12) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (12) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (12) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (12) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (12) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (12) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (12) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (12) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (12) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (12) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (12) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (12) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (12) EAP-Message = 0x020500060d00 Mon Jun 15 08:29:23 2015 : Debug: (12) State = 0x2ff6fec32cf3f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (12) Message-Authenticator = 0x58cb3c2337d71eff86d54859627d8973 Mon Jun 15 08:29:23 2015 : Debug: (12) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (12) authorize { Mon Jun 15 08:29:23 2015 : Debug: (12) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (12) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (12) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (12) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (12) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (12) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (12) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling auth_log (rlm_detail) for request 12 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (12) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (12) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (12) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (12) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (12) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from auth_log (rlm_detail) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling chap (rlm_chap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from chap (rlm_chap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling suffix (rlm_realm) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (12) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (12) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from suffix (rlm_realm) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling eap (rlm_eap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) eap : Peer sent code Response (2) ID 5 length 6 Mon Jun 15 08:29:23 2015 : Debug: (12) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from eap (rlm_eap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [eap] = updated Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling files (rlm_files) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from files (rlm_files) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [files] = noop Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling expiration (rlm_expiration) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from expiration (rlm_expiration) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [expiration] = noop Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling logintime (rlm_logintime) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from logintime (rlm_logintime) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [logintime] = noop Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: calling pap (rlm_pap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authorize]: returned from pap (rlm_pap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [pap] = noop Mon Jun 15 08:29:23 2015 : Debug: (12) } # authorize = updated Mon Jun 15 08:29:23 2015 : Debug: (12) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (12) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (12) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authenticate]: calling eap (rlm_eap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) eap : Expiring EAP session with state 0x2ff6fec32cf3f38a Mon Jun 15 08:29:23 2015 : Debug: (12) eap : Finished EAP session with state 0x2ff6fec32cf3f38a Mon Jun 15 08:29:23 2015 : Debug: (12) eap : Previous EAP request found for state 0x2ff6fec32cf3f38a, released from the list Mon Jun 15 08:29:23 2015 : Debug: (12) eap : Peer sent method TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (12) eap : EAP TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (12) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (12) eap_tls : Authenticate Mon Jun 15 08:29:23 2015 : Debug: (12) eap_tls : processing EAP-TLS Mon Jun 15 08:29:23 2015 : Debug: (12) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (12) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (12) eap_tls : ACK handshake fragment handler Mon Jun 15 08:29:23 2015 : Debug: (12) eap_tls : eaptls_verify returned 1 Mon Jun 15 08:29:23 2015 : Debug: (12) eap_tls : eaptls_process returned 13 Mon Jun 15 08:29:23 2015 : Debug: (12) eap : New EAP session, adding 'State' attribute to reply 0x2ff6fec32bf0f38a Mon Jun 15 08:29:23 2015 : Debug: (12) modsingle[authenticate]: returned from eap (rlm_eap) for request 12 Mon Jun 15 08:29:23 2015 : Debug: (12) [eap] = handled Mon Jun 15 08:29:23 2015 : Debug: (12) } # authenticate = handled Mon Jun 15 08:29:23 2015 : Debug: (12) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=204, length=0 Mon Jun 15 08:29:23 2015 : Debug: (12) EAP-Message = 0x010602810d8000000e591ad0249cf4e25319a8dc335ecf712f7dac90797bc30de6efffff3a3bb05e4d51cb5f09b3fffad4141f55c8ae6218827bd090e50761fd16aed2c49d94fa3a5015423ca228b95e2d093b916735efd9087f493b765d69e11e4b177aa3c917cd759791e7574327df45dd0c74daab55d6cc3261738baef1b239e1f77bbcd8cadb14c4ac41f3dc8f07d89e6b4d297823fcb7be5d8d89a82239ea4ae458958cde04ebc257663a853a2d5a9276121af5190483b53e49ecf544f1eaeff183d2c60957a44ae1ca7bc101f79e160301014b0c000147030017410413f6bd567c9c40ef518b8a707130bfa66018d3530cc027bcddcdd55be8d49000948399bf987b73112169ae8d3eeae124ce32fc788a65262106ce6dcd8ae9737401007f87eb1e6c0434131504f678885dc21eed56d7eec980f9af870547bd6fba3227c5ccedd6ef083c2ecb42dba4dacab20121564bdaf8f72230ac25f32c13baec457335b20b495c4dd91d1b9af703a4de2643596df23930fda89bd8eff5ead35e0912ae05bcc40bfa4fdda05fcfce1d92c1ac7a51aa765ce9c99e5c0d4a9a8a5e999abdc23bd819abc0c3469a4d761038afb61fb2f9af076473e896a109e19895aa9b79a164530f3d3102dd8d9d13e41acf054d46b2a1d490fb7fa15d004c56a411253b838117fb7b6fa44683f95512baf7450d3ba8dfd8 Mon Jun 15 08:29:23 2015 : Debug: (12) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (12) State = 0x2ff6fec32bf0f38a47a41edf3f78c64e Sending Access-Challenge Id 204 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010602810d8000000e591ad0249cf4e25319a8dc335ecf712f7dac90797bc30de6efffff3a3bb05e4d51cb5f09b3fffad4141f55c8ae6218827bd090e50761fd16aed2c49d94fa3a5015423ca228b95e2d093b916735efd9087f493b765d69e11e4b177aa3c917cd759791e7574327df45dd0c74daab55d6cc3261738baef1b239e1f77bbcd8cadb14c4ac41f3dc8f07d89e6b4d297823fcb7be5d8d89a82239ea4ae458958cde04ebc257663a853a2d5a9276121af5190483b53e49ecf544f1eaeff183d2c60957a44ae1ca7bc101f79e160301014b0c000147030017410413f6bd567c9c40ef518b8a707130bfa66018d3530cc027bcddcdd55be8d49000948399bf987b73112169ae8d3eeae124ce32fc788a65262106ce6dcd8ae9737401007f87eb1e6c0434131504f678885dc21eed56d7eec980f9af870547bd6fba3227c5ccedd6ef083c2ecb42dba4dacab20121564bdaf8f72230ac25f32c13baec457335b20b495c4dd91d1b9af703a4de2643596df23930fda89bd8eff5ead35e0912ae05bcc40bfa4fdda05fcfce1d92c1ac7a51aa765ce9c99e5c0d4a9a8a5e999abdc23bd819abc0c3469a4d761038afb61fb2f9af076473e896a109e19895aa9b79a164530f3d3102dd8d9d13e41acf054d46b2a1d490fb7fa15d004c56a411253b838117fb7b6fa44683f95512baf7450d3ba8dfd Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2ff6fec32bf0f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (12) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 205 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 = 0x020605d40dc00000082716030107e70b0006970006940006913082068d30820475a003020102021374000000528ce96f685e3bd5b2000000000052300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532343132343035395a170d3136303532333132343035395a301f311d301b060355040313144b414c4a4f2d4c542e70616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100c92346d9e0dd249f908cbffd877a1b4d87556a6bcf4395be9f949aa889e2fccd58003fc1289dd2f05afb880d58ad2ba160f47cb1f9121b973a0a843939e9c236277c2beeb138b8676ff8f0f923231e91bb0a70690342767fd8b47f605747b201274d3ffc8ae7f7387028d74ee29edc071f7ce5a7fbfc44845419aa92c6bf06979d7757b09fae99458416afea9121f7d456a127f4eba897379526df960544a011d31fc5cef56de8c45ab4b03505d82913b159d5d5feadf23f2d4bd3770c92a51e4c07f8430f8cfeddaa0ad7b446d3a68377ad76ee4ac6f2dc454808649fbbded2b8a6ec2b9e54315c3c8b75e59d9266c8102bf965bcb1679bc7ac75660c2e87c State = 0x2ff6fec32bf0f38a47a41edf3f78c64e Message-Authenticator = 0x262924574367e5eda07a6170e6111a21 Mon Jun 15 08:29:23 2015 : Debug: (13) Received Access-Request packet from host 192.168.104.80 port 32770, id=205, length=1810 Mon Jun 15 08:29:23 2015 : Debug: (13) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (13) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (13) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (13) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (13) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (13) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (13) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (13) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (13) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (13) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (13) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (13) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (13) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (13) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (13) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (13) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (13) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (13) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (13) EAP-Message = 0x020605d40dc00000082716030107e70b0006970006940006913082068d30820475a003020102021374000000528ce96f685e3bd5b2000000000052300d06092a864886f70d0101050500304931123010060a0992268993f22c6401191602656531183016060a0992268993f22c640119160870616c6d6174696e311930170603550403131050616c6d6174696e4f59526f6f744341301e170d3135303532343132343035395a170d3136303532333132343035395a301f311d301b060355040313144b414c4a4f2d4c542e70616c6d6174696e2e656530820122300d06092a864886f70d01010105000382010f003082010a0282010100c92346d9e0dd249f908cbffd877a1b4d87556a6bcf4395be9f949aa889e2fccd58003fc1289dd2f05afb880d58ad2ba160f47cb1f9121b973a0a843939e9c236277c2beeb138b8676ff8f0f923231e91bb0a70690342767fd8b47f605747b201274d3ffc8ae7f7387028d74ee29edc071f7ce5a7fbfc44845419aa92c6bf06979d7757b09fae99458416afea9121f7d456a127f4eba897379526df960544a011d31fc5cef56de8c45ab4b03505d82913b159d5d5feadf23f2d4bd3770c92a51e4c07f8430f8cfeddaa0ad7b446d3a68377ad76ee4ac6f2dc454808649fbbded2b8a6ec2b9e54315c3c8b75e59d9266c8102bf965bcb1679bc7ac75660c2e87cd Mon Jun 15 08:29:23 2015 : Debug: (13) State = 0x2ff6fec32bf0f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (13) Message-Authenticator = 0x262924574367e5eda07a6170e6111a21 Mon Jun 15 08:29:23 2015 : Debug: (13) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (13) authorize { Mon Jun 15 08:29:23 2015 : Debug: (13) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (13) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (13) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (13) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (13) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (13) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (13) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling auth_log (rlm_detail) for request 13 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (13) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (13) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (13) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (13) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (13) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from auth_log (rlm_detail) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling chap (rlm_chap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from chap (rlm_chap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling suffix (rlm_realm) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (13) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (13) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from suffix (rlm_realm) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling eap (rlm_eap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) eap : Peer sent code Response (2) ID 6 length 1492 Mon Jun 15 08:29:23 2015 : Debug: (13) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from eap (rlm_eap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [eap] = updated Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling files (rlm_files) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from files (rlm_files) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [files] = noop Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling expiration (rlm_expiration) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from expiration (rlm_expiration) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [expiration] = noop Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling logintime (rlm_logintime) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from logintime (rlm_logintime) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [logintime] = noop Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: calling pap (rlm_pap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authorize]: returned from pap (rlm_pap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [pap] = noop Mon Jun 15 08:29:23 2015 : Debug: (13) } # authorize = updated Mon Jun 15 08:29:23 2015 : Debug: (13) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (13) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (13) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authenticate]: calling eap (rlm_eap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) eap : Expiring EAP session with state 0x2ff6fec32bf0f38a Mon Jun 15 08:29:23 2015 : Debug: (13) eap : Finished EAP session with state 0x2ff6fec32bf0f38a Mon Jun 15 08:29:23 2015 : Debug: (13) eap : Previous EAP request found for state 0x2ff6fec32bf0f38a, released from the list Mon Jun 15 08:29:23 2015 : Debug: (13) eap : Peer sent method TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (13) eap : EAP TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (13) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (13) eap_tls : Authenticate Mon Jun 15 08:29:23 2015 : Debug: (13) eap_tls : processing EAP-TLS Mon Jun 15 08:29:23 2015 : Debug: TLS Length 2087 Mon Jun 15 08:29:23 2015 : Debug: (13) eap_tls : Received EAP-TLS First Fragment of the message Mon Jun 15 08:29:23 2015 : Debug: (13) eap_tls : eaptls_verify returned 9 Mon Jun 15 08:29:23 2015 : Debug: (13) eap_tls : eaptls_process returned 13 Mon Jun 15 08:29:23 2015 : Debug: (13) eap : New EAP session, adding 'State' attribute to reply 0x2ff6fec32af1f38a Mon Jun 15 08:29:23 2015 : Debug: (13) modsingle[authenticate]: returned from eap (rlm_eap) for request 13 Mon Jun 15 08:29:23 2015 : Debug: (13) [eap] = handled Mon Jun 15 08:29:23 2015 : Debug: (13) } # authenticate = handled Mon Jun 15 08:29:23 2015 : Debug: (13) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=205, length=0 Mon Jun 15 08:29:23 2015 : Debug: (13) EAP-Message = 0x010700060d00 Mon Jun 15 08:29:23 2015 : Debug: (13) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (13) State = 0x2ff6fec32af1f38a47a41edf3f78c64e Sending Access-Challenge Id 205 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010700060d00 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2ff6fec32af1f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (13) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.6 seconds. Received Access-Request Id 206 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 = 0x020702630d00fe607eb5a7e8ccac163a23d897db9fae64f37a203141a3f9ef158b6be5b7b008eb1f681313fd71561250d00fc583e5855be1687ed8dd809290b5ba8941b1261b5762e1fc5f74ea44330ddfe677480cd84ce98cb38ed18ecf75afd7339756508087210f9d15e5841f515273177fe8f8b6744dfef08426a7d147192a6c039801b31822627f2387322008acd8ce659574635479474a60557180e349d8635a320247806c83f6135430f1a6314da4fdbfe912b841e5b36a1e441fe5c8bb37952a72411d2f0879fedbb9ea9e3c68f20ef21f24577125dcbfb71000004241049c66d4e2edd71c335adf33c402ca9cf54b41b642f0121d4359816d94742069aab6d1fada31eecb52acb005169241e73984068d5720e0836f7ae9f6d41ccef84b0f00010201002604d283d0b54e353f8c0d46638bca31e08b315466c4073df926842c3337bc66a35bb9a78142dec4d48e6c7ffebb02c713a96f889739733430b94640434c2f9d2fbaf0be075856d99ee16cb4658a560a0aabba1d96f83e731d386f98a6a33240a1a2a2df83b8c7311202f13723cf47882bffa431eabdc402d4f3bb3268c5fab1f5c63a6e2b30f395ece131815f43b0375f9bcf5c9a80e3175475d8aa812697aea09708a959f505f3142804f6747d2307f78aa57f1c111761f625ae465bd63c9f99615320b5a95a8b1e4b00a104dab State = 0x2ff6fec32af1f38a47a41edf3f78c64e Message-Authenticator = 0x0901b59d7b35a5466e0d1599ea653807 Mon Jun 15 08:29:23 2015 : Debug: (14) Received Access-Request packet from host 192.168.104.80 port 32770, id=206, length=923 Mon Jun 15 08:29:23 2015 : Debug: (14) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (14) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (14) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (14) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (14) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (14) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (14) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (14) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (14) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (14) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (14) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (14) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (14) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (14) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (14) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (14) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (14) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (14) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (14) EAP-Message = 0x020702630d00fe607eb5a7e8ccac163a23d897db9fae64f37a203141a3f9ef158b6be5b7b008eb1f681313fd71561250d00fc583e5855be1687ed8dd809290b5ba8941b1261b5762e1fc5f74ea44330ddfe677480cd84ce98cb38ed18ecf75afd7339756508087210f9d15e5841f515273177fe8f8b6744dfef08426a7d147192a6c039801b31822627f2387322008acd8ce659574635479474a60557180e349d8635a320247806c83f6135430f1a6314da4fdbfe912b841e5b36a1e441fe5c8bb37952a72411d2f0879fedbb9ea9e3c68f20ef21f24577125dcbfb71000004241049c66d4e2edd71c335adf33c402ca9cf54b41b642f0121d4359816d94742069aab6d1fada31eecb52acb005169241e73984068d5720e0836f7ae9f6d41ccef84b0f00010201002604d283d0b54e353f8c0d46638bca31e08b315466c4073df926842c3337bc66a35bb9a78142dec4d48e6c7ffebb02c713a96f889739733430b94640434c2f9d2fbaf0be075856d99ee16cb4658a560a0aabba1d96f83e731d386f98a6a33240a1a2a2df83b8c7311202f13723cf47882bffa431eabdc402d4f3bb3268c5fab1f5c63a6e2b30f395ece131815f43b0375f9bcf5c9a80e3175475d8aa812697aea09708a959f505f3142804f6747d2307f78aa57f1c111761f625ae465bd63c9f99615320b5a95a8b1e4b00a104dab0 Mon Jun 15 08:29:23 2015 : Debug: (14) State = 0x2ff6fec32af1f38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (14) Message-Authenticator = 0x0901b59d7b35a5466e0d1599ea653807 Mon Jun 15 08:29:23 2015 : Debug: (14) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (14) authorize { Mon Jun 15 08:29:23 2015 : Debug: (14) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (14) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (14) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (14) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (14) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (14) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (14) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling auth_log (rlm_detail) for request 14 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (14) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (14) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (14) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (14) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (14) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from auth_log (rlm_detail) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling chap (rlm_chap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from chap (rlm_chap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling suffix (rlm_realm) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (14) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (14) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from suffix (rlm_realm) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling eap (rlm_eap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) eap : Peer sent code Response (2) ID 7 length 611 Mon Jun 15 08:29:23 2015 : Debug: (14) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from eap (rlm_eap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [eap] = updated Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling files (rlm_files) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from files (rlm_files) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [files] = noop Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling expiration (rlm_expiration) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from expiration (rlm_expiration) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [expiration] = noop Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling logintime (rlm_logintime) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from logintime (rlm_logintime) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [logintime] = noop Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: calling pap (rlm_pap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authorize]: returned from pap (rlm_pap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [pap] = noop Mon Jun 15 08:29:23 2015 : Debug: (14) } # authorize = updated Mon Jun 15 08:29:23 2015 : Debug: (14) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (14) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (14) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authenticate]: calling eap (rlm_eap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) eap : Expiring EAP session with state 0x2ff6fec32af1f38a Mon Jun 15 08:29:23 2015 : Debug: (14) eap : Finished EAP session with state 0x2ff6fec32af1f38a Mon Jun 15 08:29:23 2015 : Debug: (14) eap : Previous EAP request found for state 0x2ff6fec32af1f38a, released from the list Mon Jun 15 08:29:23 2015 : Debug: (14) eap : Peer sent method TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (14) eap : EAP TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (14) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : Authenticate Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : processing EAP-TLS Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : eaptls_verify returned 7 Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : Done initial handshake Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : <<< TLS 1.0 Handshake [length 069b], Certificate Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : chain-depth=1, Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : error=0 Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> User-Name = host/user_host.private.com Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> BUF-Name = RootCA Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> subject = /DC=com/DC=private/CN=RootCA Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> issuer = /DC=com/DC=private/CN=RootCA Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> verify return:1 Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : chain-depth=0, Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : error=0 Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> User-Name = host/user_host.private.com Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> BUF-Name = user_host.private.com Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> subject = /CN=user_host.private.com Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> issuer = /DC=com/DC=private/CN=RootCA Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : --> verify return:1 Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : TLS_accept: SSLv3 read client certificate A Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : TLS_accept: SSLv3 read client key exchange A Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : <<< TLS 1.0 Handshake [length 0106], CertificateVerify Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : TLS_accept: SSLv3 read certificate verify A Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : <<< TLS 1.0 ChangeCipherSpec [length 0001] Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : <<< TLS 1.0 Handshake [length 0010], Finished Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : TLS_accept: SSLv3 read finished A Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : >>> TLS 1.0 ChangeCipherSpec [length 0001] Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : TLS_accept: SSLv3 write change cipher spec A Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : >>> TLS 1.0 Handshake [length 0010], Finished Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : TLS_accept: SSLv3 write finished A Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : TLS_accept: SSLv3 flush data Mon Jun 15 08:29:23 2015 : Debug: SSL: adding session 5bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9 to cache Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : (other): SSL negotiation finished successfully Mon Jun 15 08:29:23 2015 : Debug: SSL Connection Established Mon Jun 15 08:29:23 2015 : Debug: (14) eap_tls : eaptls_process returned 13 Mon Jun 15 08:29:23 2015 : Debug: (14) eap : New EAP session, adding 'State' attribute to reply 0x2ff6fec329fef38a Mon Jun 15 08:29:23 2015 : Debug: (14) modsingle[authenticate]: returned from eap (rlm_eap) for request 14 Mon Jun 15 08:29:23 2015 : Debug: (14) [eap] = handled Mon Jun 15 08:29:23 2015 : Debug: (14) } # authenticate = handled Mon Jun 15 08:29:23 2015 : Debug: (14) Sending Access-Challenge packet to host 192.168.104.80 port 32770, id=206, length=0 Mon Jun 15 08:29:23 2015 : Debug: (14) EAP-Message = 0x010800450d800000003b140301000101160301003032bc9ac190c0c3dfba42c3d2a1ed061c1feb6456c4f994fed9270ba21e3058f6858b50c750b067ace1844f956428bc8d Mon Jun 15 08:29:23 2015 : Debug: (14) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (14) State = 0x2ff6fec329fef38a47a41edf3f78c64e Sending Access-Challenge Id 206 from 192.168.106.130:1812 to 192.168.104.80:32770 EAP-Message = 0x010800450d800000003b140301000101160301003032bc9ac190c0c3dfba42c3d2a1ed061c1feb6456c4f994fed9270ba21e3058f6858b50c750b067ace1844f956428bc8d Message-Authenticator = 0x00000000000000000000000000000000 State = 0x2ff6fec329fef38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (14) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.5 seconds. Received Access-Request Id 207 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 = 0x020800060d00 State = 0x2ff6fec329fef38a47a41edf3f78c64e Message-Authenticator = 0xa26e3634741dd71ce9b7430d38a7e98d Mon Jun 15 08:29:23 2015 : Debug: (15) Received Access-Request packet from host 192.168.104.80 port 32770, id=207, length=314 Mon Jun 15 08:29:23 2015 : Debug: (15) User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (15) Chargeable-User-Identity = 0x00 Mon Jun 15 08:29:23 2015 : Debug: (15) Location-Capable = Civix-Location Mon Jun 15 08:29:23 2015 : Debug: (15) Calling-Station-Id = '00-24-d7-03-2b-38' Mon Jun 15 08:29:23 2015 : Debug: (15) Called-Station-Id = 'a4-6c-2a-ea-9b-70:APSSID' Mon Jun 15 08:29:23 2015 : Debug: (15) NAS-Port = 2 Mon Jun 15 08:29:23 2015 : Debug: (15) Cisco-AVPair = 'audit-session-id=c0a868500000037f557bee92' Mon Jun 15 08:29:23 2015 : Debug: (15) Acct-Session-Id = '557bee92/00:24:d7:03:2b:38/908' Mon Jun 15 08:29:23 2015 : Debug: (15) Cisco-AVPair = 'mDNS=true' Mon Jun 15 08:29:23 2015 : Debug: (15) NAS-IP-Address = 192.168.104.80 Mon Jun 15 08:29:23 2015 : Debug: (15) NAS-Identifier = 'wc-s1-01' Mon Jun 15 08:29:23 2015 : Debug: (15) Airespace-Wlan-Id = 2 Mon Jun 15 08:29:23 2015 : Debug: (15) Service-Type = Framed-User Mon Jun 15 08:29:23 2015 : Debug: (15) Framed-MTU = 1300 Mon Jun 15 08:29:23 2015 : Debug: (15) NAS-Port-Type = Wireless-802.11 Mon Jun 15 08:29:23 2015 : Debug: (15) Tunnel-Type:0 = VLAN Mon Jun 15 08:29:23 2015 : Debug: (15) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 15 08:29:23 2015 : Debug: (15) Tunnel-Private-Group-Id:0 = '101' Mon Jun 15 08:29:23 2015 : Debug: (15) EAP-Message = 0x020800060d00 Mon Jun 15 08:29:23 2015 : Debug: (15) State = 0x2ff6fec329fef38a47a41edf3f78c64e Mon Jun 15 08:29:23 2015 : Debug: (15) Message-Authenticator = 0xa26e3634741dd71ce9b7430d38a7e98d Mon Jun 15 08:29:23 2015 : Debug: (15) # Executing section authorize from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (15) authorize { Mon Jun 15 08:29:23 2015 : Debug: (15) filter_username filter_username { Mon Jun 15 08:29:23 2015 : Debug: (15) if (!&User-Name) Mon Jun 15 08:29:23 2015 : Debug: (15) if (!&User-Name) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ / /) Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ / /) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /@.*@/ ) Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /\\.\\./ ) Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /\\.\\./ ) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) Mon Jun 15 08:29:23 2015 : Debug: (15) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /\\.$/) Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /\\.$/) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /@\\./) Mon Jun 15 08:29:23 2015 : Debug: (15) if (&User-Name =~ /@\\./) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) } # filter_username filter_username = notfound Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [preprocess] = ok Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling auth_log (rlm_detail) for request 15 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from auth_log (rlm_detail) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling chap (rlm_chap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from chap (rlm_chap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [chap] = noop Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling suffix (rlm_realm) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) suffix : Checking for suffix after "@" Mon Jun 15 08:29:23 2015 : Debug: (15) suffix : No '@' in User-Name = "host/user_host.private.com", looking up realm NULL Mon Jun 15 08:29:23 2015 : Debug: (15) suffix : No such realm "NULL" Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from suffix (rlm_realm) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [suffix] = noop Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling eap (rlm_eap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) eap : Peer sent code Response (2) ID 8 length 6 Mon Jun 15 08:29:23 2015 : Debug: (15) eap : No EAP Start, assuming it's an on-going EAP conversation Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from eap (rlm_eap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [eap] = updated Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling files (rlm_files) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from files (rlm_files) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [files] = noop Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling expiration (rlm_expiration) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from expiration (rlm_expiration) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [expiration] = noop Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling logintime (rlm_logintime) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from logintime (rlm_logintime) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [logintime] = noop Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling pap (rlm_pap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from pap (rlm_pap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [pap] = noop Mon Jun 15 08:29:23 2015 : Debug: (15) } # authorize = updated Mon Jun 15 08:29:23 2015 : Debug: (15) Found Auth-Type = EAP Mon Jun 15 08:29:23 2015 : Debug: (15) # Executing group from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (15) authenticate { Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authenticate]: calling eap (rlm_eap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) eap : Expiring EAP session with state 0x2ff6fec329fef38a Mon Jun 15 08:29:23 2015 : Debug: (15) eap : Finished EAP session with state 0x2ff6fec329fef38a Mon Jun 15 08:29:23 2015 : Debug: (15) eap : Previous EAP request found for state 0x2ff6fec329fef38a, released from the list Mon Jun 15 08:29:23 2015 : Debug: (15) eap : Peer sent method TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (15) eap : EAP TLS (13) Mon Jun 15 08:29:23 2015 : Debug: (15) eap : Calling eap_tls to process EAP data Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : Authenticate Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : processing EAP-TLS Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : Received TLS ACK Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : ACK handshake is finished Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : eaptls_verify returned 3 Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : eaptls_process returned 3 Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : Processing EAP-TLS Certificate check: Mon Jun 15 08:29:23 2015 : Debug: (15) server check-eap-tls { Mon Jun 15 08:29:23 2015 : Debug: (15) 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 = 0x020800060d00 State = 0x2ff6fec329fef38a47a41edf3f78c64e Message-Authenticator = 0xa26e3634741dd71ce9b7430d38a7e98d Event-Timestamp = 'Jun 15 2015 08:29:23 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 := 'privateOYRootCA' 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:29:23 2015 : Debug: (15) # Executing section authorize from file /etc/raddb/sites-enabled/check-eap-tls Mon Jun 15 08:29:23 2015 : Debug: (15) authorize { Mon Jun 15 08:29:23 2015 : Debug: (15) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@private\.com$/i) Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Upn} Mon Jun 15 08:29:23 2015 : Debug: (15) --> Mon Jun 15 08:29:23 2015 : Debug: (15) if ("%{TLS-Client-Cert-Subject-Alt-Name-Upn}" =~ /^([a-z0-9]|[\w\.-]?)+\@private\.com$/i) -> FALSE Mon Jun 15 08:29:23 2015 : Debug: (15) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Dns} Mon Jun 15 08:29:23 2015 : Debug: (15) --> user_host.private.com Mon Jun 15 08:29:23 2015 : Debug: (15) %{0}: Inserting new value "user_host.private.com" Mon Jun 15 08:29:23 2015 : Debug: (15) %{1}: Inserting new value "" Mon Jun 15 08:29:23 2015 : Debug: (15) %{2}: Was empty Mon Jun 15 08:29:23 2015 : Debug: (15) %{3}: Was empty Mon Jun 15 08:29:23 2015 : Debug: (15) %{4}: Was empty Mon Jun 15 08:29:23 2015 : Debug: (15) %{5}: Was empty Mon Jun 15 08:29:23 2015 : Debug: (15) %{6}: Was empty Mon Jun 15 08:29:23 2015 : Debug: (15) %{7}: Was empty Mon Jun 15 08:29:23 2015 : Debug: (15) %{8}: Was empty Mon Jun 15 08:29:23 2015 : Debug: (15) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) -> TRUE Mon Jun 15 08:29:23 2015 : Debug: (15) elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) { Mon Jun 15 08:29:23 2015 : Debug: (15) update config { Mon Jun 15 08:29:23 2015 : Debug: (15) Auth-Type := Accept Mon Jun 15 08:29:23 2015 : Debug: (15) } # update config = noop Mon Jun 15 08:29:23 2015 : Debug: (15) } # elsif ("%{TLS-Client-Cert-Subject-Alt-Name-Dns}" =~ /^([a-z0-9]|[\w\-]?)+\.private\.com$/i) = noop Mon Jun 15 08:29:23 2015 : Debug: (15) ... skipping else for request 15: Preceding "if" was taken Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: calling auth_log (rlm_detail) for request 15 Mon Jun 15 08:29:23 2015 : Debug: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: literal --> /var/log/radius/radacct/ Mon Jun 15 08:29:23 2015 : Debug: if { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IP-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: else { Mon Jun 15 08:29:23 2015 : Debug: attribute --> Packet-Src-IPv6-Address Mon Jun 15 08:29:23 2015 : Debug: } Mon Jun 15 08:29:23 2015 : Debug: literal --> /auth-detail- Mon Jun 15 08:29:23 2015 : Debug: percent --> Y Mon Jun 15 08:29:23 2015 : Debug: percent --> m Mon Jun 15 08:29:23 2015 : Debug: percent --> d Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : --> /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/192.168.104.80/auth-detail-20150615 Mon Jun 15 08:29:23 2015 : Debug: %t Mon Jun 15 08:29:23 2015 : Debug: Parsed xlat tree: Mon Jun 15 08:29:23 2015 : Debug: percent --> t Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : EXPAND %t Mon Jun 15 08:29:23 2015 : Debug: (15) auth_log : --> Mon Jun 15 08:29:23 2015 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authorize]: returned from auth_log (rlm_detail) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [auth_log] = ok Mon Jun 15 08:29:23 2015 : Debug: (15) } # authorize = ok Mon Jun 15 08:29:23 2015 : Debug: (15) Found Auth-Type = Accept Mon Jun 15 08:29:23 2015 : Debug: (15) Auth-Type = Accept, accepting the user Mon Jun 15 08:29:23 2015 : Auth: (15) 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:29:23 2015 : Debug: (15) Empty post-auth section. Using default return values. Mon Jun 15 08:29:23 2015 : Debug: (15) Reply: Mon Jun 15 08:29:23 2015 : Debug: (15) } # server check-eap-tls Mon Jun 15 08:29:23 2015 : Debug: (15) eap_tls : Saving session 5bb22b52d5ab6b8e0e2c0be1c0054e8d5e3a11198dd85a74ff14d199374706e9 vps 0x7fcd179668c0 in the cache Mon Jun 15 08:29:23 2015 : Debug: (15) eap : Freeing handler Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[authenticate]: returned from eap (rlm_eap) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [eap] = ok Mon Jun 15 08:29:23 2015 : Debug: (15) } # authenticate = ok Mon Jun 15 08:29:23 2015 : Auth: (15) 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:29:23 2015 : Debug: (15) # Executing section post-auth from file /etc/raddb/sites-enabled/default Mon Jun 15 08:29:23 2015 : Debug: (15) post-auth { Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[post-auth]: calling exec (rlm_exec) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) modsingle[post-auth]: returned from exec (rlm_exec) for request 15 Mon Jun 15 08:29:23 2015 : Debug: (15) [exec] = noop Mon Jun 15 08:29:23 2015 : Debug: (15) update reply { Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Cert-Serial} Mon Jun 15 08:29:23 2015 : Debug: (15) --> 497342570ec0c19f459efdaf66ca76cb Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "497342570ec0c19f459efdaf66ca76cb" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Cert-Expiration} Mon Jun 15 08:29:23 2015 : Debug: (15) --> 230901102449Z Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "230901102449Z" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Cert-Subject} Mon Jun 15 08:29:23 2015 : Debug: (15) --> /DC=com/DC=private/CN=RootCA Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "/DC=com/DC=private/CN=RootCA" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Cert-Issuer} Mon Jun 15 08:29:23 2015 : Debug: (15) --> /DC=com/DC=private/CN=RootCA Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "/DC=com/DC=private/CN=RootCA" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Cert-Common-Name} Mon Jun 15 08:29:23 2015 : Debug: (15) --> privateOYRootCA Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "privateOYRootCA" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Cert-Subject-Alt-Name-Email} Mon Jun 15 08:29:23 2015 : Debug: (15) --> Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Serial} Mon Jun 15 08:29:23 2015 : Debug: (15) --> 74000000528ce96f685e3bd5b2000000000052 Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "74000000528ce96f685e3bd5b2000000000052" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Expiration} Mon Jun 15 08:29:23 2015 : Debug: (15) --> 160523124059Z Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "160523124059Z" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Subject} Mon Jun 15 08:29:23 2015 : Debug: (15) --> /CN=user_host.private.com Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "/CN=user_host.private.com" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Issuer} Mon Jun 15 08:29:23 2015 : Debug: (15) --> /DC=com/DC=private/CN=RootCA Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "/DC=com/DC=private/CN=RootCA" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Common-Name} Mon Jun 15 08:29:23 2015 : Debug: (15) --> user_host.private.com Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "user_host.private.com" Mon Jun 15 08:29:23 2015 : Debug: (15) EXPAND %{TLS-Client-Cert-Subject-Alt-Name-Email} Mon Jun 15 08:29:23 2015 : Debug: (15) --> Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message += "" Mon Jun 15 08:29:23 2015 : Debug: (15) } # update reply = noop Mon Jun 15 08:29:23 2015 : Debug: (15) remove_reply_message_if_eap remove_reply_message_if_eap { Mon Jun 15 08:29:23 2015 : Debug: (15) if (&reply:EAP-Message && &reply:Reply-Message) Mon Jun 15 08:29:23 2015 : Debug: (15) if (&reply:EAP-Message && &reply:Reply-Message) -> TRUE Mon Jun 15 08:29:23 2015 : Debug: (15) if (&reply:EAP-Message && &reply:Reply-Message) { Mon Jun 15 08:29:23 2015 : Debug: (15) update reply { Mon Jun 15 08:29:23 2015 : Debug: (15) Reply-Message !* ANY Mon Jun 15 08:29:23 2015 : Debug: (15) } # update reply = noop Mon Jun 15 08:29:23 2015 : Debug: (15) } # if (&reply:EAP-Message && &reply:Reply-Message) = noop Mon Jun 15 08:29:23 2015 : Debug: (15) ... skipping else for request 15: Preceding "if" was taken Mon Jun 15 08:29:23 2015 : Debug: (15) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop Mon Jun 15 08:29:23 2015 : Debug: (15) } # post-auth = noop Mon Jun 15 08:29:23 2015 : Debug: (15) Sending Access-Accept packet to host 192.168.104.80 port 32770, id=207, length=0 Mon Jun 15 08:29:23 2015 : Debug: (15) MS-MPPE-Recv-Key = 0x954c635f76b5b2315ab3a6fd0eef6e905551bdd30051ea426ba3875367816ced Mon Jun 15 08:29:23 2015 : Debug: (15) MS-MPPE-Send-Key = 0x7c7b169d02733245414fba13e0ec8fb34ae8326d38ae950c9546b1f8b8b3d282 Mon Jun 15 08:29:23 2015 : Debug: (15) EAP-MSK = 0x954c635f76b5b2315ab3a6fd0eef6e905551bdd30051ea426ba3875367816ced7c7b169d02733245414fba13e0ec8fb34ae8326d38ae950c9546b1f8b8b3d282 Mon Jun 15 08:29:23 2015 : Debug: (15) EAP-EMSK = 0x8ce50db176489e661a20087029b11c9a8d5ebf8bf7edd6fe8cfebd467a7cd62ba890b850d5f9604f965d1be1cee3ab6f95e99d111b2f1f3219ccddff652f3a8a Mon Jun 15 08:29:23 2015 : Debug: (15) EAP-Session-Id = 0x0d557e62b345b223d0569417f5ad6c0de03cbc7a20c5d5efd1c4fbab8d1b3e4484557e62b321a4be97e0cbac1a0a6804725285353b46d83c89e338c13292c34e79 Mon Jun 15 08:29:23 2015 : Debug: (15) EAP-Message = 0x03080004 Mon Jun 15 08:29:23 2015 : Debug: (15) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 15 08:29:23 2015 : Debug: (15) User-Name = 'host/user_host.private.com' Sending Access-Accept Id 207 from 192.168.106.130:1812 to 192.168.104.80:32770 MS-MPPE-Recv-Key = 0x954c635f76b5b2315ab3a6fd0eef6e905551bdd30051ea426ba3875367816ced MS-MPPE-Send-Key = 0x7c7b169d02733245414fba13e0ec8fb34ae8326d38ae950c9546b1f8b8b3d282 EAP-Message = 0x03080004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = 'host/user_host.private.com' Mon Jun 15 08:29:23 2015 : Debug: (15) Finished request Mon Jun 15 08:29:23 2015 : Debug: Waking up in 0.5 seconds. Mon Jun 15 08:29:24 2015 : Debug: Waking up in 4.2 seconds. Mon Jun 15 08:29:28 2015 : Debug: (8) Cleaning up request packet ID 200 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Debug: (9) Cleaning up request packet ID 201 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Debug: (10) Cleaning up request packet ID 202 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Debug: (11) Cleaning up request packet ID 203 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Debug: (12) Cleaning up request packet ID 204 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Debug: (13) Cleaning up request packet ID 205 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Debug: (14) Cleaning up request packet ID 206 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Debug: (15) Cleaning up request packet ID 207 with timestamp +1514 Mon Jun 15 08:29:28 2015 : Info: Ready to process requests