v3.0.9: Log auth failure message
Lai Fu Keung
tfklai at hku.hk
Fri Jul 10 10:55:41 CEST 2015
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.html
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
More information about the Freeradius-Users
mailing list