Hi We had installed the freeradius 3.0.8 in our redhat machine but the certificate is not getting authenticated . the logs are in line along with this mail .this machine previously was running freeradius older version which was working fine .please help us resolve this issue . Thanks Latheef.S logs attached =========== n Jun 8 05:57:20 2015 : Debug: (151) EAP-Message = 0x019603ec19c00000093416030100510200004d030155756700e53bdacb99665df630bde73d39d1c5c6fce32ea9d05be3e568648039201e7488ca35449034fe49d15fb01baa51f3c1aa01f3a3c21555b9c302f338fbc20035000005ff0100010016030108d00b0008cc0008c90003de308203da308202c2 Mon Jun 8 05:57:20 2015 : Debug: (151) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 8 05:57:20 2015 : Debug: (151) State = 0x209817dc210e0ee756ad6df1b14e725e Mon Jun 8 05:57:20 2015 : Debug: (151) Finished request Mon Jun 8 05:57:20 2015 : Debug: Waking up in 4.9 seconds. Mon Jun 8 05:57:20 2015 : Debug: (152) Received Access-Request Id 48 from 192.168.3.201:1024 to 192.168.3.48:1812 length 225 Mon Jun 8 05:57:20 2015 : Debug: (152) Framed-MTU = 1480 Mon Jun 8 05:57:20 2015 : Debug: (152) NAS-IP-Address = 192.168.3.201 Mon Jun 8 05:57:20 2015 : Debug: (152) NAS-Identifier = 'HP ProCurve Switch 2824' Mon Jun 8 05:57:20 2015 : Debug: (152) User-Name = 'ctc' Mon Jun 8 05:57:20 2015 : Debug: (152) Service-Type = Framed-User Mon Jun 8 05:57:20 2015 : Debug: (152) Framed-Protocol = PPP Mon Jun 8 05:57:20 2015 : Debug: (152) NAS-Port = 2 Mon Jun 8 05:57:20 2015 : Debug: (152) NAS-Port-Type = Ethernet Mon Jun 8 05:57:20 2015 : Debug: (152) NAS-Port-Id = '2' Mon Jun 8 05:57:20 2015 : Debug: (152) Called-Station-Id = '00-0e-7f-c4-98-60' Mon Jun 8 05:57:20 2015 : Debug: (152) Calling-Station-Id = '50-65-f3-5c-e9-ed' Mon Jun 8 05:57:20 2015 : Debug: (152) Connect-Info = 'CONNECT Ethernet 1000Mbps Full duplex' Mon Jun 8 05:57:20 2015 : Debug: (152) Tunnel-Type:0 = VLAN Mon Jun 8 05:57:20 2015 : Debug: (152) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 8 05:57:20 2015 : Debug: (152) Tunnel-Private-Group-Id:0 = '1' Mon Jun 8 05:57:20 2015 : Debug: (152) State = 0x209817dc210e0ee756ad6df1b14e725e Mon Jun 8 05:57:20 2015 : Debug: (152) EAP-Message = 0x029600061900 Mon Jun 8 05:57:20 2015 : Debug: (152) Message-Authenticator = 0x39b1ce0cd6391f6f3c41fa7b4bb58913 Mon Jun 8 05:57:20 2015 : Debug: (152) session-state: No cached attributes Mon Jun 8 05:57:20 2015 : Debug: (152) # Executing section authorize from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (152) authorize { Mon Jun 8 05:57:20 2015 : Debug: (152) policy filter_username { Mon Jun 8 05:57:20 2015 : Debug: (152) if (!&User-Name) { Mon Jun 8 05:57:20 2015 : Debug: (152) if (!&User-Name) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ / /) { Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ / /) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /@.*@/ ) { Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /\.\./ ) { Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /\.\./ ) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (152) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Mon Jun 8 05:57:20 2015 : Debug: (152) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /\.$/) { Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /\.$/) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /@\./) { Mon Jun 8 05:57:20 2015 : Debug: (152) if (&User-Name =~ /@\./) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (152) } # policy filter_username = notfound Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) [preprocess] = ok Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: calling chap (rlm_chap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: returned from chap (rlm_chap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) [chap] = noop Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: calling mschap (rlm_mschap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: returned from mschap (rlm_mschap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) [mschap] = noop Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: calling digest (rlm_digest) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: returned from digest (rlm_digest) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) [digest] = noop Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: calling suffix (rlm_realm) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) suffix: Checking for suffix after "@" Mon Jun 8 05:57:20 2015 : Debug: (152) suffix: No '@' in User-Name = "ctc", looking up realm NULL Mon Jun 8 05:57:20 2015 : Debug: (152) suffix: No such realm "NULL" Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: returned from suffix (rlm_realm) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) [suffix] = noop Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: calling eap (rlm_eap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) eap: Peer sent code Response (2) ID 150 length 6 Mon Jun 8 05:57:20 2015 : Debug: (152) eap: Continuing tunnel setup Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authorize]: returned from eap (rlm_eap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) [eap] = ok Mon Jun 8 05:57:20 2015 : Debug: (152) } # authorize = ok Mon Jun 8 05:57:20 2015 : Debug: (152) Found Auth-Type = EAP Mon Jun 8 05:57:20 2015 : Debug: (152) # Executing group from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (152) authenticate { Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authenticate]: calling eap (rlm_eap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) eap: Expiring EAP session with state 0x209817dc210e0ee7 Mon Jun 8 05:57:20 2015 : Debug: (152) eap: Finished EAP session with state 0x209817dc210e0ee7 Mon Jun 8 05:57:20 2015 : Debug: (152) eap: Previous EAP request found for state 0x209817dc210e0ee7, released from the list Mon Jun 8 05:57:20 2015 : Debug: (152) eap: Peer sent method PEAP (25) Mon Jun 8 05:57:20 2015 : Debug: (152) eap: EAP PEAP (25) Mon Jun 8 05:57:20 2015 : Debug: (152) eap: Calling eap_peap to process EAP data Mon Jun 8 05:57:20 2015 : Debug: (152) eap_peap: processing EAP-TLS Mon Jun 8 05:57:20 2015 : Debug: (152) eap_peap: Received TLS ACK Mon Jun 8 05:57:20 2015 : Debug: (152) eap_peap: Received TLS ACK Mon Jun 8 05:57:20 2015 : Debug: (152) eap_peap: ACK handshake fragment handler Mon Jun 8 05:57:20 2015 : Debug: (152) eap_peap: eaptls_verify returned 1 Mon Jun 8 05:57:20 2015 : Debug: (152) eap_peap: eaptls_process returned 13 Mon Jun 8 05:57:20 2015 : Debug: (152) eap_peap: FR_TLS_HANDLED Mon Jun 8 05:57:20 2015 : Debug: (152) eap: EAP session adding &reply:State = 0x209817dc220f0ee7 Mon Jun 8 05:57:20 2015 : Debug: (152) modsingle[authenticate]: returned from eap (rlm_eap) for request 152 Mon Jun 8 05:57:20 2015 : Debug: (152) [eap] = handled Mon Jun 8 05:57:20 2015 : Debug: (152) } # authenticate = handled Mon Jun 8 05:57:20 2015 : Debug: (152) Using Post-Auth-Type Challenge Mon Jun 8 05:57:20 2015 : Debug: (152) Post-Auth-Type sub-section not found. Ignoring. Mon Jun 8 05:57:20 2015 : Debug: (152) # Executing group from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (152) session-state: Nothing to cache Mon Jun 8 05:57:20 2015 : Debug: (152) Sent Access-Challenge Id 48 from 192.168.3.48:1812 to 192.168.3.201:1024 length 0 Mon Jun 8 05:57:20 2015 : Debug: (152) EAP-Message = 0x019703e81940d027670910cd24815ce68c509691a6027d4d32c742fd2152db96203c01477e40e1fb397b2d854dadef536faac0190c02f09dadbd8c92c64b0f874bc4cd223be761823ab9c83910b648daf987435b98be5aca01f12238ff7c9651390663cfd2b91b0004e5308204e1308203c9a003020102 Mon Jun 8 05:57:20 2015 : Debug: (152) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 8 05:57:20 2015 : Debug: (152) State = 0x209817dc220f0ee756ad6df1b14e725e Mon Jun 8 05:57:20 2015 : Debug: (152) Finished request Mon Jun 8 05:57:20 2015 : Debug: Waking up in 4.9 seconds. Mon Jun 8 05:57:20 2015 : Debug: (153) Received Access-Request Id 49 from 192.168.3.201:1024 to 192.168.3.48:1812 length 225 Mon Jun 8 05:57:20 2015 : Debug: (153) Framed-MTU = 1480 Mon Jun 8 05:57:20 2015 : Debug: (153) NAS-IP-Address = 192.168.3.201 Mon Jun 8 05:57:20 2015 : Debug: (153) NAS-Identifier = 'HP ProCurve Switch 2824' Mon Jun 8 05:57:20 2015 : Debug: (153) User-Name = 'ctc' Mon Jun 8 05:57:20 2015 : Debug: (153) Service-Type = Framed-User Mon Jun 8 05:57:20 2015 : Debug: (153) Framed-Protocol = PPP Mon Jun 8 05:57:20 2015 : Debug: (153) NAS-Port = 2 Mon Jun 8 05:57:20 2015 : Debug: (153) NAS-Port-Type = Ethernet Mon Jun 8 05:57:20 2015 : Debug: (153) NAS-Port-Id = '2' Mon Jun 8 05:57:20 2015 : Debug: (153) Called-Station-Id = '00-0e-7f-c4-98-60' Mon Jun 8 05:57:20 2015 : Debug: (153) Calling-Station-Id = '50-65-f3-5c-e9-ed' Mon Jun 8 05:57:20 2015 : Debug: (153) Connect-Info = 'CONNECT Ethernet 1000Mbps Full duplex' Mon Jun 8 05:57:20 2015 : Debug: (153) Tunnel-Type:0 = VLAN Mon Jun 8 05:57:20 2015 : Debug: (153) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 8 05:57:20 2015 : Debug: (153) Tunnel-Private-Group-Id:0 = '1' Mon Jun 8 05:57:20 2015 : Debug: (153) State = 0x209817dc220f0ee756ad6df1b14e725e Mon Jun 8 05:57:20 2015 : Debug: (153) EAP-Message = 0x029700061900 Mon Jun 8 05:57:20 2015 : Debug: (153) Message-Authenticator = 0xdc642a3312c2b7a0bf5c5700b86cc72f Mon Jun 8 05:57:20 2015 : Debug: (153) session-state: No cached attributes Mon Jun 8 05:57:20 2015 : Debug: (153) # Executing section authorize from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (153) authorize { Mon Jun 8 05:57:20 2015 : Debug: (153) policy filter_username { Mon Jun 8 05:57:20 2015 : Debug: (153) if (!&User-Name) { Mon Jun 8 05:57:20 2015 : Debug: (153) if (!&User-Name) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ / /) { Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ / /) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /@.*@/ ) { Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /\.\./ ) { Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /\.\./ ) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (153) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Mon Jun 8 05:57:20 2015 : Debug: (153) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /\.$/) { Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /\.$/) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /@\./) { Mon Jun 8 05:57:20 2015 : Debug: (153) if (&User-Name =~ /@\./) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (153) } # policy filter_username = notfound Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) [preprocess] = ok Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: calling chap (rlm_chap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: returned from chap (rlm_chap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) [chap] = noop Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: calling mschap (rlm_mschap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: returned from mschap (rlm_mschap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) [mschap] = noop Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: calling digest (rlm_digest) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: returned from digest (rlm_digest) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) [digest] = noop Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: calling suffix (rlm_realm) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) suffix: Checking for suffix after "@" Mon Jun 8 05:57:20 2015 : Debug: (153) suffix: No '@' in User-Name = "ctc", looking up realm NULL Mon Jun 8 05:57:20 2015 : Debug: (153) suffix: No such realm "NULL" Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: returned from suffix (rlm_realm) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) [suffix] = noop Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: calling eap (rlm_eap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) eap: Peer sent code Response (2) ID 151 length 6 Mon Jun 8 05:57:20 2015 : Debug: (153) eap: Continuing tunnel setup Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authorize]: returned from eap (rlm_eap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) [eap] = ok Mon Jun 8 05:57:20 2015 : Debug: (153) } # authorize = ok Mon Jun 8 05:57:20 2015 : Debug: (153) Found Auth-Type = EAP Mon Jun 8 05:57:20 2015 : Debug: (153) # Executing group from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (153) authenticate { Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authenticate]: calling eap (rlm_eap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) eap: Expiring EAP session with state 0x209817dc220f0ee7 Mon Jun 8 05:57:20 2015 : Debug: (153) eap: Finished EAP session with state 0x209817dc220f0ee7 Mon Jun 8 05:57:20 2015 : Debug: (153) eap: Previous EAP request found for state 0x209817dc220f0ee7, released from the list Mon Jun 8 05:57:20 2015 : Debug: (153) eap: Peer sent method PEAP (25) Mon Jun 8 05:57:20 2015 : Debug: (153) eap: EAP PEAP (25) Mon Jun 8 05:57:20 2015 : Debug: (153) eap: Calling eap_peap to process EAP data Mon Jun 8 05:57:20 2015 : Debug: (153) eap_peap: processing EAP-TLS Mon Jun 8 05:57:20 2015 : Debug: (153) eap_peap: Received TLS ACK Mon Jun 8 05:57:20 2015 : Debug: (153) eap_peap: Received TLS ACK Mon Jun 8 05:57:20 2015 : Debug: (153) eap_peap: ACK handshake fragment handler Mon Jun 8 05:57:20 2015 : Debug: (153) eap_peap: eaptls_verify returned 1 Mon Jun 8 05:57:20 2015 : Debug: (153) eap_peap: eaptls_process returned 13 Mon Jun 8 05:57:20 2015 : Debug: (153) eap_peap: FR_TLS_HANDLED Mon Jun 8 05:57:20 2015 : Debug: (153) eap: EAP session adding &reply:State = 0x209817dc23000ee7 Mon Jun 8 05:57:20 2015 : Debug: (153) modsingle[authenticate]: returned from eap (rlm_eap) for request 153 Mon Jun 8 05:57:20 2015 : Debug: (153) [eap] = handled Mon Jun 8 05:57:20 2015 : Debug: (153) } # authenticate = handled Mon Jun 8 05:57:20 2015 : Debug: (153) Using Post-Auth-Type Challenge Mon Jun 8 05:57:20 2015 : Debug: (153) Post-Auth-Type sub-section not found. Ignoring. Mon Jun 8 05:57:20 2015 : Debug: (153) # Executing group from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (153) session-state: Nothing to cache Mon Jun 8 05:57:20 2015 : Debug: (153) Sent Access-Challenge Id 49 from 192.168.3.48:1812 to 192.168.3.201:1024 length 0 Mon Jun 8 05:57:20 2015 : Debug: (153) EAP-Message = 0x0198017619007479820900c7ba6febe19fb88e300c0603551d13040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d010105050003820101004aeb0a79893906ef633d Mon Jun 8 05:57:20 2015 : Debug: (153) Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 8 05:57:20 2015 : Debug: (153) State = 0x209817dc23000ee756ad6df1b14e725e Mon Jun 8 05:57:20 2015 : Debug: (153) Finished request Mon Jun 8 05:57:20 2015 : Debug: Waking up in 4.9 seconds. Mon Jun 8 05:57:20 2015 : Debug: (154) Received Access-Request Id 50 from 192.168.3.201:1024 to 192.168.3.48:1812 length 225 Mon Jun 8 05:57:20 2015 : Debug: (154) Framed-MTU = 1480 Mon Jun 8 05:57:20 2015 : Debug: (154) NAS-IP-Address = 192.168.3.201 Mon Jun 8 05:57:20 2015 : Debug: (154) NAS-Identifier = 'HP ProCurve Switch 2824' Mon Jun 8 05:57:20 2015 : Debug: (154) User-Name = 'ctc' Mon Jun 8 05:57:20 2015 : Debug: (154) Service-Type = Framed-User Mon Jun 8 05:57:20 2015 : Debug: (154) Framed-Protocol = PPP Mon Jun 8 05:57:20 2015 : Debug: (154) NAS-Port = 2 Mon Jun 8 05:57:20 2015 : Debug: (154) NAS-Port-Type = Ethernet Mon Jun 8 05:57:20 2015 : Debug: (154) NAS-Port-Id = '2' Mon Jun 8 05:57:20 2015 : Debug: (154) Called-Station-Id = '00-0e-7f-c4-98-60' Mon Jun 8 05:57:20 2015 : Debug: (154) Calling-Station-Id = '50-65-f3-5c-e9-ed' Mon Jun 8 05:57:20 2015 : Debug: (154) Connect-Info = 'CONNECT Ethernet 1000Mbps Full duplex' Mon Jun 8 05:57:20 2015 : Debug: (154) Tunnel-Type:0 = VLAN Mon Jun 8 05:57:20 2015 : Debug: (154) Tunnel-Medium-Type:0 = IEEE-802 Mon Jun 8 05:57:20 2015 : Debug: (154) Tunnel-Private-Group-Id:0 = '1' Mon Jun 8 05:57:20 2015 : Debug: (154) State = 0x209817dc23000ee756ad6df1b14e725e Mon Jun 8 05:57:20 2015 : Debug: (154) EAP-Message = 0x029800060319 Mon Jun 8 05:57:20 2015 : Debug: (154) Message-Authenticator = 0xb4daff305fd89d80c104cb751486a1d1 Mon Jun 8 05:57:20 2015 : Debug: (154) session-state: No cached attributes Mon Jun 8 05:57:20 2015 : Debug: (154) # Executing section authorize from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (154) authorize { Mon Jun 8 05:57:20 2015 : Debug: (154) policy filter_username { Mon Jun 8 05:57:20 2015 : Debug: (154) if (!&User-Name) { Mon Jun 8 05:57:20 2015 : Debug: (154) if (!&User-Name) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ / /) { Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ / /) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /@.*@/ ) { Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /@.*@/ ) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /\.\./ ) { Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /\.\./ ) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { Mon Jun 8 05:57:20 2015 : Debug: (154) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /\.$/) { Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /\.$/) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /@\./) { Mon Jun 8 05:57:20 2015 : Debug: (154) if (&User-Name =~ /@\./) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) } # policy filter_username = notfound Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling preprocess (rlm_preprocess) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [preprocess] = ok Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling chap (rlm_chap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from chap (rlm_chap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [chap] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling mschap (rlm_mschap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from mschap (rlm_mschap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [mschap] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling digest (rlm_digest) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from digest (rlm_digest) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [digest] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling suffix (rlm_realm) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) suffix: Checking for suffix after "@" Mon Jun 8 05:57:20 2015 : Debug: (154) suffix: No '@' in User-Name = "ctc", looking up realm NULL Mon Jun 8 05:57:20 2015 : Debug: (154) suffix: No such realm "NULL" Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from suffix (rlm_realm) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [suffix] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling eap (rlm_eap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) eap: Peer sent code Response (2) ID 152 length 6 Mon Jun 8 05:57:20 2015 : Debug: (154) eap: No EAP Start, assuming it's an on-going EAP conversation Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from eap (rlm_eap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [eap] = updated Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling files (rlm_files) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) files: users: Matched entry DEFAULT at line 182 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from files (rlm_files) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [files] = ok Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling expiration (rlm_expiration) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from expiration (rlm_expiration) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [expiration] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling logintime (rlm_logintime) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from logintime (rlm_logintime) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [logintime] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: calling pap (rlm_pap) for request 154 Mon Jun 8 05:57:20 2015 : WARNING: (154) pap: No "known good" password found for the user. Not setting Auth-Type Mon Jun 8 05:57:20 2015 : WARNING: (154) pap: Authentication will fail unless a "known good" password is available Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authorize]: returned from pap (rlm_pap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [pap] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) } # authorize = updated Mon Jun 8 05:57:20 2015 : Debug: (154) Found Auth-Type = EAP Mon Jun 8 05:57:20 2015 : Debug: (154) # Executing group from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (154) authenticate { Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authenticate]: calling eap (rlm_eap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) eap: Expiring EAP session with state 0x209817dc23000ee7 Mon Jun 8 05:57:20 2015 : Debug: (154) eap: Finished EAP session with state 0x209817dc23000ee7 Mon Jun 8 05:57:20 2015 : Debug: (154) eap: Previous EAP request found for state 0x209817dc23000ee7, released from the list Mon Jun 8 05:57:20 2015 : Debug: (154) eap: Peer sent method NAK (3) Mon Jun 8 05:57:20 2015 : Debug: (154) eap: Peer NAK'd our request for PEAP (25) with a request for PEAP (25), skipping... Mon Jun 8 05:57:20 2015 : ERROR: (154) eap: No mutually acceptable types found Mon Jun 8 05:57:20 2015 : Debug: (154) eap: Failed in EAP select Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[authenticate]: returned from eap (rlm_eap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [eap] = invalid Mon Jun 8 05:57:20 2015 : Debug: (154) } # authenticate = invalid Mon Jun 8 05:57:20 2015 : Debug: (154) Failed to authenticate the user Mon Jun 8 05:57:20 2015 : Debug: (154) Using Post-Auth-Type Reject Mon Jun 8 05:57:20 2015 : Debug: (154) # Executing group from file /root/etc/raddb/sites-enabled/default Mon Jun 8 05:57:20 2015 : Debug: (154) Post-Auth-Type REJECT { Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[post-auth]: calling attr_filter.access_reject (rlm_attr_filter) for request 154 Mon Jun 8 05:57:20 2015 : Debug: %{User-Name} Mon Jun 8 05:57:20 2015 : Debug: Parsed xlat tree: Mon Jun 8 05:57:20 2015 : Debug: attribute --> User-Name Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: EXPAND %{User-Name} Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: --> ctc Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: Matched entry DEFAULT at line 18 Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: Attribute "Framed-Protocol" allowed by 0 rules, disallowed by 0 rules Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: Attribute "Framed-Compression" allowed by 0 rules, disallowed by 0 rules Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: EAP-Message = 0x04980004 allowed by EAP-Message =* 0x Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: Attribute "EAP-Message" allowed by 1 rules, disallowed by 0 rules Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: Message-Authenticator = 0x00000000000000000000000000000000 allowed by Message-Authenticator =* 0x Mon Jun 8 05:57:20 2015 : Debug: (154) attr_filter.access_reject: Attribute "Message-Authenticator" allowed by 1 rules, disallowed by 0 rules Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[post-auth]: returned from attr_filter.access_reject (rlm_attr_filter) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [attr_filter.access_reject] = updated Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[post-auth]: calling eap (rlm_eap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[post-auth]: returned from eap (rlm_eap) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [eap] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) policy remove_reply_message_if_eap { Mon Jun 8 05:57:20 2015 : Debug: (154) if (&reply:EAP-Message && &reply:Reply-Message) { Mon Jun 8 05:57:20 2015 : Debug: (154) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Mon Jun 8 05:57:20 2015 : Debug: (154) else { Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[post-auth]: calling noop (rlm_always) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) modsingle[post-auth]: returned from noop (rlm_always) for request 154 Mon Jun 8 05:57:20 2015 : Debug: (154) [noop] = noop Mon Jun 8 05:57:20 2015 : Debug: (154) } # else = noop Mon Jun 8 05:57:20 2015 : Debug: (154) } # policy remove_reply_message_if_eap = noop Mon Jun 8 05:57:20 2015 : Debug: (154) } # Post-Auth-Type REJECT = updated Mon Jun 8 05:57:20 2015 : Debug: (154) Delaying response for 1.000000 seconds Mon Jun 8 05:57:20 2015 : Debug: Waking up in 0.3 seconds. Mon Jun 8 05:57:20 2015 : Debug: Waking up in 0.6 seconds. Mon Jun 8 05:57:21 2015 : Debug: (154) <delay>: Sending delayed response Mon Jun 8 05:57:21 2015 : Debug: (154) <delay>: Sent Access-Reject Id 50 from 192.168.3.48:1812 to 192.168.3.201:1024 length 44 Mon Jun 8 05:57:21 2015 : Debug: (154) <delay>: EAP-Message = 0x04980004 Mon Jun 8 05:57:21 2015 : Debug: (154) <delay>: Message-Authenticator = 0x00000000000000000000000000000000 Mon Jun 8 05:57:21 2015 : Debug: Waking up in 3.9 seconds. Mon Jun 8 05:57:25 2015 : Debug: (151) <done>: Cleaning up request packet ID 47 with timestamp +1844 Mon Jun 8 05:57:25 2015 : Debug: (152) <done>: Cleaning up request packet ID 48 with timestamp +1844 Mon Jun 8 05:57:25 2015 : Debug: (153) <done>: Cleaning up request packet ID 49 with timestamp +1844 Mon Jun 8 05:57:25 2015 : Debug: (154) <delay>: Cleaning up request packet ID 50 with timestamp +1844 Mon Jun 8 05:57:25 2015 : Debug: Waking up in 4.7 seconds. Mon Jun 8 05:57:29 2015 : Debug: (150) <done>: Cleaning up request packet ID 46 with timestamp +1838 Mon Jun 8 05:57:29 2015 : Info: Ready to process requests