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