Hi, I am doing eap-peap-mschap2 authentication in v3.0.9. I am trying to log the failure message in linelog when auth. fails. Does anyone get logging failure message working with the "Multi-packet session state" mentioned in: http://lists.freeradius.org/pipermail/freeradius-users/2014-October/074522.h... I tested v3.0.9 with the default configuration template for default and inner-tunnel virtual servers and added my LDAP settings in them. I found that with incorrect username/password, I could see the failed message "mschap: MS-CHAP2-Response is incorrect" in debug log. But "Module-Failure-Message" is always empty, even within inner-tunnel when I called %{Module-Failure-Message} in linelog in post-auth-type reject. What else is missing? What other changes are needed other than default and inner-tunnel files? Any help/pointer is appreciated. The relevant debug log is attached below. Fu (8) Received Access-Request Id 37 from 10.28.123.29:3629 to 10.28.235.64:1812 length 304 (8) User-Name = "hjkk" (8) Framed-MTU = 1450 (8) EAP-Message = 0x0209005b19001703010050734f6f4d1064d84a3f94094275321919b869bb34d8fcd9ab79ddb89f5c5968545009377889406ac5174f2be9d9f5ea6e792797d33ac352d329450d5c4c220c62f586f55060a97722bcfe2f746dddd4c2 (8) Message-Authenticator = 0x132de909371fe1c630d7198832881c5c (8) Chargeable-User-Identity = 0x00 (8) NAS-IP-Address = 10.28.123.29 (8) NAS-Identifier = "ITS-TEST" (8) NAS-Port = 33779942 (8) NAS-Port-Id = "slot=2;subslot=0;port=55;vlanid=230" (8) NAS-Port-Type = Wireless-802.11 (8) Service-Type = Framed-User (8) Framed-Protocol = PPP (8) Calling-Station-Id = "10-1C-0C-79-26-49" (8) Called-Station-Id = "58-6A-B1-2A-F5-E0:its-test" (8) Acct-Session-Id = "11506101629790" (8) State = 0xd0f2ff51d7fbe675d0d3651812ae64d4 (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (8) authorize { (8) policy filter_username { (8) if (&User-Name =~ / /) { (8) if (&User-Name =~ / /) -> FALSE (8) if (&User-Name =~ /@.*@/ ) { (8) if (&User-Name =~ /@.*@/ ) -> FALSE (8) if (&User-Name =~ /\\.\\./ ) { (8) if (&User-Name =~ /\\.\\./ ) -> FALSE (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (8) if (&User-Name =~ /\\.$/) { (8) if (&User-Name =~ /\\.$/) -> FALSE (8) if (&User-Name =~ /@\\./) { (8) if (&User-Name =~ /@\\./) -> FALSE (8) } # policy filter_username = notfound (8) [preprocess] = ok (8) [chap] = noop (8) [mschap] = noop (8) [digest] = noop (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "hjkk", looking up realm NULL (8) suffix: Found realm "NULL" (8) suffix: Adding Stripped-User-Name = "hjkk" (8) suffix: Adding Realm = "NULL" (8) suffix: Authentication realm is LOCAL (8) [suffix] = ok (8) eap: Peer sent EAP Response (code 2) ID 9 length 91 (8) eap: Continuing tunnel setup (8) [eap] = ok (8) } # authorize = ok (8) Found Auth-Type = EAP (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) authenticate { (8) eap: Expiring EAP session with state 0x4472bda9447ba76b (8) eap: Finished EAP session with state 0xd0f2ff51d7fbe675 (8) eap: Previous EAP request found for state 0xd0f2ff51d7fbe675, released from the list (8) eap: Peer sent packet with method EAP PEAP (25) (8) eap: Calling submodule eap_peap to process data (8) eap_peap: Continuing EAP-TLS (8) eap_peap: [eaptls verify] = ok (8) eap_peap: Done initial handshake (8) eap_peap: [eaptls process] = ok (8) eap_peap: Session established. Decoding tunneled attributes (8) eap_peap: PEAP state phase2 (8) eap_peap: EAP method MSCHAPv2 (26) (8) eap_peap: Got tunneled request (8) eap_peap: EAP-Message = 0x0209003f1a0209003a316f628f361abe6d88fb33842b3de381960000000000000000bd78decc0bc9bb5a3b8c7b907dec1d9633e58d29b10cb98e00686a6b6b (8) eap_peap: Setting User-Name to hjkk (8) eap_peap: Sending tunneled request to inner-tunnel (8) eap_peap: EAP-Message = 0x0209003f1a0209003a316f628f361abe6d88fb33842b3de381960000000000000000bd78decc0bc9bb5a3b8c7b907dec1d9633e58d29b10cb98e00686a6b6b (8) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (8) eap_peap: User-Name = "hjkk" (8) eap_peap: State = 0x4472bda9447ba76bd8632d7ad5b1698f (8) Virtual server inner-tunnel received request (8) EAP-Message = 0x0209003f1a0209003a316f628f361abe6d88fb33842b3de381960000000000000000bd78decc0bc9bb5a3b8c7b907dec1d9633e58d29b10cb98e00686a6b6b (8) FreeRADIUS-Proxied-To = 127.0.0.1 (8) User-Name = "hjkk" (8) State = 0x4472bda9447ba76bd8632d7ad5b1698f (8) server inner-tunnel { (8) session-state: No cached attributes (8) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) authorize { (8) [chap] = noop (8) [mschap] = noop (8) suffix: Checking for suffix after "@" (8) suffix: No '@' in User-Name = "hjkk", looking up realm NULL (8) suffix: Found realm "NULL" (8) suffix: Adding Stripped-User-Name = "hjkk" (8) suffix: Adding Realm = "NULL" (8) suffix: Authentication realm is LOCAL (8) [suffix] = ok (8) update control { (8) &Proxy-To-Realm := LOCAL (8) } # update control = noop (8) eap: Peer sent EAP Response (code 2) ID 9 length 63 (8) eap: No EAP Start, assuming it's an on-going EAP conversation (8) [eap] = updated (8) [files] = noop rlm_ldap (ldap): Reserved connection (0) (8) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}}) (8) ldap: --> (uid=hjkk) (8) ldap: Performing search in "ou=radius,o=test,c=hk" with filter "(uid=hjkk)", scope "sub" (8) ldap: Waiting for search result... (8) ldap: Search returned no results rlm_ldap (ldap): Released connection (0) (8) [ldap] = notfound (8) redundant ldap_DB_redundant { rlm_ldap (ldap_DB_1): Reserved connection (0) (8) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})) (8) ldap_DB_1: --> (&(uid=hjkk) (8) ldap_DB_1: Performing search in "ou=radius,o=test,c=hk" with filter "(&(uid=hjkk))", scope "sub" (8) ldap_DB_1: Waiting for search result... (8) ldap_DB_1: Search returned no results rlm_ldap (ldap_DB_1): Released connection (0) (8) [ldap_DB_1] = notfound (8) } # redundant ldap_DB_redundant = notfound (8) } # authorize = notfound (8) Found Auth-Type = EAP (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) authenticate { (8) eap: Expiring EAP session with state 0x4472bda9447ba76b (8) eap: Finished EAP session with state 0x4472bda9447ba76b (8) eap: Previous EAP request found for state 0x4472bda9447ba76b, released from the list (8) eap: Peer sent packet with method EAP MSCHAPv2 (26) (8) eap: Calling submodule eap_mschapv2 to process data (8) eap_mschapv2: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (8) eap_mschapv2: Auth-Type MS-CHAP { (8) mschap: WARNING: No Cleartext-Password configured. Cannot create NT-Password (8) mschap: WARNING: No Cleartext-Password configured. Cannot create LM-Password (8) mschap: Creating challenge hash with username: hjkk (8) mschap: Client is using MS-CHAPv2 (8) mschap: ERROR: FAILED: No NT/LM-Password. Cannot perform authentication (8) mschap: ERROR: MS-CHAP2-Response is incorrect (8) [mschap] = reject (8) } # Auth-Type MS-CHAP = reject (8) MSCHAP-Error: E=691 R=1 (8) Could not parse new challenge from MS-CHAP-Error: 2 (8) ERROR: MSCHAP Failure (8) eap: Sending EAP Request (code 1) ID 10 length 18 (8) eap: EAP session adding &reply:State = 0x4472bda94578a76b (8) [eap] = handled (8) } # authenticate = handled (8) } # server inner-tunnel (8) Virtual server sending reply (8) EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0x4472bda94578a76bd8632d7ad5b1698f (8) eap_peap: Got tunneled reply code 11 (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (8) eap_peap: State = 0x4472bda94578a76bd8632d7ad5b1698f (8) eap_peap: Got tunneled reply RADIUS code 11 (8) eap_peap: EAP-Message = 0x010a00121a0409000d453d36393120523d31 (8) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (8) eap_peap: State = 0x4472bda94578a76bd8632d7ad5b1698f (8) eap_peap: Got tunneled Access-Challenge (8) eap: Sending EAP Request (code 1) ID 10 length 59 (8) eap: EAP session adding &reply:State = 0xd0f2ff51d8f8e675 (8) [eap] = handled (8) } # authenticate = handled (8) Using Post-Auth-Type Challenge (8) Post-Auth-Type sub-section not found. Ignoring. (8) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (8) Sent Access-Challenge Id 37 from 10.28.235.64:1812 to 10.28.123.29:3629 length 0 (8) EAP-Message = 0x010a003b19001703010030c0ef9777349d844241a9edc933b3addc585704359d08ab78a35194fd5bc5cde05f88638a9fe1508f3ce9bb22e39bcbf0 (8) Message-Authenticator = 0x00000000000000000000000000000000 (8) State = 0xd0f2ff51d8f8e675d0d3651812ae64d4 (8) Finished request Waking up in 4.8 seconds. (9) Received Access-Request Id 38 from 10.28.123.29:3629 to 10.28.235.64:1812 length 256 (9) User-Name = "hjkk" (9) Framed-MTU = 1450 (9) EAP-Message = 0x020a002b1900170301002012e475052c4413b52c418471e8a8d310de04b302ca35e9a0587593afdb804d1a (9) Message-Authenticator = 0xb723576d45a0404b72f7c165300d3d64 (9) Chargeable-User-Identity = 0x00 (9) NAS-IP-Address = 10.28.123.29 (9) NAS-Identifier = "ITS-TEST" (9) NAS-Port = 33779942 (9) NAS-Port-Id = "slot=2;subslot=0;port=55;vlanid=230" (9) NAS-Port-Type = Wireless-802.11 (9) Service-Type = Framed-User (9) Framed-Protocol = PPP (9) Calling-Station-Id = "10-1C-0C-79-26-49" (9) Called-Station-Id = "58-6A-B1-2A-F5-E0:its-test" (9) Acct-Session-Id = "11506101629790" (9) State = 0xd0f2ff51d8f8e675d0d3651812ae64d4 (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default (9) authorize { (9) policy filter_username { (9) if (&User-Name =~ / /) { (9) if (&User-Name =~ / /) -> FALSE (9) if (&User-Name =~ /@.*@/ ) { (9) if (&User-Name =~ /@.*@/ ) -> FALSE (9) if (&User-Name =~ /\\.\\./ ) { (9) if (&User-Name =~ /\\.\\./ ) -> FALSE (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) { (9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE (9) if (&User-Name =~ /\\.$/) { (9) if (&User-Name =~ /\\.$/) -> FALSE (9) if (&User-Name =~ /@\\./) { (9) if (&User-Name =~ /@\\./) -> FALSE (9) } # policy filter_username = notfound (9) [preprocess] = ok (9) [chap] = noop (9) [mschap] = noop (9) [digest] = noop (9) suffix: Checking for suffix after "@" (9) suffix: No '@' in User-Name = "hjkk", looking up realm NULL (9) suffix: Found realm "NULL" (9) suffix: Adding Stripped-User-Name = "hjkk" (9) suffix: Adding Realm = "NULL" (9) suffix: Authentication realm is LOCAL (9) [suffix] = ok (9) eap: Peer sent EAP Response (code 2) ID 10 length 43 (9) eap: Continuing tunnel setup (9) [eap] = ok (9) } # authorize = ok (9) Found Auth-Type = EAP (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (9) authenticate { (9) eap: Expiring EAP session with state 0x4472bda94578a76b (9) eap: Finished EAP session with state 0xd0f2ff51d8f8e675 (9) eap: Previous EAP request found for state 0xd0f2ff51d8f8e675, released from the list (9) eap: Peer sent packet with method EAP PEAP (25) (9) eap: Calling submodule eap_peap to process data (9) eap_peap: Continuing EAP-TLS (9) eap_peap: [eaptls verify] = ok (9) eap_peap: Done initial handshake (9) eap_peap: [eaptls process] = ok (9) eap_peap: Session established. Decoding tunneled attributes (9) eap_peap: PEAP state phase2 (9) eap_peap: EAP method MSCHAPv2 (26) (9) eap_peap: Got tunneled request (9) eap_peap: EAP-Message = 0x020a00091a04090004 (9) eap_peap: Setting User-Name to hjkk (9) eap_peap: Sending tunneled request to inner-tunnel (9) eap_peap: EAP-Message = 0x020a00091a04090004 (9) eap_peap: FreeRADIUS-Proxied-To = 127.0.0.1 (9) eap_peap: User-Name = "hjkk" (9) eap_peap: State = 0x4472bda94578a76bd8632d7ad5b1698f (9) Virtual server inner-tunnel received request (9) EAP-Message = 0x020a00091a04090004 (9) FreeRADIUS-Proxied-To = 127.0.0.1 (9) User-Name = "hjkk" (9) State = 0x4472bda94578a76bd8632d7ad5b1698f (9) server inner-tunnel { (9) session-state: No cached attributes (9) # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) authorize { (9) [chap] = noop (9) [mschap] = noop (9) suffix: Checking for suffix after "@" (9) suffix: No '@' in User-Name = "hjkk", looking up realm NULL (9) suffix: Found realm "NULL" (9) suffix: Adding Stripped-User-Name = "hjkk" (9) suffix: Adding Realm = "NULL" (9) suffix: Authentication realm is LOCAL (9) [suffix] = ok (9) update control { (9) &Proxy-To-Realm := LOCAL (9) } # update control = noop (9) eap: Peer sent EAP Response (code 2) ID 10 length 9 (9) eap: No EAP Start, assuming it's an on-going EAP conversation (9) [eap] = updated (9) [files] = noop rlm_ldap (ldap): Reserved connection (1) (9) ldap: EXPAND (uid=%{%{Stripped-User-Name}:-%{User-Name}}) (9) ldap: --> (uid=hjkk) (9) ldap: Performing search in "ou=radius,o=test,c=hk" with filter "(uid=hjkk)", scope "sub" (9) ldap: Waiting for search result... (9) ldap: Search returned no results rlm_ldap (ldap): Released connection (1) (9) [ldap] = notfound (9) redundant ldap_DB_redundant { rlm_ldap (ldap_DB_1): Reserved connection (1) (9) ldap_DB_1: EXPAND (&(uid=%{%{Stripped-User-Name}:-%{User-Name}})) (9) ldap_DB_1: --> (&(uid=hjkk)) (9) ldap_DB_1: Performing search in "ou=radius,o=test,c=hk" with filter "(&(uid=hjkk))", scope "sub" (9) ldap_DB_1: Waiting for search result... (9) ldap_DB_1: Search returned no results rlm_ldap (ldap_DB_1): Released connection (1) (9) [ldap_DB_1] = notfound (9) } # redundant ldap_DB_redundant = notfound (9) } # authorize = notfound (9) Found Auth-Type = EAP (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) authenticate { (9) eap: Expiring EAP session with state 0x4472bda94578a76b (9) eap: Finished EAP session with state 0x4472bda94578a76b (9) eap: Previous EAP request found for state 0x4472bda94578a76b, released from the list (9) eap: Peer sent packet with method EAP MSCHAPv2 (26) (9) eap: Calling submodule eap_mschapv2 to process data (9) eap: Sending EAP Failure (code 4) ID 10 length 4 (9) eap: Freeing handler (9) [eap] = reject (9) } # authenticate = reject (9) Failed to authenticate the user (9) Login incorrect: [hjkk] (from client wifi-test-13.29 port 0 via TLS tunnel) (9) Using Post-Auth-Type Reject (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel (9) Post-Auth-Type REJECT { (9) attr_filter.access_reject: EXPAND %{User-Name} (9) attr_filter.access_reject: --> hjkk (9) attr_filter.access_reject: Matched entry DEFAULT at line 16 (9) [attr_filter.access_reject] = updated (9) update outer.session-state { (9) No attributes updated (9) } # update outer.session-state = noop (9) linelog: EXPAND messages.%{%{reply:Packet-Type}:-default} (9) linelog: --> messages.Access-Reject (9) linelog: EXPAND /usr/local/var/log/radius/log/linelog-%Y%m%d (9) linelog: --> /usr/local/var/log/radius/log/linelog-20150710 (9) linelog: EXPAND %S,%{reply:Packet-Type},%{Packet-Src-IP-Address},%{NAS-IP-Address},%{User-Name},%{Calling-Station-Id},%{%{Aruba-Essid-Name}:-%{Called-Station-Id}},%{reply:Reply-Message},%{%{session-state:Module-Failure-Message}:-%{Module-Failure-Message}} (9) linelog: --> 2015-07-10 16:34:09,Access-Reject,10.28.123.29,,hjkk,,,, (9) [linelog] = ok (9) } # Post-Auth-Type REJECT = updated (9) } # server inner-tunnel (9) Virtual server sending reply (9) EAP-Message = 0x040a0004 (9) Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Got tunneled reply code 3 (9) eap_peap: EAP-Message = 0x040a0004 (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Got tunneled reply RADIUS code 3 (9) eap_peap: EAP-Message = 0x040a0004 (9) eap_peap: Message-Authenticator = 0x00000000000000000000000000000000 (9) eap_peap: Tunneled authentication was rejected (9) eap_peap: FAILURE (9) eap: Sending EAP Request (code 1) ID 11 length 43 (9) eap: EAP session adding &reply:State = 0xd0f2ff51d9f9e675 (9) [eap] = handled (9) } # authenticate = handled (9) Using Post-Auth-Type Challenge (9) Post-Auth-Type sub-section not found. Ignoring. (9) # Executing group from file /usr/local/etc/raddb/sites-enabled/default (9) Sent Access-Challenge Id 38 from 10.28.235.64:1812 to 10.28.123.29:3629 length 0 (9) EAP-Message = 0x010b002b19001703010020fce42371f591a9cd4075aac9d4852261963c568adb079dad4ed6ba87dd83e232 (9) Message-Authenticator = 0x00000000000000000000000000000000 (9) State = 0xd0f2ff51d9f9e675d0d3651812ae64d4 (9) Finished request