Problem with log and PEAP/MS-CHAPv2
Hi, I'm trying to setup a PEAP-MS-CHAPv2 tunnel with FR 3.0.13. It works fine but I have a little problem with the log. When a user logs in correctly I have the usual Login OK. But if the user uses a wrong password or if the username doesn't exist, I don't have any logs of it. Testing the inner tunnel with radtest logs correctly. The configuration of the server and the inner tunnel. Users are on "files" module: server wifi_tim { authorize { filter_username auth_log chap mschap eap { ok = return } wifi_tim_files pap } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } mschap eap } preacct { } accounting { } session { } post-auth { update { &reply: += &session-state: } reply_log remove_reply_message_if_eap Post-Auth-Type REJECT { attr_filter.access_reject eap remove_reply_message_if_eap } Post-Auth-Type Challenge { } } pre-proxy { } post-proxy { } } server wifi_tim_inner_tunnel { listen { ipaddr = 127.0.0.1 port = 11812 type = auth } authorize { filter_username chap mschap eap { ok = return } wifi_tim_files pap } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } mschap eap } session { } post-auth { Post-Auth-Type REJECT { attr_filter.access_reject update outer.session-state { &Module-Failure-Message := &request:Module-Failure-Message } } } pre-proxy { } post-proxy { } } eap { default_eap_type = peap timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = ${max_requests} tls-config tls-common { private_key_password = whatever private_key_file = ${certdir}/server.pem certificate_file = ${certdir}/server.pem ca_file = ${cadir}/ca.pem dh_file = ${certdir}/dh ca_path = ${cadir} cipher_list = "ALL:!LOW:!SSLv2:!EXP:!aNULL" cipher_server_preference = yes ecdh_curve = "prime256v1" cache { enable = no max_entries = 255 } ocsp { enable = no override_cert_url = yes url = "http://127.0.0.1/ocsp/" } } peap { tls = tls-common default_eap_type = mschapv2 copy_request_to_tunnel = no use_tunneled_reply = no virtual_server = "wifi_tim_inner_tunnel" } mschapv2 { send_error = yes identity = "Tism Access Server" } } Logs with radtest: Apr 12 10:47:25 radius31 radiusd[28822]: (1) Login OK: [testuser] (from client localhost port 0) Apr 12 10:47:35 radius31 radiusd[28822]: (2) Login incorrect (mschap: MS-CHAP2-Response is incorrect): [testuser] (from client localhost port 0) Apr 12 10:47:35 radius31 radiusd[28822]: (2) Rejected in post-auth: [testuser] (from client localhost port 0) Apr 12 10:55:02 radius31 radiusd[28822]: (16) Login incorrect (mschap: FAILED: No NT/LM-Password. Cannot perform authentication): [testuserx] (from client localhost port 0) Apr 12 10:55:02 radius31 radiusd[28822]: (16) Rejected in post-auth: [testuserx] (from client localhost port 0) Debug with EAP and wrong password: (162) Wed Apr 12 11:30:39 2017: Debug: Received Access-Request Id 7 from 194.183.95.46:55808 to 194.183.95.46:1812 length 276 (162) Wed Apr 12 11:30:39 2017: Debug: User-Name = "testuser" (162) Wed Apr 12 11:30:39 2017: Debug: Calling-Station-Id = "E8-3A-12-EF-30-CE" (162) Wed Apr 12 11:30:39 2017: Debug: Framed-MTU = 1400 (162) Wed Apr 12 11:30:39 2017: Debug: NAS-Port-Type = Wireless-802.11 (162) Wed Apr 12 11:30:39 2017: Debug: Connect-Info = "rad_eap_test + eapol_test" (162) Wed Apr 12 11:30:39 2017: Debug: NAS-IP-Address = 172.16.0.4 (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x02070090190017030100207ca8e68f9cc0712a093735da2c9a7a8f8880c35df3bb05407fc2ca022b33575d1703010060960e2f55b1a94c96a4197759099aaafdcabbaa6c6c0583b1c26e354da196fc30abcab796cdf83f4bc110a14559904b992bdfff46e30d60b9d6548342b5ea2fa87d4fbd3392353b (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xe50e637de3097a45c917c73821ab3033 (162) Wed Apr 12 11:30:39 2017: Debug: Message-Authenticator = 0x79e6229a110fd499293f527c2f93be25 (162) Wed Apr 12 11:30:39 2017: Debug: session-state: No cached attributes (162) Wed Apr 12 11:30:39 2017: Debug: # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim (162) Wed Apr 12 11:30:39 2017: Debug: authorize { (162) Wed Apr 12 11:30:39 2017: Debug: policy filter_username { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) -> TRUE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: } # if (&User-Name) = notfound (162) Wed Apr 12 11:30:39 2017: Debug: } # policy filter_username = notfound (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: --> /var/log/radius/radacct/194.183.95.46/auth-detail-20170412 (162) Wed Apr 12 11:30:39 2017: Debug: 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/194.183.95.46/auth-detail-20170412 (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: EXPAND %t (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: --> Wed Apr 12 11:30:39 2017 (162) Wed Apr 12 11:30:39 2017: Debug: [auth_log] = ok (162) Wed Apr 12 11:30:39 2017: Debug: [chap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: [mschap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent EAP Response (code 2) ID 7 length 144 (162) Wed Apr 12 11:30:39 2017: Debug: eap: Continuing tunnel setup (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = ok (162) Wed Apr 12 11:30:39 2017: Debug: } # authorize = ok (162) Wed Apr 12 11:30:39 2017: Debug: Found Auth-Type = eap (162) Wed Apr 12 11:30:39 2017: Debug: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim (162) Wed Apr 12 11:30:39 2017: Debug: authenticate { (162) Wed Apr 12 11:30:39 2017: Debug: eap: Expiring EAP session with state 0xcb16895fcb11935b (162) Wed Apr 12 11:30:39 2017: Debug: eap: Finished EAP session with state 0xe50e637de3097a45 (162) Wed Apr 12 11:30:39 2017: Debug: eap: Previous EAP request found for state 0xe50e637de3097a45, released from the list (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent packet with method EAP PEAP (25) (162) Wed Apr 12 11:30:39 2017: Debug: eap: Calling submodule eap_peap to process data (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Continuing EAP-TLS (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: [eaptls verify] = ok (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Done initial handshake (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: [eaptls process] = ok (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Session established. Decoding tunneled attributes (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: PEAP state phase2 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP method MSCHAPv2 (26) (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Got tunneled request (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP-Message = 0x020700431a0207003e31b91e9f531a076d578b11807fa0c5e5570000000000000000c26b0fb3fc605a0e49b6dfc821e07a674b6f65c9e16dd07b007465737475736572 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Setting User-Name to testuser (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Sending tunneled request to wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP-Message = 0x020700431a0207003e31b91e9f531a076d578b11807fa0c5e5570000000000000000c26b0fb3fc605a0e49b6dfc821e07a674b6f65c9e16dd07b007465737475736572 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: User-Name = "testuser" (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: State = 0xcb16895fcb11935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: Debug: Virtual server wifi_tim_inner_tunnel received request (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x020700431a0207003e31b91e9f531a076d578b11807fa0c5e5570000000000000000c26b0fb3fc605a0e49b6dfc821e07a674b6f65c9e16dd07b007465737475736572 (162) Wed Apr 12 11:30:39 2017: Debug: FreeRADIUS-Proxied-To = 127.0.0.1 (162) Wed Apr 12 11:30:39 2017: Debug: User-Name = "testuser" (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xcb16895fcb11935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: WARNING: Outer and inner identities are the same. User privacy is compromised. (162) Wed Apr 12 11:30:39 2017: Debug: server wifi_tim_inner_tunnel { (162) Wed Apr 12 11:30:39 2017: Debug: session-state: No cached attributes (162) Wed Apr 12 11:30:39 2017: Debug: # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: authorize { (162) Wed Apr 12 11:30:39 2017: Debug: policy filter_username { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) -> TRUE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: } # if (&User-Name) = notfound (162) Wed Apr 12 11:30:39 2017: Debug: } # policy filter_username = notfound (162) Wed Apr 12 11:30:39 2017: Debug: [chap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: [mschap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent EAP Response (code 2) ID 7 length 67 (162) Wed Apr 12 11:30:39 2017: Debug: eap: No EAP Start, assuming it's an on-going EAP conversation (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = updated (162) Wed Apr 12 11:30:39 2017: Debug: wifi_tim_files: users: Matched entry testuser at line 13 (162) Wed Apr 12 11:30:39 2017: Debug: [wifi_tim_files] = ok (162) Wed Apr 12 11:30:39 2017: WARNING: pap: Auth-Type already set. Not setting to PAP (162) Wed Apr 12 11:30:39 2017: Debug: [pap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: } # authorize = updated (162) Wed Apr 12 11:30:39 2017: Debug: Found Auth-Type = eap (162) Wed Apr 12 11:30:39 2017: Debug: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: authenticate { (162) Wed Apr 12 11:30:39 2017: Debug: eap: Expiring EAP session with state 0xcb16895fcb11935b (162) Wed Apr 12 11:30:39 2017: Debug: eap: Finished EAP session with state 0xcb16895fcb11935b (162) Wed Apr 12 11:30:39 2017: Debug: eap: Previous EAP request found for state 0xcb16895fcb11935b, released from the list (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent packet with method EAP MSCHAPv2 (26) (162) Wed Apr 12 11:30:39 2017: Debug: eap: Calling submodule eap_mschapv2 to process data (162) Wed Apr 12 11:30:39 2017: Debug: eap_mschapv2: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: eap_mschapv2: authenticate { (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Found Cleartext-Password, hashing to create NT-Password (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Found Cleartext-Password, hashing to create LM-Password (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Creating challenge hash with username: testuser (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Client is using MS-CHAPv2 (162) Wed Apr 12 11:30:39 2017: ERROR: mschap: MS-CHAP2-Response is incorrect (162) Wed Apr 12 11:30:39 2017: Debug: [mschap] = reject (162) Wed Apr 12 11:30:39 2017: Debug: } # authenticate = reject (162) Wed Apr 12 11:30:39 2017: Debug: MSCHAP-Error: E=691 R=1 C=1474492f8f426051613ac0fd4afe37b8 V=3 M=Authentication failed (162) Wed Apr 12 11:30:39 2017: Debug: Found new challenge from MS-CHAP-Error: err=691 retry=1 challenge=1474492f8f426051613ac0fd4afe37b8 (162) Wed Apr 12 11:30:39 2017: ERROR: MSCHAP Failure (162) Wed Apr 12 11:30:39 2017: Debug: eap: Sending EAP Request (code 1) ID 8 length 81 (162) Wed Apr 12 11:30:39 2017: Debug: eap: EAP session adding &reply:State = 0xcb16895fca1e935b (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = handled (162) Wed Apr 12 11:30:39 2017: Debug: } # authenticate = handled (162) Wed Apr 12 11:30:39 2017: Debug: } # server wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: Virtual server sending reply (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x010800511a0407004c453d36393120523d3120433d313437343439326638663432363035313631336163306664346166653337623820563d33204d3d41757468656e7469636174696f6e206661696c6564 (162) Wed Apr 12 11:30:39 2017: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xcb16895fca1e935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Got tunneled reply code 11 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP-Message = 0x010800511a0407004c453d36393120523d3120433d313437343439326638663432363035313631336163306664346166653337623820563d33204d3d41757468656e7469636174696f6e206661696c6564 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: State = 0xcb16895fca1e935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Got tunneled Access-Challenge (162) Wed Apr 12 11:30:39 2017: Debug: eap: Sending EAP Request (code 1) ID 8 length 123 (162) Wed Apr 12 11:30:39 2017: Debug: eap: EAP session adding &reply:State = 0xe50e637de2067a45 (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = handled (162) Wed Apr 12 11:30:39 2017: Debug: } # authenticate = handled (162) Wed Apr 12 11:30:39 2017: Debug: Using Post-Auth-Type Challenge (162) Wed Apr 12 11:30:39 2017: Debug: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim (162) Wed Apr 12 11:30:39 2017: Debug: Challenge { ... } # empty sub-section is ignored (162) Wed Apr 12 11:30:39 2017: Debug: Sent Access-Challenge Id 7 from 194.183.95.46:1812 to 194.183.95.46:55808 length 0 (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x0108007b19001703010070ebc34da12bb045acd32080fe40bc92495c6593a5e40589775105ef0f5c76cffda64ca3039931242118be0db1a39bdd811a876d7bc9e111e9e28ee633e50ceae1b4a66367000e3990c542a0aa3227b3673d58dd69d1b006db31a8859ae1fe63416e1253dec50b6fb4959a4e51 (162) Wed Apr 12 11:30:39 2017: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xe50e637de2067a45c917c73821ab3033 (162) Wed Apr 12 11:30:39 2017: Debug: Finished request no more packets are exchanged... Thanks, Andrea -- ---------------------------------------------------------------- Truth hurts... not the searching after but the running from. ---------------------------------------------------------------- Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188 Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino http://www.telecomitalia.sm
Hi, mschapv2 { send_error = no } solves the problem... I changed it from the default and I forgot it :-( Now in the log, with the login incorrect, I found: Apr 12 13:31:28 radius31 radiusd[19562]: (8) Login incorrect (mschap: MS-CHAP2-Response is incorrect): [testuser] (from client wlc_wifi_tim port 0 via TLS tunnel) Apr 12 13:31:28 radius31 radiusd[19562]: (9) eap_peap: This means you need to read the PREVIOUS messages in the debug output Apr 12 13:31:28 radius31 radiusd[19562]: (9) eap_peap: to find out the reason why the user was rejected Apr 12 13:31:28 radius31 radiusd[19562]: (9) eap_peap: Look for "reject" or "fail". Those earlier messages will tell you Apr 12 13:31:28 radius31 radiusd[19562]: (9) eap_peap: what went wrong, and how to fix the problem Apr 12 13:31:28 radius31 radiusd[19562]: (9) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [testuser] (from client wlc_wifi_tim port 0 cli E8-3A-12-EF-30-CE) The eap_peap logs seems a debug log. Is it corect? Thanks, Andrea Il 12/04/2017 11:37, Andrea Gabellini ha scritto:
Hi,
I'm trying to setup a PEAP-MS-CHAPv2 tunnel with FR 3.0.13. It works fine but I have a little problem with the log. When a user logs in correctly I have the usual Login OK. But if the user uses a wrong password or if the username doesn't exist, I don't have any logs of it. Testing the inner tunnel with radtest logs correctly.
The configuration of the server and the inner tunnel. Users are on "files" module: server wifi_tim { authorize { filter_username auth_log chap mschap eap { ok = return } wifi_tim_files pap } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } mschap eap } preacct { } accounting { } session { } post-auth { update { &reply: += &session-state: } reply_log remove_reply_message_if_eap Post-Auth-Type REJECT { attr_filter.access_reject eap remove_reply_message_if_eap } Post-Auth-Type Challenge { } } pre-proxy { } post-proxy { } }
server wifi_tim_inner_tunnel { listen { ipaddr = 127.0.0.1 port = 11812 type = auth } authorize { filter_username chap mschap eap { ok = return } wifi_tim_files pap } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } mschap
eap } session { } post-auth { Post-Auth-Type REJECT { attr_filter.access_reject update outer.session-state { &Module-Failure-Message := &request:Module-Failure-Message } } } pre-proxy { } post-proxy { } }
eap { default_eap_type = peap timer_expire = 60 ignore_unknown_eap_types = no cisco_accounting_username_bug = no max_sessions = ${max_requests} tls-config tls-common { private_key_password = whatever private_key_file = ${certdir}/server.pem certificate_file = ${certdir}/server.pem ca_file = ${cadir}/ca.pem dh_file = ${certdir}/dh ca_path = ${cadir} cipher_list = "ALL:!LOW:!SSLv2:!EXP:!aNULL" cipher_server_preference = yes ecdh_curve = "prime256v1" cache { enable = no max_entries = 255 } ocsp { enable = no override_cert_url = yes url = "http://127.0.0.1/ocsp/" } } peap { tls = tls-common default_eap_type = mschapv2 copy_request_to_tunnel = no use_tunneled_reply = no virtual_server = "wifi_tim_inner_tunnel" } mschapv2 { send_error = yes identity = "Tism Access Server" } }
Logs with radtest: Apr 12 10:47:25 radius31 radiusd[28822]: (1) Login OK: [testuser] (from client localhost port 0)
Apr 12 10:47:35 radius31 radiusd[28822]: (2) Login incorrect (mschap: MS-CHAP2-Response is incorrect): [testuser] (from client localhost port 0) Apr 12 10:47:35 radius31 radiusd[28822]: (2) Rejected in post-auth: [testuser] (from client localhost port 0)
Apr 12 10:55:02 radius31 radiusd[28822]: (16) Login incorrect (mschap: FAILED: No NT/LM-Password. Cannot perform authentication): [testuserx] (from client localhost port 0) Apr 12 10:55:02 radius31 radiusd[28822]: (16) Rejected in post-auth: [testuserx] (from client localhost port 0)
Debug with EAP and wrong password: (162) Wed Apr 12 11:30:39 2017: Debug: Received Access-Request Id 7 from 194.183.95.46:55808 to 194.183.95.46:1812 length 276 (162) Wed Apr 12 11:30:39 2017: Debug: User-Name = "testuser" (162) Wed Apr 12 11:30:39 2017: Debug: Calling-Station-Id = "E8-3A-12-EF-30-CE" (162) Wed Apr 12 11:30:39 2017: Debug: Framed-MTU = 1400 (162) Wed Apr 12 11:30:39 2017: Debug: NAS-Port-Type = Wireless-802.11 (162) Wed Apr 12 11:30:39 2017: Debug: Connect-Info = "rad_eap_test + eapol_test" (162) Wed Apr 12 11:30:39 2017: Debug: NAS-IP-Address = 172.16.0.4 (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x02070090190017030100207ca8e68f9cc0712a093735da2c9a7a8f8880c35df3bb05407fc2ca022b33575d1703010060960e2f55b1a94c96a4197759099aaafdcabbaa6c6c0583b1c26e354da196fc30abcab796cdf83f4bc110a14559904b992bdfff46e30d60b9d6548342b5ea2fa87d4fbd3392353b (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xe50e637de3097a45c917c73821ab3033 (162) Wed Apr 12 11:30:39 2017: Debug: Message-Authenticator = 0x79e6229a110fd499293f527c2f93be25 (162) Wed Apr 12 11:30:39 2017: Debug: session-state: No cached attributes (162) Wed Apr 12 11:30:39 2017: Debug: # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim (162) Wed Apr 12 11:30:39 2017: Debug: authorize { (162) Wed Apr 12 11:30:39 2017: Debug: policy filter_username { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) -> TRUE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: } # if (&User-Name) = notfound (162) Wed Apr 12 11:30:39 2017: Debug: } # policy filter_username = notfound (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: EXPAND /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: --> /var/log/radius/radacct/194.183.95.46/auth-detail-20170412 (162) Wed Apr 12 11:30:39 2017: Debug: 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/194.183.95.46/auth-detail-20170412 (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: EXPAND %t (162) Wed Apr 12 11:30:39 2017: Debug: auth_log: --> Wed Apr 12 11:30:39 2017 (162) Wed Apr 12 11:30:39 2017: Debug: [auth_log] = ok (162) Wed Apr 12 11:30:39 2017: Debug: [chap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: [mschap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent EAP Response (code 2) ID 7 length 144 (162) Wed Apr 12 11:30:39 2017: Debug: eap: Continuing tunnel setup (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = ok (162) Wed Apr 12 11:30:39 2017: Debug: } # authorize = ok (162) Wed Apr 12 11:30:39 2017: Debug: Found Auth-Type = eap (162) Wed Apr 12 11:30:39 2017: Debug: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim (162) Wed Apr 12 11:30:39 2017: Debug: authenticate { (162) Wed Apr 12 11:30:39 2017: Debug: eap: Expiring EAP session with state 0xcb16895fcb11935b (162) Wed Apr 12 11:30:39 2017: Debug: eap: Finished EAP session with state 0xe50e637de3097a45 (162) Wed Apr 12 11:30:39 2017: Debug: eap: Previous EAP request found for state 0xe50e637de3097a45, released from the list (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent packet with method EAP PEAP (25) (162) Wed Apr 12 11:30:39 2017: Debug: eap: Calling submodule eap_peap to process data (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Continuing EAP-TLS (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: [eaptls verify] = ok (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Done initial handshake (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: [eaptls process] = ok (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Session established. Decoding tunneled attributes (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: PEAP state phase2 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP method MSCHAPv2 (26) (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Got tunneled request (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP-Message = 0x020700431a0207003e31b91e9f531a076d578b11807fa0c5e5570000000000000000c26b0fb3fc605a0e49b6dfc821e07a674b6f65c9e16dd07b007465737475736572 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Setting User-Name to testuser (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Sending tunneled request to wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP-Message = 0x020700431a0207003e31b91e9f531a076d578b11807fa0c5e5570000000000000000c26b0fb3fc605a0e49b6dfc821e07a674b6f65c9e16dd07b007465737475736572 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: User-Name = "testuser" (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: State = 0xcb16895fcb11935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: Debug: Virtual server wifi_tim_inner_tunnel received request (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x020700431a0207003e31b91e9f531a076d578b11807fa0c5e5570000000000000000c26b0fb3fc605a0e49b6dfc821e07a674b6f65c9e16dd07b007465737475736572 (162) Wed Apr 12 11:30:39 2017: Debug: FreeRADIUS-Proxied-To = 127.0.0.1 (162) Wed Apr 12 11:30:39 2017: Debug: User-Name = "testuser" (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xcb16895fcb11935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: WARNING: Outer and inner identities are the same. User privacy is compromised. (162) Wed Apr 12 11:30:39 2017: Debug: server wifi_tim_inner_tunnel { (162) Wed Apr 12 11:30:39 2017: Debug: session-state: No cached attributes (162) Wed Apr 12 11:30:39 2017: Debug: # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: authorize { (162) Wed Apr 12 11:30:39 2017: Debug: policy filter_username { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) -> TRUE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ / /) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (162) Wed Apr 12 11:30:39 2017: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /\.$/) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) { (162) Wed Apr 12 11:30:39 2017: Debug: if (&User-Name =~ /@\./) -> FALSE (162) Wed Apr 12 11:30:39 2017: Debug: } # if (&User-Name) = notfound (162) Wed Apr 12 11:30:39 2017: Debug: } # policy filter_username = notfound (162) Wed Apr 12 11:30:39 2017: Debug: [chap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: [mschap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent EAP Response (code 2) ID 7 length 67 (162) Wed Apr 12 11:30:39 2017: Debug: eap: No EAP Start, assuming it's an on-going EAP conversation (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = updated (162) Wed Apr 12 11:30:39 2017: Debug: wifi_tim_files: users: Matched entry testuser at line 13 (162) Wed Apr 12 11:30:39 2017: Debug: [wifi_tim_files] = ok (162) Wed Apr 12 11:30:39 2017: WARNING: pap: Auth-Type already set. Not setting to PAP (162) Wed Apr 12 11:30:39 2017: Debug: [pap] = noop (162) Wed Apr 12 11:30:39 2017: Debug: } # authorize = updated (162) Wed Apr 12 11:30:39 2017: Debug: Found Auth-Type = eap (162) Wed Apr 12 11:30:39 2017: Debug: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: authenticate { (162) Wed Apr 12 11:30:39 2017: Debug: eap: Expiring EAP session with state 0xcb16895fcb11935b (162) Wed Apr 12 11:30:39 2017: Debug: eap: Finished EAP session with state 0xcb16895fcb11935b (162) Wed Apr 12 11:30:39 2017: Debug: eap: Previous EAP request found for state 0xcb16895fcb11935b, released from the list (162) Wed Apr 12 11:30:39 2017: Debug: eap: Peer sent packet with method EAP MSCHAPv2 (26) (162) Wed Apr 12 11:30:39 2017: Debug: eap: Calling submodule eap_mschapv2 to process data (162) Wed Apr 12 11:30:39 2017: Debug: eap_mschapv2: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: eap_mschapv2: authenticate { (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Found Cleartext-Password, hashing to create NT-Password (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Found Cleartext-Password, hashing to create LM-Password (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Creating challenge hash with username: testuser (162) Wed Apr 12 11:30:39 2017: Debug: mschap: Client is using MS-CHAPv2 (162) Wed Apr 12 11:30:39 2017: ERROR: mschap: MS-CHAP2-Response is incorrect (162) Wed Apr 12 11:30:39 2017: Debug: [mschap] = reject (162) Wed Apr 12 11:30:39 2017: Debug: } # authenticate = reject (162) Wed Apr 12 11:30:39 2017: Debug: MSCHAP-Error: E=691 R=1 C=1474492f8f426051613ac0fd4afe37b8 V=3 M=Authentication failed (162) Wed Apr 12 11:30:39 2017: Debug: Found new challenge from MS-CHAP-Error: err=691 retry=1 challenge=1474492f8f426051613ac0fd4afe37b8 (162) Wed Apr 12 11:30:39 2017: ERROR: MSCHAP Failure (162) Wed Apr 12 11:30:39 2017: Debug: eap: Sending EAP Request (code 1) ID 8 length 81 (162) Wed Apr 12 11:30:39 2017: Debug: eap: EAP session adding &reply:State = 0xcb16895fca1e935b (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = handled (162) Wed Apr 12 11:30:39 2017: Debug: } # authenticate = handled (162) Wed Apr 12 11:30:39 2017: Debug: } # server wifi_tim_inner_tunnel (162) Wed Apr 12 11:30:39 2017: Debug: Virtual server sending reply (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x010800511a0407004c453d36393120523d3120433d313437343439326638663432363035313631336163306664346166653337623820563d33204d3d41757468656e7469636174696f6e206661696c6564 (162) Wed Apr 12 11:30:39 2017: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xcb16895fca1e935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Got tunneled reply code 11 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: EAP-Message = 0x010800511a0407004c453d36393120523d3120433d313437343439326638663432363035313631336163306664346166653337623820563d33204d3d41757468656e7469636174696f6e206661696c6564 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: State = 0xcb16895fca1e935b1be4d67ff3649f78 (162) Wed Apr 12 11:30:39 2017: Debug: eap_peap: Got tunneled Access-Challenge (162) Wed Apr 12 11:30:39 2017: Debug: eap: Sending EAP Request (code 1) ID 8 length 123 (162) Wed Apr 12 11:30:39 2017: Debug: eap: EAP session adding &reply:State = 0xe50e637de2067a45 (162) Wed Apr 12 11:30:39 2017: Debug: [eap] = handled (162) Wed Apr 12 11:30:39 2017: Debug: } # authenticate = handled (162) Wed Apr 12 11:30:39 2017: Debug: Using Post-Auth-Type Challenge (162) Wed Apr 12 11:30:39 2017: Debug: # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/wifi_tim (162) Wed Apr 12 11:30:39 2017: Debug: Challenge { ... } # empty sub-section is ignored (162) Wed Apr 12 11:30:39 2017: Debug: Sent Access-Challenge Id 7 from 194.183.95.46:1812 to 194.183.95.46:55808 length 0 (162) Wed Apr 12 11:30:39 2017: Debug: EAP-Message = 0x0108007b19001703010070ebc34da12bb045acd32080fe40bc92495c6593a5e40589775105ef0f5c76cffda64ca3039931242118be0db1a39bdd811a876d7bc9e111e9e28ee633e50ceae1b4a66367000e3990c542a0aa3227b3673d58dd69d1b006db31a8859ae1fe63416e1253dec50b6fb4959a4e51 (162) Wed Apr 12 11:30:39 2017: Debug: Message-Authenticator = 0x00000000000000000000000000000000 (162) Wed Apr 12 11:30:39 2017: Debug: State = 0xe50e637de2067a45c917c73821ab3033 (162) Wed Apr 12 11:30:39 2017: Debug: Finished request
no more packets are exchanged...
Thanks, Andrea
-- ---------------------------------------------------------------- Be a good listener. Your ears will never get you in trouble. ---------------------------------------------------------------- Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188 Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino http://www.telecomitalia.sm
On Apr 12, 2017, at 7:34 AM, Andrea Gabellini <andrea.gabellini@telecomitalia.sm> wrote:
Now in the log, with the login incorrect, I found:
Apr 12 13:31:28 radius31 radiusd[19562]: (8) Login incorrect (mschap: MS-CHAP2-Response is incorrect): [testuser] (from client wlc_wifi_tim port 0 via TLS tunnel)
The (8) is the clue. You've started the server in daemon mode, but passed it "-xx" on the command line. So *all* debug output is being sent to the main log file. The simple answer is "don't do that".
The eap_peap logs seems a debug log. Is it corect?
it's a debug log because you told it to be a debug log. It helps to pay attention to the configuration changes you make. Alan DeKok.
Il 13/04/2017 02:15, Alan DeKok ha scritto:
On Apr 12, 2017, at 7:34 AM, Andrea Gabellini <andrea.gabellini@telecomitalia.sm> wrote:
Now in the log, with the login incorrect, I found:
Apr 12 13:31:28 radius31 radiusd[19562]: (8) Login incorrect (mschap: MS-CHAP2-Response is incorrect): [testuser] (from client wlc_wifi_tim port 0 via TLS tunnel) The (8) is the clue.
You've started the server in daemon mode, but passed it "-xx" on the command line. So *all* debug output is being sent to the main log file.
The simple answer is "don't do that".
Hi Alan, the server doesn't have any extra options: [09:25:43][radius31:~] #systemctl restart radiusd [09:29:46][radius31:~] #ps -ef | grep radiusd radiusd 21746 1 0 09:29 ? 00:00:00 /usr/local/freeradius/sbin/radiusd [09:30:06][radius31:~] #tail -f /var/log/radius/radius.log Apr 13 09:30:44 radius31 radiusd[21746]: (9) Login OK: [testuser] (from client wlc_wifi_tim port 0 via TLS tunnel) Apr 13 09:30:44 radius31 radiusd[21746]: (10) Login OK: [testuser] (from client wlc_wifi_tim port 0 cli E8-3A-12-EF-30-CE) Apr 13 09:30:52 radius31 radiusd[21746]: (19) Login incorrect (mschap: MS-CHAP2-Response is incorrect): [testuser] (from client wlc_wifi_tim port 0 via TLS tunnel) Apr 13 09:30:52 radius31 radiusd[21746]: (20) eap_peap: This means you need to read the PREVIOUS messages in the debug output Apr 13 09:30:52 radius31 radiusd[21746]: (20) eap_peap: to find out the reason why the user was rejected Apr 13 09:30:52 radius31 radiusd[21746]: (20) eap_peap: Look for "reject" or "fail". Those earlier messages will tell you Apr 13 09:30:52 radius31 radiusd[21746]: (20) eap_peap: what went wrong, and how to fix the problem Apr 13 09:30:52 radius31 radiusd[21746]: (20) Login incorrect (eap_peap: The users session was previously rejected: returning reject (again.)): [testuser] (from client wlc_wifi_tim port 0 cli E8-3A-12-EF-30-CE) I used the -xx switch in the past for the initial configuration, but now I'm not using it. Is there any other place where can I find debug switch? Thanks, Andrea
The eap_peap logs seems a debug log. Is it corect? it's a debug log because you told it to be a debug log.
It helps to pay attention to the configuration changes you make.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- ---------------------------------------------------------------- So many pedestrians, so little time. ---------------------------------------------------------------- Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188 Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino http://www.telecomitalia.sm
On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@telecomitalia.sm> wrote:
the server doesn't have any extra options:
<shrug> The server doesn't magically start printing all debug messages to the log file. You've made some change in your local configuration to cause this to happen. Find it, and fix it. $ cd /etc/raddb $ grep -r debug . Maybe that will help. Again, you *should* keep track of your local changes, and you *should* know what changes you made. Alan DeKok.
Il 13/04/2017 13:18, Alan DeKok ha scritto:
On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@telecomitalia.sm> wrote:
the server doesn't have any extra options: <shrug> The server doesn't magically start printing all debug messages to the log file.
You've made some change in your local configuration to cause this to happen. Find it, and fix it.
$ cd /etc/raddb $ grep -r debug .
Maybe that will help.
Hi Alan, the search for the debug keyword in the config directory doesn't return any hint. I removed the raddb directory and reinstalled all with make install. Just modified "auth = yes" and enabled the user "bob" from the default configuration: [09:14:22][radius31:/usr/local/freeradius/etc/raddb] #systemctl restart radiusd [09:14:26][radius31:/usr/local/freeradius/etc/raddb] #tail -f /var/log/radius/radius.log Fri Apr 14 09:14:26 2017 : Info: Debugger not attached Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server <default> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server default Fri Apr 14 09:14:26 2017 : Info: # Skipping contents of 'if' as it is always 'false' -- /usr/local/freeradius/etc/raddb/sites-enabled/inner-tunnel:330 Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server inner-tunnel Fri Apr 14 09:14:26 2017 : Info: Ready to process requests Fri Apr 14 09:14:30 2017 : Auth: (0) Login OK: [bob] (from client localhost port 0) Fri Apr 14 09:14:32 2017 : Auth: (1) Login incorrect (pap: Cleartext password "hellox" does not match "known good" password): [bob] (from client localhost port 0) Freeradius was compiled on CentOS 7 server with: ./configure --prefix=/usr/local/freeradius --enable-static=no --localstatedir=/var --with-docdir=no --with-vmps=no --with-oracle-include-dir=/usr/local/oracle/sdk/include --with-oracle-lib-dir=/usr/local/oracle Any idea on what I can check? Thanks, Andrea
Again, you *should* keep track of your local changes, and you *should* know what changes you made.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- ---------------------------------------------------------------- The box said: 'install on Windows 95, NT 4.0 or better'. So I installed it on Linux. ---------------------------------------------------------------- Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188 Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino http://www.telecomitalia.sm
hi, this is just the output of the standard freeradius logfile - which gives you some basic info (with log_auth enabled) . you need to be looking at the output when you run the server in full debug mode: radiusd -X or freeradiusd -X (if you're on debian/ubuntu builds) (and yes, thats just one big uppercase X) - as that will tell you exactly what is happening and why something doesnt work. if this is a vanilla install with no local confidential stuff etc then theres no reason to not post the output in full to the list - there will be one or 2 obvious things alan On 14 April 2017 at 08:19, Andrea Gabellini < andrea.gabellini@telecomitalia.sm> wrote:
Il 13/04/2017 13:18, Alan DeKok ha scritto:
On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@ telecomitalia.sm> wrote:
the server doesn't have any extra options: <shrug> The server doesn't magically start printing all debug messages to the log file.
You've made some change in your local configuration to cause this to happen. Find it, and fix it.
$ cd /etc/raddb $ grep -r debug .
Maybe that will help.
Hi Alan,
the search for the debug keyword in the config directory doesn't return any hint.
I removed the raddb directory and reinstalled all with make install. Just modified "auth = yes" and enabled the user "bob" from the default configuration:
[09:14:22][radius31:/usr/local/freeradius/etc/raddb] #systemctl restart radiusd [09:14:26][radius31:/usr/local/freeradius/etc/raddb] #tail -f /var/log/radius/radius.log Fri Apr 14 09:14:26 2017 : Info: Debugger not attached Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server <default> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server default Fri Apr 14 09:14:26 2017 : Info: # Skipping contents of 'if' as it is always 'false' -- /usr/local/freeradius/etc/raddb/sites-enabled/inner-tunnel:330 Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server inner-tunnel Fri Apr 14 09:14:26 2017 : Info: Ready to process requests Fri Apr 14 09:14:30 2017 : Auth: (0) Login OK: [bob] (from client localhost port 0) Fri Apr 14 09:14:32 2017 : Auth: (1) Login incorrect (pap: Cleartext password "hellox" does not match "known good" password): [bob] (from client localhost port 0)
Freeradius was compiled on CentOS 7 server with: ./configure --prefix=/usr/local/freeradius --enable-static=no --localstatedir=/var --with-docdir=no --with-vmps=no --with-oracle-include-dir=/usr/local/oracle/sdk/include --with-oracle-lib-dir=/usr/local/oracle
Any idea on what I can check?
Thanks, Andrea
Again, you *should* keep track of your local changes, and you *should*
know what changes you made.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/
list/users.html
-- ---------------------------------------------------------------- The box said: 'install on Windows 95, NT 4.0 or better'. So I installed it on Linux.
----------------------------------------------------------------
Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188
Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino
- List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
Hi, the problem is the (0) and (1) in the log. I think this is the packet number. Using eap with wrong username or password logs some debug output (see previous posts). Alan DeKok says that this is a debug log, but radiusd isn't running debug mode. So the question is: why I got a debug output if the server is running without it? Thanks, Andrea Il 14/04/2017 11:03, Alan Buxey ha scritto:
hi,
this is just the output of the standard freeradius logfile - which gives you some basic info (with log_auth enabled) .
you need to be looking at the output when you run the server in full debug mode:
radiusd -X or freeradiusd -X (if you're on debian/ubuntu builds)
(and yes, thats just one big uppercase X) - as that will tell you exactly what is happening and why something doesnt work.
if this is a vanilla install with no local confidential stuff etc then theres no reason to not post the output in full to the list - there will be one or 2 obvious things
alan
On 14 April 2017 at 08:19, Andrea Gabellini < andrea.gabellini@telecomitalia.sm> wrote:
Il 13/04/2017 13:18, Alan DeKok ha scritto:
On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@ telecomitalia.sm> wrote:
the server doesn't have any extra options: <shrug> The server doesn't magically start printing all debug messages to the log file. You've made some change in your local configuration to cause this to happen. Find it, and fix it. $ cd /etc/raddb $ grep -r debug .
Maybe that will help. Hi Alan,
the search for the debug keyword in the config directory doesn't return any hint.
I removed the raddb directory and reinstalled all with make install. Just modified "auth = yes" and enabled the user "bob" from the default configuration:
[09:14:22][radius31:/usr/local/freeradius/etc/raddb] #systemctl restart radiusd [09:14:26][radius31:/usr/local/freeradius/etc/raddb] #tail -f /var/log/radius/radius.log Fri Apr 14 09:14:26 2017 : Info: Debugger not attached Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server <default> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server default Fri Apr 14 09:14:26 2017 : Info: # Skipping contents of 'if' as it is always 'false' -- /usr/local/freeradius/etc/raddb/sites-enabled/inner-tunnel:330 Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server inner-tunnel Fri Apr 14 09:14:26 2017 : Info: Ready to process requests Fri Apr 14 09:14:30 2017 : Auth: (0) Login OK: [bob] (from client localhost port 0) Fri Apr 14 09:14:32 2017 : Auth: (1) Login incorrect (pap: Cleartext password "hellox" does not match "known good" password): [bob] (from client localhost port 0)
Freeradius was compiled on CentOS 7 server with: ./configure --prefix=/usr/local/freeradius --enable-static=no --localstatedir=/var --with-docdir=no --with-vmps=no --with-oracle-include-dir=/usr/local/oracle/sdk/include --with-oracle-lib-dir=/usr/local/oracle
Any idea on what I can check?
Thanks, Andrea
Again, you *should* keep track of your local changes, and you *should* know what changes you made. Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
-- ---------------------------------------------------------------- The box said: 'install on Windows 95, NT 4.0 or better'. So I installed it on Linux.
----------------------------------------------------------------
Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188
Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino
- List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- ---------------------------------------------------------------- Hardware: The parts of a computer system that can be kicked. ---------------------------------------------------------------- Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188 Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino http://www.telecomitalia.sm
you are not - you are getting some of the stuff that gets logged. the reason for 2 outputs is varied but usually seen with EAP tunneled methods and the reaaon for the auth failure AFTER things look okay is usually due to things like failure for the server to log the event (in which case an error is seen and the server will reject the user). if you run in full debug mode then you will get the full pucture of what is happening....and you've been told this many times. just runt he server in full debug mode (radiusd -X) see what is going on. fix it, THEN run it in production mode, there is no other sensible way to proceed. alan On 14 April 2017 at 10:21, Andrea Gabellini < andrea.gabellini@telecomitalia.sm> wrote:
Hi,
the problem is the (0) and (1) in the log. I think this is the packet number. Using eap with wrong username or password logs some debug output (see previous posts). Alan DeKok says that this is a debug log, but radiusd isn't running debug mode.
So the question is: why I got a debug output if the server is running without it?
Thanks, Andrea
Il 14/04/2017 11:03, Alan Buxey ha scritto:
hi,
this is just the output of the standard freeradius logfile - which gives you some basic info (with log_auth enabled) .
you need to be looking at the output when you run the server in full debug mode:
radiusd -X or freeradiusd -X (if you're on debian/ubuntu builds)
(and yes, thats just one big uppercase X) - as that will tell you exactly what is happening and why something doesnt work.
if this is a vanilla install with no local confidential stuff etc then theres no reason to not post the output in full to the list - there will be one or 2 obvious things
alan
On 14 April 2017 at 08:19, Andrea Gabellini < andrea.gabellini@telecomitalia.sm> wrote:
Il 13/04/2017 13:18, Alan DeKok ha scritto:
On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@ telecomitalia.sm> wrote:
the server doesn't have any extra options: <shrug> The server doesn't magically start printing all debug messages to the log file. You've made some change in your local configuration to cause this to happen. Find it, and fix it. $ cd /etc/raddb $ grep -r debug .
Maybe that will help. Hi Alan,
the search for the debug keyword in the config directory doesn't return any hint.
I removed the raddb directory and reinstalled all with make install. Just modified "auth = yes" and enabled the user "bob" from the default configuration:
[09:14:22][radius31:/usr/local/freeradius/etc/raddb] #systemctl restart radiusd [09:14:26][radius31:/usr/local/freeradius/etc/raddb] #tail -f /var/log/radius/radius.log Fri Apr 14 09:14:26 2017 : Info: Debugger not attached Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/
Check item "FreeRADIUS-Response-Delay" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Warning: [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/ access_reject]:11 Check item "FreeRADIUS-Response-Delay-USec" found in filter list for realm "DEFAULT". Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server <default> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "sql" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Warning: Ignoring "ldap" (see raddb/mods-available/README.rst) Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server default Fri Apr 14 09:14:26 2017 : Info: # Skipping contents of 'if' as it is always 'false' -- /usr/local/freeradius/etc/raddb/sites-enabled/inner-tunnel:330 Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server inner-tunnel Fri Apr 14 09:14:26 2017 : Info: Ready to process requests Fri Apr 14 09:14:30 2017 : Auth: (0) Login OK: [bob] (from client localhost port 0) Fri Apr 14 09:14:32 2017 : Auth: (1) Login incorrect (pap: Cleartext password "hellox" does not match "known good" password): [bob] (from client localhost port 0)
Freeradius was compiled on CentOS 7 server with: ./configure --prefix=/usr/local/freeradius --enable-static=no --localstatedir=/var --with-docdir=no --with-vmps=no --with-oracle-include-dir=/usr/local/oracle/sdk/include --with-oracle-lib-dir=/usr/local/oracle
Any idea on what I can check?
Thanks, Andrea
Again, you *should* keep track of your local changes, and you *should* know what changes you made. Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
-- ---------------------------------------------------------------- The box said: 'install on Windows 95, NT 4.0 or better'. So I installed it on Linux.
----------------------------------------------------------------
Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188
Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino
- List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
access_reject]:11 - List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
-- ---------------------------------------------------------------- Hardware: The parts of a computer system that can be kicked.
----------------------------------------------------------------
Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188
Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino
- List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
Hi Alan, my problem is not what is going on. I'm forcing an error. My problem is why I get some debug errors in the log when the server is not running in debug mode. Andrea Il 14/04/2017 16:42, Alan Buxey ha scritto: > you are not - you are getting some of the stuff that gets logged. the > reason for 2 outputs is varied but usually seen with EAP tunneled methods > and the reaaon > for the auth failure AFTER things look okay is usually due to things like > failure for the server to log the event (in which case an error is seen and > the server > will reject the user). if you run in full debug mode then you will get > the full pucture of what is happening....and you've been told this many > times. just runt he server in full debug mode (radiusd -X) see what is > going on. fix it, THEN run it in production mode, there is no other > sensible way to proceed. > > alan > > On 14 April 2017 at 10:21, Andrea Gabellini < > andrea.gabellini@telecomitalia.sm> wrote: > >> Hi, >> >> the problem is the (0) and (1) in the log. I think this is the packet >> number. Using eap with wrong username or password logs some debug output >> (see previous posts). Alan DeKok says that this is a debug log, but >> radiusd isn't running debug mode. >> >> So the question is: why I got a debug output if the server is running >> without it? >> >> Thanks, >> Andrea >> >> Il 14/04/2017 11:03, Alan Buxey ha scritto: >>> hi, >>> >>> this is just the output of the standard freeradius logfile - which gives >>> you some basic info (with log_auth enabled) . >>> >>> you need to be looking at the output when you run the server in full >> debug >>> mode: >>> >>> radiusd -X >>> or >>> freeradiusd -X (if you're on debian/ubuntu builds) >>> >>> (and yes, thats just one big uppercase X) - as that will tell you >> exactly >>> what is happening and why something doesnt work. >>> >>> if this is a vanilla install with no local confidential stuff etc then >>> theres no reason to not post the output in full to the list - there will >> be >>> one or 2 obvious things >>> >>> >>> alan >>> >>> On 14 April 2017 at 08:19, Andrea Gabellini < >>> andrea.gabellini@telecomitalia.sm> wrote: >>> >>>> Il 13/04/2017 13:18, Alan DeKok ha scritto: >>>>> On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@ >>>> telecomitalia.sm> wrote: >>>>>> the server doesn't have any extra options: >>>>> <shrug> The server doesn't magically start printing all debug >>>> messages to the log file. >>>>> You've made some change in your local configuration to cause this to >>>> happen. Find it, and fix it. >>>>> $ cd /etc/raddb >>>>> $ grep -r debug . >>>>> >>>>> Maybe that will help. >>>> Hi Alan, >>>> >>>> the search for the debug keyword in the config directory doesn't return >>>> any hint. >>>> >>>> I removed the raddb directory and reinstalled all with make install. >>>> Just modified "auth = yes" and enabled the user "bob" from the default >>>> configuration: >>>> >>>> [09:14:22][radius31:/usr/local/freeradius/etc/raddb] #systemctl restart >>>> radiusd >>>> [09:14:26][radius31:/usr/local/freeradius/etc/raddb] #tail -f >>>> /var/log/radius/radius.log >>>> Fri Apr 14 09:14:26 2017 : Info: Debugger not attached >>>> Fri Apr 14 09:14:26 2017 : Warning: >>>> [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/ >> access_reject]:11 >>>> Check item "FreeRADIUS-Response-Delay" found in filter list for >>>> realm "DEFAULT". >>>> Fri Apr 14 09:14:26 2017 : Warning: >>>> [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/ >> access_reject]:11 >>>> Check item "FreeRADIUS-Response-Delay-USec" found in filter list for >>>> realm "DEFAULT". >>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server <default> >>>> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "sql" (see >>>> raddb/mods-available/README.rst) >>>> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "ldap" (see >>>> raddb/mods-available/README.rst) >>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server default >>>> Fri Apr 14 09:14:26 2017 : Info: # Skipping contents of 'if' as it is >>>> always 'false' -- >>>> /usr/local/freeradius/etc/raddb/sites-enabled/inner-tunnel:330 >>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server inner-tunnel >>>> Fri Apr 14 09:14:26 2017 : Info: Ready to process requests >>>> Fri Apr 14 09:14:30 2017 : Auth: (0) Login OK: [bob] (from client >>>> localhost port 0) >>>> Fri Apr 14 09:14:32 2017 : Auth: (1) Login incorrect (pap: Cleartext >>>> password "hellox" does not match "known good" password): [bob] (from >>>> client localhost port 0) >>>> >>>> Freeradius was compiled on CentOS 7 server with: ./configure >>>> --prefix=/usr/local/freeradius --enable-static=no --localstatedir=/var >>>> --with-docdir=no --with-vmps=no >>>> --with-oracle-include-dir=/usr/local/oracle/sdk/include >>>> --with-oracle-lib-dir=/usr/local/oracle >>>> >>>> Any idea on what I can check? >>>> >>>> Thanks, >>>> Andrea >>>> >>>>> Again, you *should* keep track of your local changes, and you >> *should* >>>> know what changes you made. >>>>> Alan DeKok. >>>>> >>>>> >>>>> - >>>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >>>> list/users.html >>>> >>>> -- >>>> ---------------------------------------------------------------- >>>> The box said: 'install on Windows 95, NT 4.0 or better'. So I installed >> it >>>> on Linux. >>>> >>>> ---------------------------------------------------------------- >>>> >>>> Ing. Andrea Gabellini >>>> Email: andrea.gabellini@telecomitalia.sm >>>> Skype: andreagabellini >>>> Tel: (+378) 0549 886111 >>>> Fax: (+378) 0549 886188 >>>> >>>> Telecom Italia San Marino S.p.A. >>>> Via XXVIII Luglio, 212 - Piano -2 >>>> 47893 Borgo Maggiore >>>> Republic of San Marino >>>> >>>> http://www.telecomitalia.sm >>>> >>>> - >>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >>>> list/users.html >>> - >>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >> list/users.html >> >> -- >> ---------------------------------------------------------------- >> Hardware: The parts of a computer system that can be kicked. >> >> ---------------------------------------------------------------- >> >> Ing. Andrea Gabellini >> Email: andrea.gabellini@telecomitalia.sm >> Skype: andreagabellini >> Tel: (+378) 0549 886111 >> Fax: (+378) 0549 886188 >> >> Telecom Italia San Marino S.p.A. >> Via XXVIII Luglio, 212 - Piano -2 >> 47893 Borgo Maggiore >> Republic of San Marino >> >> http://www.telecomitalia.sm >> >> - >> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >> list/users.html >> > - > List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html -- ---------------------------------------------------------------- The statement below is true. The statement above is false. ---------------------------------------------------------------- Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188 Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino http://www.telecomitalia.sm
Why do you think those are debug logs? If they are only meant to be in debug then either code needs changing so it's print statement is changed, report a bug OR your server is running with eg the -l stdout argument with a wrapper ensuring that output also goes to the standard log file , i think systemd does that. For better logging and control of logging, use the linelog module alan On 18 Apr 2017 7:48 am, "Andrea Gabellini" < andrea.gabellini@telecomitalia.sm> wrote: > Hi Alan, > > my problem is not what is going on. I'm forcing an error. > > My problem is why I get some debug errors in the log when the server is > not running in debug mode. > > Andrea > > Il 14/04/2017 16:42, Alan Buxey ha scritto: > > you are not - you are getting some of the stuff that gets logged. the > > reason for 2 outputs is varied but usually seen with EAP tunneled > methods > > and the reaaon > > for the auth failure AFTER things look okay is usually due to things like > > failure for the server to log the event (in which case an error is seen > and > > the server > > will reject the user). if you run in full debug mode then you will get > > the full pucture of what is happening....and you've been told this many > > times. just runt he server in full debug mode (radiusd -X) see what is > > going on. fix it, THEN run it in production mode, there is no other > > sensible way to proceed. > > > > alan > > > > On 14 April 2017 at 10:21, Andrea Gabellini < > > andrea.gabellini@telecomitalia.sm> wrote: > > > >> Hi, > >> > >> the problem is the (0) and (1) in the log. I think this is the packet > >> number. Using eap with wrong username or password logs some debug output > >> (see previous posts). Alan DeKok says that this is a debug log, but > >> radiusd isn't running debug mode. > >> > >> So the question is: why I got a debug output if the server is running > >> without it? > >> > >> Thanks, > >> Andrea > >> > >> Il 14/04/2017 11:03, Alan Buxey ha scritto: > >>> hi, > >>> > >>> this is just the output of the standard freeradius logfile - which > gives > >>> you some basic info (with log_auth enabled) . > >>> > >>> you need to be looking at the output when you run the server in full > >> debug > >>> mode: > >>> > >>> radiusd -X > >>> or > >>> freeradiusd -X (if you're on debian/ubuntu builds) > >>> > >>> (and yes, thats just one big uppercase X) - as that will tell you > >> exactly > >>> what is happening and why something doesnt work. > >>> > >>> if this is a vanilla install with no local confidential stuff etc then > >>> theres no reason to not post the output in full to the list - there > will > >> be > >>> one or 2 obvious things > >>> > >>> > >>> alan > >>> > >>> On 14 April 2017 at 08:19, Andrea Gabellini < > >>> andrea.gabellini@telecomitalia.sm> wrote: > >>> > >>>> Il 13/04/2017 13:18, Alan DeKok ha scritto: > >>>>> On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@ > >>>> telecomitalia.sm> wrote: > >>>>>> the server doesn't have any extra options: > >>>>> <shrug> The server doesn't magically start printing all debug > >>>> messages to the log file. > >>>>> You've made some change in your local configuration to cause this > to > >>>> happen. Find it, and fix it. > >>>>> $ cd /etc/raddb > >>>>> $ grep -r debug . > >>>>> > >>>>> Maybe that will help. > >>>> Hi Alan, > >>>> > >>>> the search for the debug keyword in the config directory doesn't > return > >>>> any hint. > >>>> > >>>> I removed the raddb directory and reinstalled all with make install. > >>>> Just modified "auth = yes" and enabled the user "bob" from the default > >>>> configuration: > >>>> > >>>> [09:14:22][radius31:/usr/local/freeradius/etc/raddb] #systemctl > restart > >>>> radiusd > >>>> [09:14:26][radius31:/usr/local/freeradius/etc/raddb] #tail -f > >>>> /var/log/radius/radius.log > >>>> Fri Apr 14 09:14:26 2017 : Info: Debugger not attached > >>>> Fri Apr 14 09:14:26 2017 : Warning: > >>>> [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/ > >> access_reject]:11 > >>>> Check item "FreeRADIUS-Response-Delay" found in filter list for > >>>> realm "DEFAULT". > >>>> Fri Apr 14 09:14:26 2017 : Warning: > >>>> [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/ > >> access_reject]:11 > >>>> Check item "FreeRADIUS-Response-Delay-USec" found in filter list for > >>>> realm "DEFAULT". > >>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server <default> > >>>> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "sql" (see > >>>> raddb/mods-available/README.rst) > >>>> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "ldap" (see > >>>> raddb/mods-available/README.rst) > >>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server default > >>>> Fri Apr 14 09:14:26 2017 : Info: # Skipping contents of 'if' as it is > >>>> always 'false' -- > >>>> /usr/local/freeradius/etc/raddb/sites-enabled/inner-tunnel:330 > >>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server inner-tunnel > >>>> Fri Apr 14 09:14:26 2017 : Info: Ready to process requests > >>>> Fri Apr 14 09:14:30 2017 : Auth: (0) Login OK: [bob] (from client > >>>> localhost port 0) > >>>> Fri Apr 14 09:14:32 2017 : Auth: (1) Login incorrect (pap: Cleartext > >>>> password "hellox" does not match "known good" password): [bob] (from > >>>> client localhost port 0) > >>>> > >>>> Freeradius was compiled on CentOS 7 server with: ./configure > >>>> --prefix=/usr/local/freeradius --enable-static=no --localstatedir=/var > >>>> --with-docdir=no --with-vmps=no > >>>> --with-oracle-include-dir=/usr/local/oracle/sdk/include > >>>> --with-oracle-lib-dir=/usr/local/oracle > >>>> > >>>> Any idea on what I can check? > >>>> > >>>> Thanks, > >>>> Andrea > >>>> > >>>>> Again, you *should* keep track of your local changes, and you > >> *should* > >>>> know what changes you made. > >>>>> Alan DeKok. > >>>>> > >>>>> > >>>>> - > >>>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ > >>>> list/users.html > >>>> > >>>> -- > >>>> ---------------------------------------------------------------- > >>>> The box said: 'install on Windows 95, NT 4.0 or better'. So I > installed > >> it > >>>> on Linux. > >>>> > >>>> ---------------------------------------------------------------- > >>>> > >>>> Ing. Andrea Gabellini > >>>> Email: andrea.gabellini@telecomitalia.sm > >>>> Skype: andreagabellini > >>>> Tel: (+378) 0549 886111 > >>>> Fax: (+378) 0549 886188 > >>>> > >>>> Telecom Italia San Marino S.p.A. > >>>> Via XXVIII Luglio, 212 - Piano -2 > >>>> 47893 Borgo Maggiore > >>>> Republic of San Marino > >>>> > >>>> http://www.telecomitalia.sm > >>>> > >>>> - > >>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ > >>>> list/users.html > >>> - > >>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ > >> list/users.html > >> > >> -- > >> ---------------------------------------------------------------- > >> Hardware: The parts of a computer system that can be kicked. > >> > >> ---------------------------------------------------------------- > >> > >> Ing. Andrea Gabellini > >> Email: andrea.gabellini@telecomitalia.sm > >> Skype: andreagabellini > >> Tel: (+378) 0549 886111 > >> Fax: (+378) 0549 886188 > >> > >> Telecom Italia San Marino S.p.A. > >> Via XXVIII Luglio, 212 - Piano -2 > >> 47893 Borgo Maggiore > >> Republic of San Marino > >> > >> http://www.telecomitalia.sm > >> > >> - > >> List info/subscribe/unsubscribe? See http://www.freeradius.org/ > >> list/users.html > >> > > - > > List info/subscribe/unsubscribe? See http://www.freeradius.org/ > list/users.html > > -- > ---------------------------------------------------------------- > The statement below is true. The statement above is false. > > ---------------------------------------------------------------- > > Ing. Andrea Gabellini > Email: andrea.gabellini@telecomitalia.sm > Skype: andreagabellini > Tel: (+378) 0549 886111 > Fax: (+378) 0549 886188 > > Telecom Italia San Marino S.p.A. > Via XXVIII Luglio, 212 - Piano -2 > 47893 Borgo Maggiore > Republic of San Marino > > http://www.telecomitalia.sm > > - > List info/subscribe/unsubscribe? See http://www.freeradius.org/ > list/users.html
Il 18/04/2017 09:18, Alan Buxey ha scritto: > Why do you think those are debug logs? Alan DeKok said that :-) > > If they are only meant to be in debug then either code needs changing so > it's print statement is changed, report a bug OR your server is running > with eg the -l stdout argument with a wrapper ensuring that output also > goes to the standard log file , i think systemd does that. the server runs under systemd. I tried also to run the server manually without systemd, but the problem remains... > > For better logging and control of logging, use the linelog module Thank you for the suggestion. I will try it. > > alan > > On 18 Apr 2017 7:48 am, "Andrea Gabellini" < > andrea.gabellini@telecomitalia.sm> wrote: > >> Hi Alan, >> >> my problem is not what is going on. I'm forcing an error. >> >> My problem is why I get some debug errors in the log when the server is >> not running in debug mode. >> >> Andrea >> >> Il 14/04/2017 16:42, Alan Buxey ha scritto: >>> you are not - you are getting some of the stuff that gets logged. the >>> reason for 2 outputs is varied but usually seen with EAP tunneled >> methods >>> and the reaaon >>> for the auth failure AFTER things look okay is usually due to things like >>> failure for the server to log the event (in which case an error is seen >> and >>> the server >>> will reject the user). if you run in full debug mode then you will get >>> the full pucture of what is happening....and you've been told this many >>> times. just runt he server in full debug mode (radiusd -X) see what is >>> going on. fix it, THEN run it in production mode, there is no other >>> sensible way to proceed. >>> >>> alan >>> >>> On 14 April 2017 at 10:21, Andrea Gabellini < >>> andrea.gabellini@telecomitalia.sm> wrote: >>> >>>> Hi, >>>> >>>> the problem is the (0) and (1) in the log. I think this is the packet >>>> number. Using eap with wrong username or password logs some debug output >>>> (see previous posts). Alan DeKok says that this is a debug log, but >>>> radiusd isn't running debug mode. >>>> >>>> So the question is: why I got a debug output if the server is running >>>> without it? >>>> >>>> Thanks, >>>> Andrea >>>> >>>> Il 14/04/2017 11:03, Alan Buxey ha scritto: >>>>> hi, >>>>> >>>>> this is just the output of the standard freeradius logfile - which >> gives >>>>> you some basic info (with log_auth enabled) . >>>>> >>>>> you need to be looking at the output when you run the server in full >>>> debug >>>>> mode: >>>>> >>>>> radiusd -X >>>>> or >>>>> freeradiusd -X (if you're on debian/ubuntu builds) >>>>> >>>>> (and yes, thats just one big uppercase X) - as that will tell you >>>> exactly >>>>> what is happening and why something doesnt work. >>>>> >>>>> if this is a vanilla install with no local confidential stuff etc then >>>>> theres no reason to not post the output in full to the list - there >> will >>>> be >>>>> one or 2 obvious things >>>>> >>>>> >>>>> alan >>>>> >>>>> On 14 April 2017 at 08:19, Andrea Gabellini < >>>>> andrea.gabellini@telecomitalia.sm> wrote: >>>>> >>>>>> Il 13/04/2017 13:18, Alan DeKok ha scritto: >>>>>>> On Apr 13, 2017, at 3:41 AM, Andrea Gabellini <andrea.gabellini@ >>>>>> telecomitalia.sm> wrote: >>>>>>>> the server doesn't have any extra options: >>>>>>> <shrug> The server doesn't magically start printing all debug >>>>>> messages to the log file. >>>>>>> You've made some change in your local configuration to cause this >> to >>>>>> happen. Find it, and fix it. >>>>>>> $ cd /etc/raddb >>>>>>> $ grep -r debug . >>>>>>> >>>>>>> Maybe that will help. >>>>>> Hi Alan, >>>>>> >>>>>> the search for the debug keyword in the config directory doesn't >> return >>>>>> any hint. >>>>>> >>>>>> I removed the raddb directory and reinstalled all with make install. >>>>>> Just modified "auth = yes" and enabled the user "bob" from the default >>>>>> configuration: >>>>>> >>>>>> [09:14:22][radius31:/usr/local/freeradius/etc/raddb] #systemctl >> restart >>>>>> radiusd >>>>>> [09:14:26][radius31:/usr/local/freeradius/etc/raddb] #tail -f >>>>>> /var/log/radius/radius.log >>>>>> Fri Apr 14 09:14:26 2017 : Info: Debugger not attached >>>>>> Fri Apr 14 09:14:26 2017 : Warning: >>>>>> [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/ >>>> access_reject]:11 >>>>>> Check item "FreeRADIUS-Response-Delay" found in filter list for >>>>>> realm "DEFAULT". >>>>>> Fri Apr 14 09:14:26 2017 : Warning: >>>>>> [/usr/local/freeradius/etc/raddb/mods-config/attr_filter/ >>>> access_reject]:11 >>>>>> Check item "FreeRADIUS-Response-Delay-USec" found in filter list for >>>>>> realm "DEFAULT". >>>>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server <default> >>>>>> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "sql" (see >>>>>> raddb/mods-available/README.rst) >>>>>> Fri Apr 14 09:14:26 2017 : Warning: Ignoring "ldap" (see >>>>>> raddb/mods-available/README.rst) >>>>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server default >>>>>> Fri Apr 14 09:14:26 2017 : Info: # Skipping contents of 'if' as it is >>>>>> always 'false' -- >>>>>> /usr/local/freeradius/etc/raddb/sites-enabled/inner-tunnel:330 >>>>>> Fri Apr 14 09:14:26 2017 : Info: Loaded virtual server inner-tunnel >>>>>> Fri Apr 14 09:14:26 2017 : Info: Ready to process requests >>>>>> Fri Apr 14 09:14:30 2017 : Auth: (0) Login OK: [bob] (from client >>>>>> localhost port 0) >>>>>> Fri Apr 14 09:14:32 2017 : Auth: (1) Login incorrect (pap: Cleartext >>>>>> password "hellox" does not match "known good" password): [bob] (from >>>>>> client localhost port 0) >>>>>> >>>>>> Freeradius was compiled on CentOS 7 server with: ./configure >>>>>> --prefix=/usr/local/freeradius --enable-static=no --localstatedir=/var >>>>>> --with-docdir=no --with-vmps=no >>>>>> --with-oracle-include-dir=/usr/local/oracle/sdk/include >>>>>> --with-oracle-lib-dir=/usr/local/oracle >>>>>> >>>>>> Any idea on what I can check? >>>>>> >>>>>> Thanks, >>>>>> Andrea >>>>>> >>>>>>> Again, you *should* keep track of your local changes, and you >>>> *should* >>>>>> know what changes you made. >>>>>>> Alan DeKok. >>>>>>> >>>>>>> >>>>>>> - >>>>>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >>>>>> list/users.html >>>>>> >>>>>> -- >>>>>> ---------------------------------------------------------------- >>>>>> The box said: 'install on Windows 95, NT 4.0 or better'. So I >> installed >>>> it >>>>>> on Linux. >>>>>> >>>>>> ---------------------------------------------------------------- >>>>>> >>>>>> Ing. Andrea Gabellini >>>>>> Email: andrea.gabellini@telecomitalia.sm >>>>>> Skype: andreagabellini >>>>>> Tel: (+378) 0549 886111 >>>>>> Fax: (+378) 0549 886188 >>>>>> >>>>>> Telecom Italia San Marino S.p.A. >>>>>> Via XXVIII Luglio, 212 - Piano -2 >>>>>> 47893 Borgo Maggiore >>>>>> Republic of San Marino >>>>>> >>>>>> http://www.telecomitalia.sm >>>>>> >>>>>> - >>>>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >>>>>> list/users.html >>>>> - >>>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >>>> list/users.html >>>> >>>> -- >>>> ---------------------------------------------------------------- >>>> Hardware: The parts of a computer system that can be kicked. >>>> >>>> ---------------------------------------------------------------- >>>> >>>> Ing. Andrea Gabellini >>>> Email: andrea.gabellini@telecomitalia.sm >>>> Skype: andreagabellini >>>> Tel: (+378) 0549 886111 >>>> Fax: (+378) 0549 886188 >>>> >>>> Telecom Italia San Marino S.p.A. >>>> Via XXVIII Luglio, 212 - Piano -2 >>>> 47893 Borgo Maggiore >>>> Republic of San Marino >>>> >>>> http://www.telecomitalia.sm >>>> >>>> - >>>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >>>> list/users.html >>>> >>> - >>> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >> list/users.html >> >> -- >> ---------------------------------------------------------------- >> The statement below is true. The statement above is false. >> >> ---------------------------------------------------------------- >> >> Ing. Andrea Gabellini >> Email: andrea.gabellini@telecomitalia.sm >> Skype: andreagabellini >> Tel: (+378) 0549 886111 >> Fax: (+378) 0549 886188 >> >> Telecom Italia San Marino S.p.A. >> Via XXVIII Luglio, 212 - Piano -2 >> 47893 Borgo Maggiore >> Republic of San Marino >> >> http://www.telecomitalia.sm >> >> - >> List info/subscribe/unsubscribe? See http://www.freeradius.org/ >> list/users.html > - > List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html -- ---------------------------------------------------------------- All generalizations are false, including this one. ---------------------------------------------------------------- Ing. Andrea Gabellini Email: andrea.gabellini@telecomitalia.sm Skype: andreagabellini Tel: (+378) 0549 886111 Fax: (+378) 0549 886188 Telecom Italia San Marino S.p.A. Via XXVIII Luglio, 212 - Piano -2 47893 Borgo Maggiore Republic of San Marino http://www.telecomitalia.sm
participants (3)
-
Alan Buxey -
Alan DeKok -
Andrea Gabellini