Strange password when authenticating via pppoe-server.

Sat Jul 12 15:55:24 CEST 2008

Sat Jul 12 15:53:55 2008 : Debug: Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 32770, id=59,
length=88
        Service-Type = Framed-User
        Framed-Protocol = PPP
        User-Name = "steve"
        User-Password = "\241\205N\255m@Ü\2247l\3559\2457\021"
        Calling-Station-Id = "00:04:61:5C:14:11"
        NAS-IP-Address = 127.0.0.1
        NAS-Port = 0
Sat Jul 12 15:54:03 2008 : Debug: +- entering group authorize
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[preprocess] returns ok
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[chap] returns noop
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[mschap] returns noop
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling suffix
(rlm_realm) for request 0
Sat Jul 12 15:54:03 2008 : Debug:     rlm_realm: No '@' in User-Name =
"steve", looking up realm NULL
Sat Jul 12 15:54:03 2008 : Debug:     rlm_realm: No such realm "NULL"
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
suffix (rlm_realm) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[suffix] returns noop
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   rlm_eap: No EAP-Message, not doing EAP
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from eap
(rlm_eap) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[eap] returns noop
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling unix
(rlm_unix) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
unix (rlm_unix) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[unix] returns notfound
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 0
Sat Jul 12 15:54:03 2008 : Debug:     users: Matched entry steve at line 76
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[files] returns ok
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling
expiration (rlm_expiration) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
expiration (rlm_expiration) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[expiration] returns noop
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling logintime
(rlm_logintime) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from
logintime (rlm_logintime) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[logintime] returns noop
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: calling pap
(rlm_pap) for request 0
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authorize]: returned from pap
(rlm_pap) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[pap] returns updated
Sat Jul 12 15:54:03 2008 : Debug:   rad_check_password:  Found Auth-Type
Sat Jul 12 15:54:03 2008 : Debug: auth: type "PAP"
Sat Jul 12 15:54:03 2008 : Debug: +- entering group PAP
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authenticate]: calling pap
(rlm_pap) for request 0
Sat Jul 12 15:54:03 2008 : Debug: rlm_pap: login attempt with password
"Ą?Nm@Ü??7lí9Ľ7?"
Sat Jul 12 15:54:03 2008 : Debug: rlm_pap: Using clear text password
"testing"
Sat Jul 12 15:54:03 2008 : Debug: rlm_pap: Passwords don't match
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[authenticate]: returned from
pap (rlm_pap) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[pap] returns reject
Sat Jul 12 15:54:03 2008 : Debug: auth: Failed to validate the user.
Sat Jul 12 15:54:03 2008 : Debug:   WARNING: Unprintable characters in the
password.      Double-check the shared secret on the server and the NAS!
Sat Jul 12 15:54:03 2008 : Debug:   Found Post-Auth-Type Reject
Sat Jul 12 15:54:03 2008 : Debug: +- entering group REJECT
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[post-auth]: calling
attr_filter.access_reject (rlm_attr_filter) for request 0
Sat Jul 12 15:54:03 2008 : Debug:       expand: %{User-Name} -> steve
Sat Jul 12 15:54:03 2008 : Debug:  attr_filter: Matched entry DEFAULT at
line 11
Sat Jul 12 15:54:03 2008 : Debug:   modsingle[post-auth]: returned from
attr_filter.access_reject (rlm_attr_filter) for request 0
Sat Jul 12 15:54:03 2008 : Debug: ++[attr_filter.access_reject] returns
updated
Sending Access-Reject of id 59 to 127.0.0.1 port 32770
Sat Jul 12 15:54:03 2008 : Debug: Finished request 0.
Sat Jul 12 15:54:03 2008 : Debug: Going to the next request
Sat Jul 12 15:54:03 2008 : Debug: Waking up in 4.9 seconds.
Sat Jul 12 15:54:08 2008 : Debug: Cleaning up request 0 ID 59 with
timestamp +8
Sat Jul 12 15:54:08 2008 : Debug: Ready to process requests.

On Sat, 12 Jul 2008 12:25:44 +0100, "Ivan Kalik" <tnt at kalik.net> wrote:
> Post the whole debug including the request. You have chopped off the
> front bit.
> 
> Ivan Kalik
> Kalik Informatika ISP
> 
> 
> Dana 12/7/2008, "Maciej Drobniuch" <maciej at drobniuch.pl> piše:
> 
>>
>>Hi!
>>Now I have a new problem.
>>When auth via radiusclient, everyting works fine:
>>
>>>radtest steve testing localhost 1813 somesecret
>>
>>Sat Jul 12 12:07:31 2008 : Debug:   modsingle[authenticate]: calling pap
>>(rlm_pap) for request 4
>>Sat Jul 12 12:07:31 2008 : Debug: rlm_pap: login attempt with password
>>"testing"
>>Sat Jul 12 12:07:31 2008 : Debug: rlm_pap: Using clear text password
>>"testing"
>>Sat Jul 12 12:07:31 2008 : Debug: rlm_pap: User authenticated
> successfully
>>Sat Jul 12 12:07:31 2008 : Debug:   modsingle[authenticate]: returned
> from
>>pap (rlm_pap) for request 4
>>Sat Jul 12 12:07:31 2008 : Debug: ++[pap] returns ok
>>Sat Jul 12 12:07:31 2008 : Debug: +- entering group post-auth
>>Sat Jul 12 12:07:31 2008 : Debug:   modsingle[post-auth]: calling exec
>>(rlm_exec) for request 4
>>Sat Jul 12 12:07:31 2008 : Debug:   modsingle[post-auth]: returned from
>>exec (rlm_exec) for request 4
>>Sat Jul 12 12:07:31 2008 : Debug: ++[exec] returns noop
>>Sending Access-Accept of id 146 to 127.0.0.1 port 32770
>>        Service-Type = Framed-User
>>        Framed-Protocol = PPP
>>        Framed-IP-Address = 172.16.3.33
>>        Framed-IP-Netmask = 255.255.255.0
>>        Framed-Routing = Broadcast-Listen
>>        Framed-Filter-Id = "std.ppp"
>>        Framed-MTU = 1500
>>        Framed-Compression = Van-Jacobson-TCP-IP
>>
>>I've also tried to auth using this command(and the login is also
>>successful):
>>echo User-Name = "steve", CHAP-Password = "testing" | radclient localhost
>>auth somesecret
>>
>>But when i've had tried to login from a client (windows xp) station using
>>the pppoe-server(on the server) the debug output looks like this:
>>Force PAP(require-pap) on pppoe-server:
>>Sat Jul 12 12:11:23 2008 : Debug: auth: type "PAP"
>>Sat Jul 12 12:11:23 2008 : Debug: +- entering group PAP
>>Sat Jul 12 12:11:23 2008 : Debug:   modsingle[authenticate]: calling pap
>>(rlm_pap) for request 7
>>Sat Jul 12 12:11:23 2008 : Debug: rlm_pap: login attempt with password
>>"Ĺ�Ä�23Ä�tn?? 8ĹĄÄž1RÄ�"
>>Sat Jul 12 12:11:23 2008 : Debug: rlm_pap: Using clear text password
>>"testing"
>>Sat Jul 12 12:11:23 2008 : Debug: rlm_pap: Passwords don't match
>>Sat Jul 12 12:11:23 2008 : Debug:   modsingle[authenticate]: returned
> from
>>pap (rlm_pap) for request 7
>>Sat Jul 12 12:11:23 2008 : Debug: ++[pap] returns reject
>>Sat Jul 12 12:11:23 2008 : Debug: auth: Failed to validate the user.
>>Sat Jul 12 12:11:23 2008 : Debug:   WARNING: Unprintable characters in
> the
>>password.      Double-check the shared secret on the server and the NAS!
>>Sat Jul 12 12:11:23 2008 : Debug:   Found Post-Auth-Type Reject
>>Sat Jul 12 12:11:23 2008 : Debug: +- entering group REJECT
>>Sat Jul 12 12:11:23 2008 : Debug:   modsingle[post-auth]: calling
>>attr_filter.access_reject (rlm_attr_filter) for request 7
>>Sat Jul 12 12:11:23 2008 : Debug:       expand: %{User-Name} -> steve
>>Sat Jul 12 12:11:23 2008 : Debug:  attr_filter: Matched entry DEFAULT at
>>line 11
>>Sat Jul 12 12:11:23 2008 : Debug:   modsingle[post-auth]: returned from
>>attr_filter.access_reject (rlm_attr_filter) for request 7
>>Sat Jul 12 12:11:23 2008 : Debug: ++[attr_filter.access_reject] returns
>>updated
>>Force CHAP(require-chap) on PPPoE server:
>>Sat Jul 12 12:13:04 2008 : Debug: auth: type "CHAP"
>>Sat Jul 12 12:13:04 2008 : Debug: +- entering group CHAP
>>Sat Jul 12 12:13:04 2008 : Debug:   modsingle[authenticate]: calling chap
>>(rlm_chap) for request 0
>>Sat Jul 12 12:13:04 2008 : Debug:   rlm_chap: login attempt by "steve"
> with
>>CHAP password
>>Sat Jul 12 12:13:04 2008 : Debug:   rlm_chap: Using clear text password
>>"testing" for user steve authentication.
>>Sat Jul 12 12:13:04 2008 : Debug:   rlm_chap: Password check failed
>>Sat Jul 12 12:13:04 2008 : Debug:   modsingle[authenticate]: returned
> from
>>chap (rlm_chap) for request 0
>>Sat Jul 12 12:13:04 2008 : Debug: ++[chap] returns reject
>>Sat Jul 12 12:13:04 2008 : Debug: auth: Failed to validate the user.
>>Sat Jul 12 12:13:04 2008 : Debug:   Found Post-Auth-Type Reject
>>Sat Jul 12 12:13:04 2008 : Debug: +- entering group REJECT
>>Sat Jul 12 12:13:04 2008 : Debug:   modsingle[post-auth]: calling
>>attr_filter.access_reject (rlm_attr_filter) for request 0
>>Sat Jul 12 12:13:04 2008 : Debug:       expand: %{User-Name} -> steve
>>Sat Jul 12 12:13:04 2008 : Debug:  attr_filter: Matched entry DEFAULT at
>>line 11
>>Sat Jul 12 12:13:04 2008 : Debug:   modsingle[post-auth]: returned from
>>attr_filter.access_reject (rlm_attr_filter) for request 0
>>Sat Jul 12 12:13:04 2008 : Debug: ++[attr_filter.access_reject] returns
>>updated
>>Sending Access-Reject of id 57 to 127.0.0.1 port 32770
>>Sat Jul 12 12:13:04 2008 : Debug: Finished request 0.
>>Sat Jul 12 12:13:04 2008 : Debug: Going to the next request
>>Sat Jul 12 12:13:04 2008 : Debug: Waking up in 4.9 seconds.
>>Sat Jul 12 12:13:09 2008 : Debug: Cleaning up request 0 ID 57 with
>>timestamp +8
>>Sat Jul 12 12:13:09 2008 : Debug: Ready to process requests.
>>
>>What's wrong again?
>>Thanks !
>>
>
-- 
------------------------
Maciej Drobniuch