CHAP authentication fails when radtest communicates with freeradius 3.0.4 server through radsecproxy 1.6.2

anoop anoop.v at gadgeon.com
Wed Oct 22 16:26:18 CEST 2014


> Hi,
>
In process of evaluating Radsec feature, We encountered the failure with 
CHAP authentication.
Authentication was successful with PAP, MSCHAP and eap-md5.

Version(3.0.4) of freeradius is same in Client and Server.
Radsecproxy version is 1.6.2.

>
> The following is the radtest command used and the output.
> $radtest -x -t chap root root1234 127.0.0.1:1812 1812 radsec
> Sending Access-Request Id 80 from 0.0.0.0:35860 to 127.0.0.1:1812
>     User-Name = 'root'
>     CHAP-Password = 0xdb78dddafe77d7bb8d5d554b24d26ba2bb
>     NAS-IP-Address = 127.0.1.1
>     NAS-Port = 1812
>     Message-Authenticator = 0x00
> Received Access-Reject Id 80 from 127.0.0.1:1812 to 127.0.0.1:35860 
> length 33
>     Reply-Message = 'Hello, root'
> (0) -: Expected Access-Accept got Access-Reject
>
>
> The following is the freeradius 3.0.4 server log.
>
> Wed Oct 22 19:47:17 2014 : Debug: (0) Reading from socket 14
> READ FROM SSL 138
> 00: 17 03 01 00 20 63 12 16 67 d9 d9 9b 72 10 c9 28
> 10: 29 28 f9 9d a3 91 76 34 76 50 c2 02 0d ed a3 de
> 20: d0 b5 b6 05 41 17 03 01 00 60 ed 50 88 08 7f 9f
> 30: ed 15 d8 ed b9 0a c7 ea f8 75 21 fe df a9 1c 56
> 40: 91 85 c8 e8 4c fd 7d e3 14 52 78 a2 3d f0 fe fa
> 50: 57 a6 bc b7 87 4a 18 95 63 4f 6d 41 7e f4 dc f0
> 60: 10 f3 72 39 3b 58 8f 8c 0a 9f 0f 88 1a 5e 19 d4
> 70: 60 f6 c3 57 d7 a6 88 95 f0 5d f2 c6 de ee 93 0b
> 80: d0 24 74 ae 2a 6c 8e 8c 79 96
> Wed Oct 22 19:47:17 2014 : Debug: (0) Application data status 7
> TUNNELED DATA >  75
> 00: 01 01 00 4b ad 6c 2d c3 12 71 3a 32 7a 8a ed ae
> 10: 47 a7 34 4f 01 06 72 6f 6f 74 03 13 db 78 dd da
> 20: fe 77 d7 bb 8d 5d 55 4b 24 d2 6b a2 bb 04 06 7f
> 30: 00 01 01 05 06 00 00 07 14 50 12 07 3f 6b 50 ab
> 40: d7 1b 3f d8 e9 b1 2b 4e eb 18 e4
> Wed Oct 22 19:47:17 2014 : Debug: (0) tls_recv: Access-Request packet 
> from host 192.168.14.56 port 2083, id=1, length=75
> Wed Oct 22 19:47:17 2014 : Debug: Waking up in 0.3 seconds.
> Wed Oct 22 19:47:17 2014 : Debug: Thread 1 got semaphore
> Wed Oct 22 19:47:17 2014 : Debug: Thread 1 handling request 8, (2 
> handled so far)
>     User-Name = 'root'
>     CHAP-Password = 0xdb78dddafe77d7bb8d5d554b24d26ba2bb
>     NAS-IP-Address = 127.0.1.1
>     NAS-Port = 1812
>     Message-Authenticator = 0x073f6b50abd71b3fd8e9b12b4eeb18e4
> Wed Oct 22 19:47:17 2014 : Debug: (8) Received Access-Request packet 
> from host 192.168.14.56 port 2083, id=1, length=75
> Wed Oct 22 19:47:17 2014 : Debug: (8)     User-Name = 'root'
> Wed Oct 22 19:47:17 2014 : Debug: (8)     CHAP-Password = 
> 0xdb78dddafe77d7bb8d5d554b24d26ba2bb
> Wed Oct 22 19:47:17 2014 : Debug: (8)     NAS-IP-Address = 127.0.1.1
> Wed Oct 22 19:47:17 2014 : Debug: (8)     NAS-Port = 1812
> Wed Oct 22 19:47:17 2014 : Debug: (8) Message-Authenticator = 
> 0x073f6b50abd71b3fd8e9b12b4eeb18e4
> Wed Oct 22 19:47:17 2014 : Debug: (8) # Executing section authorize 
> from file /usr/local/etc/raddb/sites-enabled/default
> Wed Oct 22 19:47:17 2014 : Debug: (8)   authorize {
> Wed Oct 22 19:47:17 2014 : Debug: (8)   filter_username filter_username {
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (!&User-Name)
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (!&User-Name)  -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ / /)
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ / /)  -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /@.*@/ )
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /@.*@/ )  
> -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /\\.\\./ )
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /\\.\\./ 
> )  -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if ((&User-Name =~ /@/) && 
> (&User-Name !~ /@(.+)\\.(.+)$/))
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if ((&User-Name =~ /@/) && 
> (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /\\.$/)
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /\\.$/)   
> -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /@\\./)
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&User-Name =~ /@\\./)   
> -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)   } # filter_username 
> filter_username = notfound
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> preprocess (rlm_preprocess) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from preprocess (rlm_preprocess) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [preprocess] = ok
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> chap (rlm_chap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)  chap : Setting 'Auth-Type := CHAP'
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from chap (rlm_chap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [chap] = ok
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> mschap (rlm_mschap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from mschap (rlm_mschap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [mschap] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> digest (rlm_digest) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from digest (rlm_digest) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [digest] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> suffix (rlm_realm) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)  suffix : Checking for suffix 
> after "@"
> Wed Oct 22 19:47:17 2014 : Debug: (8)  suffix : No '@' in User-Name = 
> "root", looking up realm NULL
> Wed Oct 22 19:47:17 2014 : Debug: (8)  suffix : No such realm "NULL"
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from suffix (rlm_realm) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [suffix] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> eap (rlm_eap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)  eap : No EAP-Message, not doing EAP
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from eap (rlm_eap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [eap] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> files (rlm_files) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files : users: Matched entry 
> root at line 91
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files : ::: FROM 1 TO 0 MAX 1
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files : ::: Examining Reply-Message
> Wed Oct 22 19:47:17 2014 : Debug: Hello, %{User-Name}
> Wed Oct 22 19:47:17 2014 : Debug: Parsed xlat tree:
> Wed Oct 22 19:47:17 2014 : Debug: literal --> Hello,
> Wed Oct 22 19:47:17 2014 : Debug: attribute --> User-Name
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files : EXPAND Hello, %{User-Name}
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files :    --> Hello, root
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files : ::: APPENDING 
> Reply-Message FROM 0 TO 0
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files : ::: TO in 0 out 1
> Wed Oct 22 19:47:17 2014 : Debug: (8)  files : ::: to[0] = Reply-Message
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from files (rlm_files) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [files] = ok
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> expiration (rlm_expiration) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from expiration (rlm_expiration) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [expiration] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> logintime (rlm_logintime) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from logintime (rlm_logintime) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [logintime] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[authorize]: calling 
> pap (rlm_pap) for request 8
> Wed Oct 22 19:47:17 2014 : WARNING: (8)  pap : Auth-Type already set.  
> Not setting to PAP
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authorize]: returned 
> from pap (rlm_pap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [pap] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  } #  authorize = ok
> Wed Oct 22 19:47:17 2014 : Debug: (8) Found Auth-Type = CHAP
> Wed Oct 22 19:47:17 2014 : Debug: (8) # Executing group from file 
> /usr/local/etc/raddb/sites-enabled/default
> Wed Oct 22 19:47:17 2014 : Debug: (8)  Auth-Type CHAP {
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authenticate]: calling 
> chap (rlm_chap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)  chap : Login attempt by "root" 
> with CHAP password
> Wed Oct 22 19:47:17 2014 : Debug: (8)  chap : Comparing with "known 
> good" Cleartext-Password "root1234"
> Wed Oct 22 19:47:17 2014 : Debug: (8)   chap : CHAP challenge :  
> ad6c2dc312713a327a8aedae47a7344f
> Wed Oct 22 19:47:17 2014 : Debug: (8)   chap : Client sent : 
> 78dddafe77d7bb8d5d554b24d26ba2bb
> Wed Oct 22 19:47:17 2014 : Debug: (8)   chap : We calculated : 
> 8b672ba8589f7d0658b3b3e8e2002b09
> Wed Oct 22 19:47:17 2014 : ERROR: (8)  chap : Password is comparison 
> failed: password is incorrect
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[authenticate]: 
> returned from chap (rlm_chap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [chap] = reject
> Wed Oct 22 19:47:17 2014 : Debug: (8)  } # Auth-Type CHAP = reject
> Wed Oct 22 19:47:17 2014 : Debug: (8) Failed to authenticate the user
> Wed Oct 22 19:47:17 2014 : Debug: (8) Using Post-Auth-Type Reject
> Wed Oct 22 19:47:17 2014 : Debug: (8) # Executing group from file 
> /usr/local/etc/raddb/sites-enabled/default
> Wed Oct 22 19:47:17 2014 : Debug: (8)  Post-Auth-Type REJECT {
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[post-auth]: calling 
> attr_filter.access_reject (rlm_attr_filter) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: %{User-Name}
> Wed Oct 22 19:47:17 2014 : Debug: Parsed xlat tree:
> Wed Oct 22 19:47:17 2014 : Debug: attribute --> User-Name
> Wed Oct 22 19:47:17 2014 : Debug: (8) attr_filter.access_reject : 
> EXPAND %{User-Name}
> Wed Oct 22 19:47:17 2014 : Debug: (8) attr_filter.access_reject :    
> --> root
> Wed Oct 22 19:47:17 2014 : Debug: (8) attr_filter.access_reject : 
> Matched entry DEFAULT at line 11
> Wed Oct 22 19:47:17 2014 : Debug: (8) attr_filter.access_reject : 
> Reply-Message = 'Hello, root' allowed by Reply-Message =* ''
> Wed Oct 22 19:47:17 2014 : Debug: (8) attr_filter.access_reject : 
> Attribute "Reply-Message" allowed by 1 rules, disallowed by 0 rules
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[post-auth]: returned 
> from attr_filter.access_reject (rlm_attr_filter) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8) [attr_filter.access_reject] = 
> updated
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[post-auth]: calling 
> eap (rlm_eap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)  eap : Request didn't contain an 
> EAP-Message, not inserting EAP-Failure
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[post-auth]: returned 
> from eap (rlm_eap) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)   [eap] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8) remove_reply_message_if_eap 
> remove_reply_message_if_eap {
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&reply:EAP-Message && 
> &reply:Reply-Message)
> Wed Oct 22 19:47:17 2014 : Debug: (8)     if (&reply:EAP-Message && 
> &reply:Reply-Message) -> FALSE
> Wed Oct 22 19:47:17 2014 : Debug: (8)    else else {
> Wed Oct 22 19:47:17 2014 : Debug: (8)  modsingle[post-auth]: calling 
> noop (rlm_always) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8) modsingle[post-auth]: returned 
> from noop (rlm_always) for request 8
> Wed Oct 22 19:47:17 2014 : Debug: (8)     [noop] = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)    } # else else = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)   } # 
> remove_reply_message_if_eap remove_reply_message_if_eap = noop
> Wed Oct 22 19:47:17 2014 : Debug: (8)  } # Post-Auth-Type REJECT = updated
> Wed Oct 22 19:47:17 2014 : Debug: (8) Delaying response for 1 seconds
> Wed Oct 22 19:47:17 2014 : Debug: Thread 1 waiting to be assigned a 
> request
> Wed Oct 22 19:47:18 2014 : Debug: Waking up in 0.6 seconds.
> Wed Oct 22 19:47:18 2014 : Debug: (8) Sending delayed response
> Wed Oct 22 19:47:18 2014 : Debug: (8) Sending Access-Reject packet to 
> host 192.168.14.56 port 2083, id=1, length=0
> Wed Oct 22 19:47:18 2014 : Debug: (8)     Reply-Message = 'Hello, root'
> Sending Access-Reject Id 1 from 0.0.0.0:2083 to 192.168.14.56:2083
>     Reply-Message = 'Hello, root'
> TUNNELED DATA <  33
> 00: 03 01 00 21 76 36 57 24 bd 97 0d 4a 15 a5 f2 4d
> 10: 13 5f 61 fd 12 0d 48 65 6c 6c 6f 2c 20 72 6f 6f
> 20: 74
> WRITE TO SSL 69
> 00: 17 03 01 00 40 bb e3 13 b9 34 ff 57 aa 32 38 19
> 10: ad da 7c aa 29 76 bf 04 ff 5a b1 64 00 5d 3c ff
> 20: 2c a1 4f 5f 76 31 63 04 d3 93 f9 a1 41 b8 1f 23
> 30: c9 c6 7e 59 da 1a 46 ff a7 e0 eb 7d f1 a2 0a 56
> 40: f3 d4 c4 dd de
> Wed Oct 22 19:47:18 2014 : Debug: (8) Writing to socket 14
> Wed Oct 22 19:47:18 2014 : Debug: Waking up in 3.9 seconds.
> Wed Oct 22 19:47:23 2014 : Debug: (8) Cleaning up request packet ID 1 
> with timestamp +397
> Wed Oct 22 19:47:23 2014 : Debug: Waking up in 5.4 seconds.
> Wed Oct 22 19:47:28 2014 : Debug: Waking up in 18.9 seconds.
>
>
>
> Thanks and Regards,
> Anoop

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20141022/422fd8b3/attachment-0001.html>


More information about the Freeradius-Users mailing list