Problem with log and PEAP/MS-CHAPv2
Andrea Gabellini
andrea.gabellini at telecomitalia.sm
Wed Apr 12 11:37:41 CEST 2017
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 at 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
More information about the Freeradius-Users
mailing list