wrong password failures not logged
Hi, I'm trying FreeRADIUS Version 3.0.10. I've realized that quite often when users fail authentication due to wrong password this does not result in a "Login incorrect" message in the logs. When the password is set to the correct value again a "Login OK" appears in the logs. It looks like the session hangs. I was able to reproduce the behaviour on an android phone and this is the output of radiusd -X (NT and SHA1 hashes obscured). Any help would be greatly appreciated. Thanks, Stefano (0) Received Access-Request Id 175 from 147.162.234.209:32776 to 147.162.57.7:1812 length 288 (0) User-Name = "stefano.zanmarchi@unipd.it" (0) Chargeable-User-Identity = 0x00 (0) Location-Capable = Civix-Location (0) Calling-Station-Id = "64-89-9a-1f-93-d6" (0) Called-Station-Id = "AP-GROUP-CSIA" (0) NAS-Port = 1 (0) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (0) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (0) NAS-IP-Address = 147.162.234.209 (0) NAS-Identifier = "WLC" (0) Airespace-Wlan-Id = 6 (0) Service-Type = Framed-User (0) Framed-MTU = 1300 (0) NAS-Port-Type = Wireless-802.11 (0) Tunnel-Type:0 = VLAN (0) Tunnel-Medium-Type:0 = IEEE-802 (0) Tunnel-Private-Group-Id:0 = "83" (0) EAP-Message = 0x0201001f0173746566616e6f2e7a616e6d617263686940756e6970642e6974 (0) Message-Authenticator = 0xccfded3b06bc9f6779fc4d3a25cd8c28 (0) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (0) authorize { (0) policy filter_username { (0) if (!&User-Name) { (0) if (!&User-Name) -> FALSE (0) if (&User-Name =~ / /) { (0) if (&User-Name =~ / /) -> FALSE (0) if (&User-Name =~ /@.*@/ ) { (0) if (&User-Name =~ /@.*@/ ) -> FALSE (0) if (&User-Name =~ /\.\./ ) { (0) if (&User-Name =~ /\.\./ ) -> FALSE (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (0) if (&User-Name =~ /\.$/) { (0) if (&User-Name =~ /\.$/) -> FALSE (0) if (&User-Name =~ /@\./) { (0) if (&User-Name =~ /@\./) -> FALSE (0) } # policy filter_username = notfound (0) [preprocess] = ok (0) suffix: Checking for suffix after "@" (0) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (0) suffix: Found realm "unipd.it" (0) suffix: Adding Realm = "unipd.it" (0) suffix: Authentication realm is LOCAL (0) [suffix] = ok (0) eap: Peer sent EAP Response (code 2) ID 1 length 31 (0) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (0) [eap] = ok (0) } # authorize = ok (0) Found Auth-Type = EAP (0) # Executing group from file /etc/freeradius/sites-enabled/eduroam (0) authenticate { (0) eap: Peer sent packet with method EAP Identity (1) (0) eap: Calling submodule eap_peap to process data (0) eap_peap: Initiating new EAP-TLS session (0) eap_peap: [eaptls start] = request (0) eap: Sending EAP Request (code 1) ID 2 length 6 (0) eap: EAP session adding &reply:State = 0x3adf3a9e3add23ab (0) [eap] = handled (0) } # authenticate = handled (0) Using Post-Auth-Type Challenge (0) Post-Auth-Type sub-section not found. Ignoring. (0) # Executing group from file /etc/freeradius/sites-enabled/eduroam (0) Sent Access-Challenge Id 175 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (0) EAP-Message = 0x010200061920 (0) Message-Authenticator = 0x00000000000000000000000000000000 (0) State = 0x3adf3a9e3add23abadde1d2911153d2e (0) Finished request Waking up in 4.9 seconds. (1) Received Access-Request Id 176 from 147.162.234.209:32776 to 147.162.57.7:1812 length 483 (1) User-Name = "stefano.zanmarchi@unipd.it" (1) Chargeable-User-Identity = 0x00 (1) Location-Capable = Civix-Location (1) Calling-Station-Id = "64-89-9a-1f-93-d6" (1) Called-Station-Id = "AP-GROUP-CSIA" (1) NAS-Port = 1 (1) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (1) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (1) NAS-IP-Address = 147.162.234.209 (1) NAS-Identifier = "WLC" (1) Airespace-Wlan-Id = 6 (1) Service-Type = Framed-User (1) Framed-MTU = 1300 (1) NAS-Port-Type = Wireless-802.11 (1) Tunnel-Type:0 = VLAN (1) Tunnel-Medium-Type:0 = IEEE-802 (1) Tunnel-Private-Group-Id:0 = "83" (1) EAP-Message = 0x020200d01980000000c616030100c1010000bd0301969c67acc968dbc4ad3c8d94b9ae9db616fe9fb1316dcdff20d19c913c051c90000054c014c00ac022c02100390038c00fc0050035c012c008c01cc01b00160013c00dc003000ac013c009c01fc01e00330032c00ec004002fc011c007c00cc00200 (1) State = 0x3adf3a9e3add23abadde1d2911153d2e (1) Message-Authenticator = 0xb3a4502bf04b94541918ffd352911106 (1) session-state: No cached attributes (1) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (1) authorize { (1) policy filter_username { (1) if (!&User-Name) { (1) if (!&User-Name) -> FALSE (1) if (&User-Name =~ / /) { (1) if (&User-Name =~ / /) -> FALSE (1) if (&User-Name =~ /@.*@/ ) { (1) if (&User-Name =~ /@.*@/ ) -> FALSE (1) if (&User-Name =~ /\.\./ ) { (1) if (&User-Name =~ /\.\./ ) -> FALSE (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (1) if (&User-Name =~ /\.$/) { (1) if (&User-Name =~ /\.$/) -> FALSE (1) if (&User-Name =~ /@\./) { (1) if (&User-Name =~ /@\./) -> FALSE (1) } # policy filter_username = notfound (1) [preprocess] = ok (1) suffix: Checking for suffix after "@" (1) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (1) suffix: Found realm "unipd.it" (1) suffix: Adding Realm = "unipd.it" (1) suffix: Authentication realm is LOCAL (1) [suffix] = ok (1) eap: Peer sent EAP Response (code 2) ID 2 length 208 (1) eap: Continuing tunnel setup (1) [eap] = ok (1) } # authorize = ok (1) Found Auth-Type = EAP (1) # Executing group from file /etc/freeradius/sites-enabled/eduroam (1) authenticate { (1) eap: Expiring EAP session with state 0x3adf3a9e3add23ab (1) eap: Finished EAP session with state 0x3adf3a9e3add23ab (1) eap: Previous EAP request found for state 0x3adf3a9e3add23ab, released from the list (1) eap: Peer sent packet with method EAP PEAP (25) (1) eap: Calling submodule eap_peap to process data (1) eap_peap: Continuing EAP-TLS (1) eap_peap: Peer indicated complete TLS record size will be 198 bytes (1) eap_peap: Got complete TLS record (198 bytes) (1) eap_peap: [eaptls verify] = length included (1) eap_peap: (other): before/accept initialization (1) eap_peap: TLS_accept: before/accept initialization (1) eap_peap: <<< TLS 1.0 Handshake [length 00c1], ClientHello (1) eap_peap: TLS_accept: unknown state (1) eap_peap: >>> TLS 1.0 Handshake [length 0039], ServerHello (1) eap_peap: TLS_accept: unknown state (1) eap_peap: >>> TLS 1.0 Handshake [length 0872], Certificate (1) eap_peap: TLS_accept: unknown state (1) eap_peap: >>> TLS 1.0 Handshake [length 014b], ServerKeyExchange (1) eap_peap: TLS_accept: unknown state (1) eap_peap: >>> TLS 1.0 Handshake [length 0004], ServerHelloDone (1) eap_peap: TLS_accept: unknown state (1) eap_peap: TLS_accept: unknown state (1) eap_peap: TLS_accept: Need to read more data: unknown state (1) eap_peap: TLS_accept: Need to read more data: unknown state (1) eap_peap: In SSL Handshake Phase (1) eap_peap: In SSL Accept mode (1) eap_peap: [eaptls process] = handled (1) eap: Sending EAP Request (code 1) ID 3 length 1004 (1) eap: EAP session adding &reply:State = 0x3adf3a9e3bdc23ab (1) [eap] = handled (1) } # authenticate = handled (1) Using Post-Auth-Type Challenge (1) Post-Auth-Type sub-section not found. Ignoring. (1) # Executing group from file /etc/freeradius/sites-enabled/eduroam (1) Sent Access-Challenge Id 176 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (1) EAP-Message = 0x010303ec19c000000a0e1603010039020000350301b7177f6d9e3032797230a6f3413574a730725e60992ed9d439c00a787b088f4000c01400000dff01000100000b00040300010216030108720b00086e00086b0003cf308203cb308202b3a003020102020101300d06092a864886f70d010105050030 (1) Message-Authenticator = 0x00000000000000000000000000000000 (1) State = 0x3adf3a9e3bdc23abadde1d2911153d2e (1) Finished request Waking up in 4.9 seconds. (2) Received Access-Request Id 177 from 147.162.234.209:32776 to 147.162.57.7:1812 length 281 (2) User-Name = "stefano.zanmarchi@unipd.it" (2) Chargeable-User-Identity = 0x00 (2) Location-Capable = Civix-Location (2) Calling-Station-Id = "64-89-9a-1f-93-d6" (2) Called-Station-Id = "AP-GROUP-CSIA" (2) NAS-Port = 1 (2) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (2) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (2) NAS-IP-Address = 147.162.234.209 (2) NAS-Identifier = "WLC" (2) Airespace-Wlan-Id = 6 (2) Service-Type = Framed-User (2) Framed-MTU = 1300 (2) NAS-Port-Type = Wireless-802.11 (2) Tunnel-Type:0 = VLAN (2) Tunnel-Medium-Type:0 = IEEE-802 (2) Tunnel-Private-Group-Id:0 = "83" (2) EAP-Message = 0x020300061900 (2) State = 0x3adf3a9e3bdc23abadde1d2911153d2e (2) Message-Authenticator = 0xcb6416eeff83d20ed4309fb25316a8ba (2) session-state: No cached attributes (2) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (2) authorize { (2) policy filter_username { (2) if (!&User-Name) { (2) if (!&User-Name) -> FALSE (2) if (&User-Name =~ / /) { (2) if (&User-Name =~ / /) -> FALSE (2) if (&User-Name =~ /@.*@/ ) { (2) if (&User-Name =~ /@.*@/ ) -> FALSE (2) if (&User-Name =~ /\.\./ ) { (2) if (&User-Name =~ /\.\./ ) -> FALSE (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (2) if (&User-Name =~ /\.$/) { (2) if (&User-Name =~ /\.$/) -> FALSE (2) if (&User-Name =~ /@\./) { (2) if (&User-Name =~ /@\./) -> FALSE (2) } # policy filter_username = notfound (2) [preprocess] = ok (2) suffix: Checking for suffix after "@" (2) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (2) suffix: Found realm "unipd.it" (2) suffix: Adding Realm = "unipd.it" (2) suffix: Authentication realm is LOCAL (2) [suffix] = ok (2) eap: Peer sent EAP Response (code 2) ID 3 length 6 (2) eap: Continuing tunnel setup (2) [eap] = ok (2) } # authorize = ok (2) Found Auth-Type = EAP (2) # Executing group from file /etc/freeradius/sites-enabled/eduroam (2) authenticate { (2) eap: Expiring EAP session with state 0x3adf3a9e3bdc23ab (2) eap: Finished EAP session with state 0x3adf3a9e3bdc23ab (2) eap: Previous EAP request found for state 0x3adf3a9e3bdc23ab, released from the list (2) eap: Peer sent packet with method EAP PEAP (25) (2) eap: Calling submodule eap_peap to process data (2) eap_peap: Continuing EAP-TLS (2) eap_peap: Peer ACKed our handshake fragment (2) eap_peap: [eaptls verify] = request (2) eap_peap: [eaptls process] = handled (2) eap: Sending EAP Request (code 1) ID 4 length 1000 (2) eap: EAP session adding &reply:State = 0x3adf3a9e38db23ab (2) [eap] = handled (2) } # authenticate = handled (2) Using Post-Auth-Type Challenge (2) Post-Auth-Type sub-section not found. Ignoring. (2) # Executing group from file /etc/freeradius/sites-enabled/eduroam (2) Sent Access-Challenge Id 177 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (2) EAP-Message = 0x010403e81940615303759f86db56d0ef434ad84d7a3cce7a6d343f735f2bd9e8b9a3f70dc23d640220814ec749af6bb5e9396a38d2ca58f5809013a17ee10414000496308204923082037aa003020102020900e844f7302b8c478a300d06092a864886f70d010105050030818c310b3009060355040613 (2) Message-Authenticator = 0x00000000000000000000000000000000 (2) State = 0x3adf3a9e38db23abadde1d2911153d2e (2) Finished request Waking up in 4.9 seconds. (3) Received Access-Request Id 178 from 147.162.234.209:32776 to 147.162.57.7:1812 length 281 (3) User-Name = "stefano.zanmarchi@unipd.it" (3) Chargeable-User-Identity = 0x00 (3) Location-Capable = Civix-Location (3) Calling-Station-Id = "64-89-9a-1f-93-d6" (3) Called-Station-Id = "AP-GROUP-CSIA" (3) NAS-Port = 1 (3) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (3) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (3) NAS-IP-Address = 147.162.234.209 (3) NAS-Identifier = "WLC" (3) Airespace-Wlan-Id = 6 (3) Service-Type = Framed-User (3) Framed-MTU = 1300 (3) NAS-Port-Type = Wireless-802.11 (3) Tunnel-Type:0 = VLAN (3) Tunnel-Medium-Type:0 = IEEE-802 (3) Tunnel-Private-Group-Id:0 = "83" (3) EAP-Message = 0x020400061900 (3) State = 0x3adf3a9e38db23abadde1d2911153d2e (3) Message-Authenticator = 0xb50359a22e2e95a9ed46f832e08cf9a8 (3) session-state: No cached attributes (3) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (3) authorize { (3) policy filter_username { (3) if (!&User-Name) { (3) if (!&User-Name) -> FALSE (3) if (&User-Name =~ / /) { (3) if (&User-Name =~ / /) -> FALSE (3) if (&User-Name =~ /@.*@/ ) { (3) if (&User-Name =~ /@.*@/ ) -> FALSE (3) if (&User-Name =~ /\.\./ ) { (3) if (&User-Name =~ /\.\./ ) -> FALSE (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (3) if (&User-Name =~ /\.$/) { (3) if (&User-Name =~ /\.$/) -> FALSE (3) if (&User-Name =~ /@\./) { (3) if (&User-Name =~ /@\./) -> FALSE (3) } # policy filter_username = notfound (3) [preprocess] = ok (3) suffix: Checking for suffix after "@" (3) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (3) suffix: Found realm "unipd.it" (3) suffix: Adding Realm = "unipd.it" (3) suffix: Authentication realm is LOCAL (3) [suffix] = ok (3) eap: Peer sent EAP Response (code 2) ID 4 length 6 (3) eap: Continuing tunnel setup (3) [eap] = ok (3) } # authorize = ok (3) Found Auth-Type = EAP (3) # Executing group from file /etc/freeradius/sites-enabled/eduroam (3) authenticate { (3) eap: Expiring EAP session with state 0x3adf3a9e38db23ab (3) eap: Finished EAP session with state 0x3adf3a9e38db23ab (3) eap: Previous EAP request found for state 0x3adf3a9e38db23ab, released from the list (3) eap: Peer sent packet with method EAP PEAP (25) (3) eap: Calling submodule eap_peap to process data (3) eap_peap: Continuing EAP-TLS (3) eap_peap: Peer ACKed our handshake fragment (3) eap_peap: [eaptls verify] = request (3) eap_peap: [eaptls process] = handled (3) eap: Sending EAP Request (code 1) ID 5 length 592 (3) eap: EAP session adding &reply:State = 0x3adf3a9e39da23ab (3) [eap] = handled (3) } # authenticate = handled (3) Using Post-Auth-Type Challenge (3) Post-Auth-Type sub-section not found. Ignoring. (3) # Executing group from file /etc/freeradius/sites-enabled/eduroam (3) Sent Access-Challenge Id 178 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (3) EAP-Message = 0x010502501900a7a684baf97aecd2eef8b0b44514c7b507c8c995b89e7c83bb3292aeb1f67239bbc928d8e50658a7a80c78c2945dc51c0ba44f51309774b01f659149de4dcd6430808a20c7523d614c1d02cb6f6ba3dc82bd6ea4a9f63a732b9b14735f36ebb571b865d1c72a2f432f105721c3a46fe07b (3) Message-Authenticator = 0x00000000000000000000000000000000 (3) State = 0x3adf3a9e39da23abadde1d2911153d2e (3) Finished request Waking up in 4.9 seconds. (4) Received Access-Request Id 179 from 147.162.234.209:32776 to 147.162.57.7:1812 length 419 (4) User-Name = "stefano.zanmarchi@unipd.it" (4) Chargeable-User-Identity = 0x00 (4) Location-Capable = Civix-Location (4) Calling-Station-Id = "64-89-9a-1f-93-d6" (4) Called-Station-Id = "AP-GROUP-CSIA" (4) NAS-Port = 1 (4) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (4) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (4) NAS-IP-Address = 147.162.234.209 (4) NAS-Identifier = "WLC" (4) Airespace-Wlan-Id = 6 (4) Service-Type = Framed-User (4) Framed-MTU = 1300 (4) NAS-Port-Type = Wireless-802.11 (4) Tunnel-Type:0 = VLAN (4) Tunnel-Medium-Type:0 = IEEE-802 (4) Tunnel-Private-Group-Id:0 = "83" (4) EAP-Message = 0x0205009019800000008616030100461000004241043cb671ee52940994f9ae05ab5f95057965c697c47d43e1c34c9db46bb5182aded07390f3724cb801ec35e1408259434863a3de860d5a7c421271b4f179bd07701403010001011603010030b7a729bde9c569be42d4661a37622f9750281f9c3b911e (4) State = 0x3adf3a9e39da23abadde1d2911153d2e (4) Message-Authenticator = 0x676371211b581d2118426440bdb98377 (4) session-state: No cached attributes (4) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (4) authorize { (4) policy filter_username { (4) if (!&User-Name) { (4) if (!&User-Name) -> FALSE (4) if (&User-Name =~ / /) { (4) if (&User-Name =~ / /) -> FALSE (4) if (&User-Name =~ /@.*@/ ) { (4) if (&User-Name =~ /@.*@/ ) -> FALSE (4) if (&User-Name =~ /\.\./ ) { (4) if (&User-Name =~ /\.\./ ) -> FALSE (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (4) if (&User-Name =~ /\.$/) { (4) if (&User-Name =~ /\.$/) -> FALSE (4) if (&User-Name =~ /@\./) { (4) if (&User-Name =~ /@\./) -> FALSE (4) } # policy filter_username = notfound (4) [preprocess] = ok (4) suffix: Checking for suffix after "@" (4) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (4) suffix: Found realm "unipd.it" (4) suffix: Adding Realm = "unipd.it" (4) suffix: Authentication realm is LOCAL (4) [suffix] = ok (4) eap: Peer sent EAP Response (code 2) ID 5 length 144 (4) eap: Continuing tunnel setup (4) [eap] = ok (4) } # authorize = ok (4) Found Auth-Type = EAP (4) # Executing group from file /etc/freeradius/sites-enabled/eduroam (4) authenticate { (4) eap: Expiring EAP session with state 0x3adf3a9e39da23ab (4) eap: Finished EAP session with state 0x3adf3a9e39da23ab (4) eap: Previous EAP request found for state 0x3adf3a9e39da23ab, released from the list (4) eap: Peer sent packet with method EAP PEAP (25) (4) eap: Calling submodule eap_peap to process data (4) eap_peap: Continuing EAP-TLS (4) eap_peap: Peer indicated complete TLS record size will be 134 bytes (4) eap_peap: Got complete TLS record (134 bytes) (4) eap_peap: [eaptls verify] = length included (4) eap_peap: <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange (4) eap_peap: TLS_accept: unknown state (4) eap_peap: <<< TLS 1.0 ChangeCipherSpec [length 0001] (4) eap_peap: <<< TLS 1.0 Handshake [length 0010], Finished (4) eap_peap: TLS_accept: unknown state (4) eap_peap: >>> TLS 1.0 ChangeCipherSpec [length 0001] (4) eap_peap: TLS_accept: unknown state (4) eap_peap: >>> TLS 1.0 Handshake [length 0010], Finished (4) eap_peap: TLS_accept: unknown state (4) eap_peap: TLS_accept: unknown state (4) eap_peap: (other): SSL negotiation finished successfully (4) eap_peap: SSL Connection Established (4) eap_peap: [eaptls process] = handled (4) eap: Sending EAP Request (code 1) ID 6 length 65 (4) eap: EAP session adding &reply:State = 0x3adf3a9e3ed923ab (4) [eap] = handled (4) } # authenticate = handled (4) Using Post-Auth-Type Challenge (4) Post-Auth-Type sub-section not found. Ignoring. (4) # Executing group from file /etc/freeradius/sites-enabled/eduroam (4) Sent Access-Challenge Id 179 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (4) EAP-Message = 0x0106004119001403010001011603010030f9ed23944a88a71125eaa9f3b8f579c9e15adf58c096171f3f63c08c7a2b846273684b3d6a012fba87f33e21250ae4c5 (4) Message-Authenticator = 0x00000000000000000000000000000000 (4) State = 0x3adf3a9e3ed923abadde1d2911153d2e (4) Finished request Waking up in 4.9 seconds. (5) Received Access-Request Id 180 from 147.162.234.209:32776 to 147.162.57.7:1812 length 281 (5) User-Name = "stefano.zanmarchi@unipd.it" (5) Chargeable-User-Identity = 0x00 (5) Location-Capable = Civix-Location (5) Calling-Station-Id = "64-89-9a-1f-93-d6" (5) Called-Station-Id = "AP-GROUP-CSIA" (5) NAS-Port = 1 (5) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (5) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (5) NAS-IP-Address = 147.162.234.209 (5) NAS-Identifier = "WLC" (5) Airespace-Wlan-Id = 6 (5) Service-Type = Framed-User (5) Framed-MTU = 1300 (5) NAS-Port-Type = Wireless-802.11 (5) Tunnel-Type:0 = VLAN (5) Tunnel-Medium-Type:0 = IEEE-802 (5) Tunnel-Private-Group-Id:0 = "83" (5) EAP-Message = 0x020600061900 (5) State = 0x3adf3a9e3ed923abadde1d2911153d2e (5) Message-Authenticator = 0x4ef8dfdfb188820743371d8a471ebf95 (5) session-state: No cached attributes (5) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (5) authorize { (5) policy filter_username { (5) if (!&User-Name) { (5) if (!&User-Name) -> FALSE (5) if (&User-Name =~ / /) { (5) if (&User-Name =~ / /) -> FALSE (5) if (&User-Name =~ /@.*@/ ) { (5) if (&User-Name =~ /@.*@/ ) -> FALSE (5) if (&User-Name =~ /\.\./ ) { (5) if (&User-Name =~ /\.\./ ) -> FALSE (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (5) if (&User-Name =~ /\.$/) { (5) if (&User-Name =~ /\.$/) -> FALSE (5) if (&User-Name =~ /@\./) { (5) if (&User-Name =~ /@\./) -> FALSE (5) } # policy filter_username = notfound (5) [preprocess] = ok (5) suffix: Checking for suffix after "@" (5) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (5) suffix: Found realm "unipd.it" (5) suffix: Adding Realm = "unipd.it" (5) suffix: Authentication realm is LOCAL (5) [suffix] = ok (5) eap: Peer sent EAP Response (code 2) ID 6 length 6 (5) eap: Continuing tunnel setup (5) [eap] = ok (5) } # authorize = ok (5) Found Auth-Type = EAP (5) # Executing group from file /etc/freeradius/sites-enabled/eduroam (5) authenticate { (5) eap: Expiring EAP session with state 0x3adf3a9e3ed923ab (5) eap: Finished EAP session with state 0x3adf3a9e3ed923ab (5) eap: Previous EAP request found for state 0x3adf3a9e3ed923ab, released from the list (5) eap: Peer sent packet with method EAP PEAP (25) (5) eap: Calling submodule eap_peap to process data (5) eap_peap: Continuing EAP-TLS (5) eap_peap: Peer ACKed our handshake fragment. handshake is finished (5) eap_peap: [eaptls verify] = success (5) eap_peap: [eaptls process] = success (5) eap_peap: Session established. Decoding tunneled attributes (5) eap_peap: PEAP state TUNNEL ESTABLISHED (5) eap: Sending EAP Request (code 1) ID 7 length 43 (5) eap: EAP session adding &reply:State = 0x3adf3a9e3fd823ab (5) [eap] = handled (5) } # authenticate = handled (5) Using Post-Auth-Type Challenge (5) Post-Auth-Type sub-section not found. Ignoring. (5) # Executing group from file /etc/freeradius/sites-enabled/eduroam (5) Sent Access-Challenge Id 180 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (5) EAP-Message = 0x0107002b19001703010020f3c9c2b8099d88fb8a5a17e92339b071361f4512552aa935b8f2c1d2a5e999e4 (5) Message-Authenticator = 0x00000000000000000000000000000000 (5) State = 0x3adf3a9e3fd823abadde1d2911153d2e (5) Finished request Waking up in 4.8 seconds. (6) Received Access-Request Id 181 from 147.162.234.209:32776 to 147.162.57.7:1812 length 334 (6) User-Name = "stefano.zanmarchi@unipd.it" (6) Chargeable-User-Identity = 0x00 (6) Location-Capable = Civix-Location (6) Calling-Station-Id = "64-89-9a-1f-93-d6" (6) Called-Station-Id = "AP-GROUP-CSIA" (6) NAS-Port = 1 (6) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (6) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (6) NAS-IP-Address = 147.162.234.209 (6) NAS-Identifier = "WLC" (6) Airespace-Wlan-Id = 6 (6) Service-Type = Framed-User (6) Framed-MTU = 1300 (6) NAS-Port-Type = Wireless-802.11 (6) Tunnel-Type:0 = VLAN (6) Tunnel-Medium-Type:0 = IEEE-802 (6) Tunnel-Private-Group-Id:0 = "83" (6) EAP-Message = 0x0207003b19001703010030b781fe68e1dc489c935b9b06c89fbc7155e55c6ba11b13ef4513cc5fc511461936c348ab414f8ad33403ea7f4726b46e (6) State = 0x3adf3a9e3fd823abadde1d2911153d2e (6) Message-Authenticator = 0x8d3ff642d9fd28b6988d9f0d24a13e0c (6) session-state: No cached attributes (6) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (6) authorize { (6) policy filter_username { (6) if (!&User-Name) { (6) if (!&User-Name) -> FALSE (6) if (&User-Name =~ / /) { (6) if (&User-Name =~ / /) -> FALSE (6) if (&User-Name =~ /@.*@/ ) { (6) if (&User-Name =~ /@.*@/ ) -> FALSE (6) if (&User-Name =~ /\.\./ ) { (6) if (&User-Name =~ /\.\./ ) -> FALSE (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (6) if (&User-Name =~ /\.$/) { (6) if (&User-Name =~ /\.$/) -> FALSE (6) if (&User-Name =~ /@\./) { (6) if (&User-Name =~ /@\./) -> FALSE (6) } # policy filter_username = notfound (6) [preprocess] = ok (6) suffix: Checking for suffix after "@" (6) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (6) suffix: Found realm "unipd.it" (6) suffix: Adding Realm = "unipd.it" (6) suffix: Authentication realm is LOCAL (6) [suffix] = ok (6) eap: Peer sent EAP Response (code 2) ID 7 length 59 (6) eap: Continuing tunnel setup (6) [eap] = ok (6) } # authorize = ok (6) Found Auth-Type = EAP (6) # Executing group from file /etc/freeradius/sites-enabled/eduroam (6) authenticate { (6) eap: Expiring EAP session with state 0x3adf3a9e3fd823ab (6) eap: Finished EAP session with state 0x3adf3a9e3fd823ab (6) eap: Previous EAP request found for state 0x3adf3a9e3fd823ab, released from the list (6) eap: Peer sent packet with method EAP PEAP (25) (6) eap: Calling submodule eap_peap to process data (6) eap_peap: Continuing EAP-TLS (6) eap_peap: [eaptls verify] = ok (6) eap_peap: Done initial handshake (6) eap_peap: [eaptls process] = ok (6) eap_peap: Session established. Decoding tunneled attributes (6) eap_peap: PEAP state WAITING FOR INNER IDENTITY (6) eap_peap: Identity - stefano.zanmarchi@unipd.it (6) eap_peap: Got inner identity 'stefano.zanmarchi@unipd.it' (6) eap_peap: Setting default EAP type for tunneled EAP session (6) eap_peap: Got tunneled request (6) eap_peap: EAP-Message = 0x0207001f0173746566616e6f2e7a616e6d617263686940756e6970642e6974 (6) eap_peap: Setting User-Name to stefano.zanmarchi@unipd.it (6) eap_peap: Sending tunneled request to eduroam-inner-tunnel (6) eap_peap: EAP-Message = 0x0207001f0173746566616e6f2e7a616e6d617263686940756e6970642e6974 (6) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (6) eap_peap: User-Name = "stefano.zanmarchi@unipd.it" (6) eap_peap: Chargeable-User-Identity = 0x00 (6) eap_peap: Location-Capable = Civix-Location (6) eap_peap: Calling-Station-Id = "64-89-9a-1f-93-d6" (6) eap_peap: Called-Station-Id = "AP-GROUP-CSIA" (6) eap_peap: NAS-Port = 1 (6) eap_peap: Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (6) eap_peap: NAS-IP-Address = 147.162.234.209 (6) eap_peap: NAS-Identifier = "WLC" (6) eap_peap: Service-Type = Framed-User (6) eap_peap: Framed-MTU = 1300 (6) eap_peap: NAS-Port-Type = Wireless-802.11 (6) eap_peap: Tunnel-Type:0 = VLAN (6) eap_peap: Tunnel-Medium-Type:0 = IEEE-802 (6) eap_peap: Tunnel-Private-Group-Id:0 = "83" (6) eap_peap: Event-Timestamp = "Mar 29 2016 14:59:28 CEST" (6) Virtual server eduroam-inner-tunnel received request (6) EAP-Message = 0x0207001f0173746566616e6f2e7a616e6d617263686940756e6970642e6974 (6) FreeRADIUS-Proxied-To = 127.0.0.1 (6) User-Name = "stefano.zanmarchi@unipd.it" (6) Chargeable-User-Identity = 0x00 (6) Location-Capable = Civix-Location (6) Calling-Station-Id = "64-89-9a-1f-93-d6" (6) Called-Station-Id = "AP-GROUP-CSIA" (6) NAS-Port = 1 (6) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (6) NAS-IP-Address = 147.162.234.209 (6) NAS-Identifier = "WLC" (6) Service-Type = Framed-User (6) Framed-MTU = 1300 (6) NAS-Port-Type = Wireless-802.11 (6) Tunnel-Type:0 = VLAN (6) Tunnel-Medium-Type:0 = IEEE-802 (6) Tunnel-Private-Group-Id:0 = "83" (6) Event-Timestamp = "Mar 29 2016 14:59:28 CEST" (6) server eduroam-inner-tunnel { (6) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam-inner-tunnel (6) authorize { (6) SZ_test: EXPAND TEST: %{User-Name} da client %{client:shortname} cli %{Calling-Station-Id} con Framed IP address %{Framed-IP-Address} e NAS-IP-Address %{NAS-IP-Address} e NAS-Identifier %{NAS-Identifier} (6) SZ_test: --> TEST: stefano.zanmarchi@unipd.it da client eduroam.cca.unipd.it cli 64-89-9a-1f-93-d6 con Framed IP address e NAS-IP-Address 147.162.234.209 e NAS-Identifier WLC (6) [SZ_test] = ok (6) [preprocess] = ok (6) policy rewrite_calling_station_id { (6) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { (6) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) -> TRUE (6) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { (6) update request { (6) EXPAND %{toupper:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} (6) --> 64-89-9A-1F-93-D6 (6) &Calling-Station-Id := 64-89-9A-1F-93-D6 (6) } # update request = noop (6) [updated] = updated (6) } # if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) = updated (6) ... skipping else for request 6: Preceding "if" was taken (6) } # policy rewrite_calling_station_id = updated (6) if ("%{client:shortname}" =~ /radius_garr_(.*)/i) { (6) EXPAND %{client:shortname} (6) --> eduroam.cca.unipd.it (6) if ("%{client:shortname}" =~ /radius_garr_(.*)/i) -> FALSE (6) elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}"
= 1) { (6) EXPAND %{User-Name} (6) --> stefano.zanmarchi@unipd.it (6) SQL-User-Name set to 'stefano.zanmarchi@unipd.it' rlm_sql (sql): Reserved connection (0) (6) Executing select query: SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = ' stefano.zanmarchi@unipd.it' rlm_sql (sql): Released connection (0) rlm_sql (sql): Need 5 more connections to reach 10 spares rlm_sql (sql): Opening additional connection (5), 1 of 27 pending slots used (6) EXPAND %{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'} (6) --> 1 (6) elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}" = 1) -> TRUE (6) elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}" = 1) { (6) [ok] = ok (6) } # elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}" = 1) = ok (6) ... skipping else for request 6: Preceding "if" was taken (6) [mschap] = noop (6) eap: Peer sent EAP Response (code 2) ID 7 length 31 (6) eap: EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize (6) [eap] = ok (6) } # authorize = ok (6) Found Auth-Type = EAP (6) # Executing group from file /etc/freeradius/sites-enabled/eduroam-inner-tunnel (6) authenticate { (6) eap: Peer sent packet with method EAP Identity (1) (6) eap: Calling submodule eap_mschapv2 to process data (6) eap_mschapv2: Issuing Challenge (6) eap: Sending EAP Request (code 1) ID 8 length 43 (6) eap: EAP session adding &reply:State = 0x8b88ae478b80b4f4 (6) [eap] = handled (6) } # authenticate = handled (6) } # server eduroam-inner-tunnel (6) Virtual server sending reply (6) EAP-Message = 0x0108002b1a01080026104244889bc21c473d54ace02c5eccd042667265657261646975732d332e302e3130 (6) Message-Authenticator = 0x00000000000000000000000000000000 (6) State = 0x8b88ae478b80b4f47def8c61a94495e0 (6) eap_peap: Got tunneled reply code 11 (6) eap_peap: EAP-Message = 0x0108002b1a01080026104244889bc21c473d54ace02c5eccd042667265657261646975732d332e302e3130 (6) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (6) eap_peap: State = 0x8b88ae478b80b4f47def8c61a94495e0 (6) eap_peap: Got tunneled reply RADIUS code 11 (6) eap_peap: EAP-Message = 0x0108002b1a01080026104244889bc21c473d54ace02c5eccd042667265657261646975732d332e302e3130 (6) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (6) eap_peap: State = 0x8b88ae478b80b4f47def8c61a94495e0 (6) eap_peap: Got tunneled Access-Challenge (6) eap: Sending EAP Request (code 1) ID 8 length 75 (6) eap: EAP session adding &reply:State = 0x3adf3a9e3cd723ab (6) [eap] = handled (6) } # authenticate = handled (6) Using Post-Auth-Type Challenge (6) Post-Auth-Type sub-section not found. Ignoring. (6) # Executing group from file /etc/freeradius/sites-enabled/eduroam (6) Sent Access-Challenge Id 181 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (6) EAP-Message = 0x0108004b19001703010040dd631c1b0d9bf69f9ffa222f96176fbd96b7bcc6b35f99549a24fbf18be5308d359e9a85b105e8a37ae982ec48907653f14569e954ac7c0043cbd9f37eccae8f (6) Message-Authenticator = 0x00000000000000000000000000000000 (6) State = 0x3adf3a9e3cd723abadde1d2911153d2e (6) Finished request Waking up in 4.8 seconds. (7) Received Access-Request Id 182 from 147.162.234.209:32776 to 147.162.57.7:1812 length 398 (7) User-Name = "stefano.zanmarchi@unipd.it" (7) Chargeable-User-Identity = 0x00 (7) Location-Capable = Civix-Location (7) Calling-Station-Id = "64-89-9a-1f-93-d6" (7) Called-Station-Id = "AP-GROUP-CSIA" (7) NAS-Port = 1 (7) Cisco-AVPair = "audit-session-id=93a2ead100012e6456fa7c31" (7) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (7) NAS-IP-Address = 147.162.234.209 (7) NAS-Identifier = "WLC" (7) Airespace-Wlan-Id = 6 (7) Service-Type = Framed-User (7) Framed-MTU = 1300 (7) NAS-Port-Type = Wireless-802.11 (7) Tunnel-Type:0 = VLAN (7) Tunnel-Medium-Type:0 = IEEE-802 (7) Tunnel-Private-Group-Id:0 = "83" (7) EAP-Message = 0x0208007b190017030100705610816905db6adcfe969b807a18738075bc096ab28b380a093f4e40ce422da1693ca7095dd7e1a0915d2a90de9c93931a2a65325bac062a343567297e088bfe6d62442e0107a51e1cbbfa2f6b376956c8ec250b445f6bb672ccae875a34aff4c5ee6269e83ce423dd14fedf (7) State = 0x3adf3a9e3cd723abadde1d2911153d2e (7) Message-Authenticator = 0x0d1b0904bfd3b74235a0f88a643e4344 (7) session-state: No cached attributes (7) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam (7) authorize { (7) policy filter_username { (7) if (!&User-Name) { (7) if (!&User-Name) -> FALSE (7) if (&User-Name =~ / /) { (7) if (&User-Name =~ / /) -> FALSE (7) if (&User-Name =~ /@.*@/ ) { (7) if (&User-Name =~ /@.*@/ ) -> FALSE (7) if (&User-Name =~ /\.\./ ) { (7) if (&User-Name =~ /\.\./ ) -> FALSE (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (7) if (&User-Name =~ /\.$/) { (7) if (&User-Name =~ /\.$/) -> FALSE (7) if (&User-Name =~ /@\./) { (7) if (&User-Name =~ /@\./) -> FALSE (7) } # policy filter_username = notfound (7) [preprocess] = ok (7) suffix: Checking for suffix after "@" (7) suffix: Looking up realm "unipd.it" for User-Name = " stefano.zanmarchi@unipd.it" (7) suffix: Found realm "unipd.it" (7) suffix: Adding Realm = "unipd.it" (7) suffix: Authentication realm is LOCAL (7) [suffix] = ok (7) eap: Peer sent EAP Response (code 2) ID 8 length 123 (7) eap: Continuing tunnel setup (7) [eap] = ok (7) } # authorize = ok (7) Found Auth-Type = EAP (7) # Executing group from file /etc/freeradius/sites-enabled/eduroam (7) authenticate { (7) eap: Expiring EAP session with state 0x8b88ae478b80b4f4 (7) eap: Finished EAP session with state 0x3adf3a9e3cd723ab (7) eap: Previous EAP request found for state 0x3adf3a9e3cd723ab, released from the list (7) eap: Peer sent packet with method EAP PEAP (25) (7) eap: Calling submodule eap_peap to process data (7) eap_peap: Continuing EAP-TLS (7) eap_peap: [eaptls verify] = ok (7) eap_peap: Done initial handshake (7) eap_peap: [eaptls process] = ok (7) eap_peap: Session established. Decoding tunneled attributes (7) eap_peap: PEAP state phase2 (7) eap_peap: EAP method MSCHAPv2 (26) (7) eap_peap: Got tunneled request (7) eap_peap: EAP-Message = 0x020800551a0208005031c4b0987b86deb1ab0391deeed5b7e9060000000000000000ec36fb4662c854a92a2b7834c29eab13b273957b7c32cbd60073746566616e6f2e7a616e6d617263686940756e6970642e6974 (7) eap_peap: Setting User-Name to stefano.zanmarchi@unipd.it (7) eap_peap: Sending tunneled request to eduroam-inner-tunnel (7) eap_peap: EAP-Message = 0x020800551a0208005031c4b0987b86deb1ab0391deeed5b7e9060000000000000000ec36fb4662c854a92a2b7834c29eab13b273957b7c32cbd60073746566616e6f2e7a616e6d617263686940756e6970642e6974 (7) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (7) eap_peap: User-Name = "stefano.zanmarchi@unipd.it" (7) eap_peap: State = 0x8b88ae478b80b4f47def8c61a94495e0 (7) eap_peap: Chargeable-User-Identity = 0x00 (7) eap_peap: Location-Capable = Civix-Location (7) eap_peap: Calling-Station-Id = "64-89-9a-1f-93-d6" (7) eap_peap: Called-Station-Id = "AP-GROUP-CSIA" (7) eap_peap: NAS-Port = 1 (7) eap_peap: Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (7) eap_peap: NAS-IP-Address = 147.162.234.209 (7) eap_peap: NAS-Identifier = "WLC" (7) eap_peap: Service-Type = Framed-User (7) eap_peap: Framed-MTU = 1300 (7) eap_peap: NAS-Port-Type = Wireless-802.11 (7) eap_peap: Tunnel-Type:0 = VLAN (7) eap_peap: Tunnel-Medium-Type:0 = IEEE-802 (7) eap_peap: Tunnel-Private-Group-Id:0 = "83" (7) eap_peap: Event-Timestamp = "Mar 29 2016 14:59:28 CEST" (7) Virtual server eduroam-inner-tunnel received request (7) EAP-Message = 0x020800551a0208005031c4b0987b86deb1ab0391deeed5b7e9060000000000000000ec36fb4662c854a92a2b7834c29eab13b273957b7c32cbd60073746566616e6f2e7a616e6d617263686940756e6970642e6974 (7) FreeRADIUS-Proxied-To = 127.0.0.1 (7) User-Name = "stefano.zanmarchi@unipd.it" (7) State = 0x8b88ae478b80b4f47def8c61a94495e0 (7) Chargeable-User-Identity = 0x00 (7) Location-Capable = Civix-Location (7) Calling-Station-Id = "64-89-9a-1f-93-d6" (7) Called-Station-Id = "AP-GROUP-CSIA" (7) NAS-Port = 1 (7) Acct-Session-Id = "56fa7c31/64:89:9a:1f:93:d6/84429" (7) NAS-IP-Address = 147.162.234.209 (7) NAS-Identifier = "WLC" (7) Service-Type = Framed-User (7) Framed-MTU = 1300 (7) NAS-Port-Type = Wireless-802.11 (7) Tunnel-Type:0 = VLAN (7) Tunnel-Medium-Type:0 = IEEE-802 (7) Tunnel-Private-Group-Id:0 = "83" (7) Event-Timestamp = "Mar 29 2016 14:59:28 CEST" (7) server eduroam-inner-tunnel { (7) session-state: No cached attributes (7) # Executing section authorize from file /etc/freeradius/sites-enabled/eduroam-inner-tunnel (7) authorize { (7) SZ_test: EXPAND TEST: %{User-Name} da client %{client:shortname} cli %{Calling-Station-Id} con Framed IP address %{Framed-IP-Address} e NAS-IP-Address %{NAS-IP-Address} e NAS-Identifier %{NAS-Identifier} (7) SZ_test: --> TEST: stefano.zanmarchi@unipd.it da client eduroam.cca.unipd.it cli 64-89-9a-1f-93-d6 con Framed IP address e NAS-IP-Address 147.162.234.209 e NAS-Identifier WLC (7) [SZ_test] = ok (7) [preprocess] = ok (7) policy rewrite_calling_station_id { (7) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { (7) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) -> TRUE (7) if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) { (7) update request { (7) EXPAND %{toupper:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} (7) --> 64-89-9A-1F-93-D6 (7) &Calling-Station-Id := 64-89-9A-1F-93-D6 (7) } # update request = noop (7) [updated] = updated (7) } # if (&Calling-Station-Id && (&Calling-Station-Id =~ /^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$/i)) = updated (7) ... skipping else for request 7: Preceding "if" was taken (7) } # policy rewrite_calling_station_id = updated (7) if ("%{client:shortname}" =~ /radius_garr_(.*)/i) { (7) EXPAND %{client:shortname} (7) --> eduroam.cca.unipd.it (7) if ("%{client:shortname}" =~ /radius_garr_(.*)/i) -> FALSE (7) elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}" = 1) { (7) EXPAND %{User-Name} (7) --> stefano.zanmarchi@unipd.it (7) SQL-User-Name set to 'stefano.zanmarchi@unipd.it' rlm_sql (sql): Reserved connection (1) (7) Executing select query: SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('64-89-9A-1F-93-D6','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = ' stefano.zanmarchi@unipd.it' rlm_sql (sql): Released connection (1) (7) EXPAND %{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'} (7) --> 1 (7) elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}" = 1) -> TRUE (7) elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}" = 1) { (7) [ok] = ok (7) } # elsif ("%{sql:SELECT count(*) FROM eduroam_mac_registrati m, eduroam_diritto_uso d WHERE m.username = d.username AND m.mac=LOWER(SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),1,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),3,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),5,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),7,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),9,2) || '-' ||SUBSTR(REGEXP_REPLACE('%{Calling-Station-Id}','(-|\.|:)',''),11,2)) AND m.data_cancell IS NULL AND d.diritto='S' AND d.username = '%{User-Name}'}" = 1) = ok (7) ... skipping else for request 7: Preceding "if" was taken (7) [mschap] = noop (7) eap: Peer sent EAP Response (code 2) ID 8 length 85 (7) eap: No EAP Start, assuming it's an on-going EAP conversation (7) [eap] = updated rlm_ldap (ldap): Reserved connection (0) (7) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}}) (7) ldap: --> (uid=stefano.zanmarchi@unipd.it) (7) ldap: Performing search in "dc=unipd,dc=it" with filter "(uid= stefano.zanmarchi@unipd.it)", scope "sub" (7) ldap: Waiting for search result... (7) ldap: User object found at DN "uid=stefano.zanmarchi@unipd.it ,ou=people,dc=unipd,dc=it" (7) ldap: Processing user attributes (7) ldap: control:Password-With-Header += '{SSHA}daAb5hYqd57iqIj0r06v1EAbt9jJ45Ab' (7) ldap: control:NT-Password = 0x3664184078903237303639104460024333383932463938343041010385285232 rlm_ldap (ldap): Released connection (0) rlm_ldap (ldap): Need 5 more connections to reach 10 spares rlm_ldap (ldap): Opening additional connection (5), 1 of 27 pending slots used rlm_ldap (ldap): Connecting to ldap://directory.cca.unipd.it:12316 rlm_ldap (ldap): Waiting for bind result... rlm_ldap (ldap): Bind successful (7) [ldap] = updated (7) [expiration] = noop (7) [logintime] = noop (7) pap: Converted: Password-With-Header -> SSHA1-Password (7) pap: Removing &control:Password-With-Header (7) pap: Normalizing NT-Password from hex encoding, 32 bytes -> 16 bytes (7) pap: Normalizing SSHA1-Password from base64 encoding, 32 bytes -> 24 bytes (7) pap: WARNING: Auth-Type already set. Not setting to PAP (7) [pap] = noop (7) } # authorize = updated (7) Found Auth-Type = EAP (7) # Executing group from file /etc/freeradius/sites-enabled/eduroam-inner-tunnel (7) authenticate { (7) eap: Expiring EAP session with state 0x8b88ae478b80b4f4 (7) eap: Finished EAP session with state 0x8b88ae478b80b4f4 (7) eap: Previous EAP request found for state 0x8b88ae478b80b4f4, released from the list (7) eap: Peer sent packet with method EAP MSCHAPv2 (26) (7) eap: Calling submodule eap_mschapv2 to process data (7) eap_mschapv2: # Executing group from file /etc/freeradius/sites-enabled/eduroam-inner-tunnel (7) eap_mschapv2: Auth-Type MS-CHAP { (7) SZ_BBB: EXPAND BBB: %{User-Name} da client %{client:shortname} cli %{Calling-Station-Id} con Framed IP address %{Framed-IP-Address} e NAS-IP-Address %{NAS-IP-Address} e NAS-Identifier %{NAS-Identifier} (7) SZ_BBB: --> BBB: stefano.zanmarchi@unipd.it da client eduroam.cca.unipd.it cli 64-89-9A-1F-93-D6 con Framed IP address e NAS-IP-Address 147.162.234.209 e NAS-Identifier WLC (7) [SZ_BBB] = ok (7) mschap: Found NT-Password (7) mschap: Creating challenge hash with username: stefano.zanmarchi@unipd.it (7) mschap: Client is using MS-CHAPv2 (7) mschap: ERROR: MS-CHAP2-Response is incorrect (7) [mschap] = reject (7) } # Auth-Type MS-CHAP = reject (7) MSCHAP-Error: ?E=691 R=1 C=6e8acc35f6597bba35a458c113c9cb09 V=3 M=Authentication failed (7) Found new challenge from MS-CHAP-Error: err=691 retry=1 challenge=6e8acc35f6597bba35a458c113c9cb09 (7) ERROR: MSCHAP Failure (7) eap: Sending EAP Request (code 1) ID 9 length 81 (7) eap: EAP session adding &reply:State = 0x8b88ae478a81b4f4 (7) [eap] = handled (7) } # authenticate = handled (7) } # server eduroam-inner-tunnel (7) Virtual server sending reply (7) EAP-Message = 0x010900511a0408004c453d36393120523d3120433d366538616363333566363539376262613335613435386331313363396362303920563d33204d3d41757468656e7469636174696f6e206661696c6564 (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0x8b88ae478a81b4f47def8c61a94495e0 (7) eap_peap: Got tunneled reply code 11 (7) eap_peap: EAP-Message = 0x010900511a0408004c453d36393120523d3120433d366538616363333566363539376262613335613435386331313363396362303920563d33204d3d41757468656e7469636174696f6e206661696c6564 (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (7) eap_peap: State = 0x8b88ae478a81b4f47def8c61a94495e0 (7) eap_peap: Got tunneled reply RADIUS code 11 (7) eap_peap: EAP-Message = 0x010900511a0408004c453d36393120523d3120433d366538616363333566363539376262613335613435386331313363396362303920563d33204d3d41757468656e7469636174696f6e206661696c6564 (7) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (7) eap_peap: State = 0x8b88ae478a81b4f47def8c61a94495e0 (7) eap_peap: Got tunneled Access-Challenge (7) eap: Sending EAP Request (code 1) ID 9 length 123 (7) eap: EAP session adding &reply:State = 0x3adf3a9e3dd623ab (7) [eap] = handled (7) } # authenticate = handled (7) Using Post-Auth-Type Challenge (7) Post-Auth-Type sub-section not found. Ignoring. (7) # Executing group from file /etc/freeradius/sites-enabled/eduroam (7) Sent Access-Challenge Id 182 from 147.162.57.7:1812 to 147.162.234.209:32776 length 0 (7) EAP-Message = 0x0109007b190017030100705a4b4e13a23f3d9f94ddfedb9e691bf9b8099e093560fbbcb0bc0ea1ea2d0c63a6c7ed0292643cc99b5e1f2113026e70d751ada6850ffee66fd821d4a16c3f918b1d1763b3e958d5c7bfd01db00287630429d6b7efa719c09595b87a65fa13162ad0d664cf4f63cbdec7583a (7) Message-Authenticator = 0x00000000000000000000000000000000 (7) State = 0x3adf3a9e3dd623abadde1d2911153d2e (7) Finished request Waking up in 4.8 seconds.
On Mar 31, 2016, at 9:04 AM, Stefano Zanmarchi <zanmarchi@gmail.com> wrote:
I've realized that quite often when users fail authentication due to wrong password this does not result in a "Login incorrect" message in the logs.
"Login incorrect" only occurs when the server sends an Access-Reject. EAP requires many packet exchanges, and the client may simply give up part way through. In that case, it won't show a "login incorrect" message. Alan DeKok.
Hi Alan, but this happens only with freeradius 3 which is running in parallel with a freeradius 2 server, and when the request from the same supplicant with a wrong password reaches the freeradius 2 server the "login incorrect" message appears in its logs! Moreover, the following lines do not cause the freeradius 3 server to send Access-Reject? (7) mschap: Client is using MS-CHAPv2 (7) mschap: ERROR: MS-CHAP2-Response is incorrect (7) [mschap] = reject (7) } # Auth-Type MS-CHAP = reject (7) MSCHAP-Error: ?E=691 R=1 C=6e8acc35f6597bba35a458c113c9cb09 V=3 M=Authentication failed Thank you, Stefano On Thu, Mar 31, 2016 at 3:29 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Mar 31, 2016, at 9:04 AM, Stefano Zanmarchi <zanmarchi@gmail.com> wrote:
I've realized that quite often when users fail authentication due to wrong password this does not result in a "Login incorrect" message in the logs.
"Login incorrect" only occurs when the server sends an Access-Reject.
EAP requires many packet exchanges, and the client may simply give up part way through. In that case, it won't show a "login incorrect" message.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Mar 31, 2016, at 10:20 AM, Stefano Zanmarchi <zanmarchi@gmail.com> wrote:
but this happens only with freeradius 3 which is running in parallel with a freeradius 2 server, and when the request from the same supplicant with a wrong password reaches the freeradius 2 server the "login incorrect" message appears in its logs!
The server has changed from time to time...
Moreover, the following lines do not cause the freeradius 3 server to send Access-Reject?
Have you tried... oh, I don't know... running the server in debug mode? And READING the output? I mean honestly, if you can cut & paste 6 lines from the debug output here, you can READ the following lines to see if the server sends an Access-Reject. It's not hard. And that would answer your question. After 17 years of doing this, I'm amazed at the number of people who just refuse to read the debug output. Why? Just... why? Alan DeKok.
Hello Alan, I should have put my question in a more explicit but maybe less polite way. Let me do it now. Having read the debugging output, and having performed the same test with freeradius 2 and freeradius 3, I have come to the conclusion that freeradius 3 detects mschap failures but does not always log the event, whereas freeradius 2 does. Why that? Not having the failure event logged anymore is quite a nuisance because when a user complains that the network isn't working I can't easily see from the logs that it's just him typing the wrong password. It'd be very useful if freeradius could log the "mschap: ERROR: MS-CHAP2-Response is incorrect" in the logs even when not run in debug mode. Thank you for your great work, Stefano
On Thu, Mar 31, 2016 at 06:10:09PM +0200, Stefano Zanmarchi wrote:
Not having the failure event logged anymore is quite a nuisance because when a user complains that the network isn't working I can't easily see from the logs that it's just him typing the wrong password. It'd be very useful if freeradius could log the "mschap: ERROR: MS-CHAP2-Response is incorrect" in the logs even when not run in debug mode.
Have you tried logging the Module-Failure-Message attribute? It might help (some modules give better errors in it than others). Matthew -- Matthew Newton, Ph.D. <mcn4@le.ac.uk> Systems Specialist, Infrastructure Services, I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom For IT help contact helpdesk extn. 2253, <ithelp@le.ac.uk>
On 31 Mar 2016, at 10:10, Stefano Zanmarchi <zanmarchi@gmail.com> wrote:
Hello Alan, I should have put my question in a more explicit but maybe less polite way. Let me do it now. Having read the debugging output, and having performed the same test with freeradius 2 and freeradius 3, I have come to the conclusion that freeradius 3 detects mschap failures but does not always log the event, whereas freeradius 2 does. Why that?
Because that is not a global error. FreeRADIUS 3 only logs global errors to its main log. Much of the code has been cleaned up to properly categorise errors, which is why you may no longer see some request specific errors that appeared in the global log of FreeRADIUS 2. During request processing FreeRADIUS 3 creates a 'stack' of errors that occurred. This stack is created by adding multiple instances of the Module-Failure-Message attribute to the request list. Every time an REDEBUG* or RERROR macro is called in the code a new instance of the Module-Failure-Message attribute is created. If you see the error in the debug output, it will be available on the error stack. Request errors may be concatenated using the %{Module-Failure-Message[*]} expansion, which can be added either to a rlm_linelog instance or the auth success/failure messages in radiusd.conf. This is significantly more flexible and useful than dumping everything uncategorised to the global log. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On Mar 31, 2016, at 12:10 PM, Stefano Zanmarchi <zanmarchi@gmail.com> wrote:
I should have put my question in a more explicit but maybe less polite way. Let me do it now.
Technical content is what we're looking for.
Having read the debugging output, and having performed the same test with freeradius 2 and freeradius 3, I have come to the conclusion that freeradius 3 detects mschap failures but does not always log the event, whereas freeradius 2 does. Why that?
Arran's response explains this. But also.. you can run the server in debug mode to see what it does in v2, and what it does in v3. Compare them to see the differences.
Not having the failure event logged anymore is quite a nuisance because when a user complains that the network isn't working I can't easily see from the logs that it's just him typing the wrong password.
I understand.
It'd be very useful if freeradius could log the "mschap: ERROR: MS-CHAP2-Response is incorrect" in the logs even when not run in debug mode.
It should generally log the failure of an inner-tunnel authentication. If it doesn't, that's probably an issue. Alan DeKok.
Thank you very much for the tip, it's working fine. Module-Failure-Message does the job, "mschap: MS-CHAP2-Response is incorrect" gets now logged. Just in case someone faces the same problem: In the inner-tunnel: Auth-Type EAP { eap { handled = 1 } if (Module-Failure-Message) { eap_problem } handled } With eap_problem defined at the end of .../mods-enabled/linelog: linelog eap_problem { filename = syslog syslog_facility = daemon format = "EAP problem, (%{Module-Failure-Message}) [%{User-Name}] (from %{client:shortname} cli %{Calling-Station-Id})" } On Thu, Mar 31, 2016 at 10:49 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Mar 31, 2016, at 12:10 PM, Stefano Zanmarchi <zanmarchi@gmail.com> wrote:
I should have put my question in a more explicit but maybe less polite way. Let me do it now.
Technical content is what we're looking for.
Having read the debugging output, and having performed the same test with freeradius 2 and freeradius 3, I have come to the conclusion that freeradius 3 detects mschap failures but does not always log the event, whereas freeradius 2 does. Why that?
Arran's response explains this. But also.. you can run the server in debug mode to see what it does in v2, and what it does in v3. Compare them to see the differences.
Not having the failure event logged anymore is quite a nuisance because when a user complains that the network isn't working I can't easily see from the logs that it's just him typing the wrong password.
I understand.
It'd be very useful if freeradius could log the "mschap: ERROR: MS-CHAP2-Response is incorrect" in the logs even when not run in debug mode.
It should generally log the failure of an inner-tunnel authentication. If it doesn't, that's probably an issue.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (4)
-
Alan DeKok -
Arran Cudbard-Bell -
Matthew Newton -
Stefano Zanmarchi