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