Problem with log and PEAP/MS-CHAPv2

12 Apr 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@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