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@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@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