Hi,

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