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