chilli + freeradius + mysql : Password check failed

27 Nov 2009

      Hi all,
   I have a problem, where I work, I installed a system wifi hotspot (chillispot+freeradius+mysql), all in one machine (debian lenny) for external workers.
   The problem is that freeradius does not understand the password it receives from chillispot L

   Fri Nov 27 16:13:30 2009 : Info: [chap] Using clear text password "P1s0S" for user 9799-8798-3665-6561 authentication.
   Fri Nov 27 16:13:30 2009 : Info: [chap] Password check failed

  P1s0S is the good passwd !!!  This well written in the MySQL .

  I think that chillispot is using PAP instead of CHAP, I've looked at the code file hotspotlogin.php :

--------------------------- hotspotlogin.php -----------------------------------------------------
    $response = md5("\0" . $_GET['Password'] . $newchal);
    $newpwd = pack("a32", $_GET['Password']);
    $pappassword = implode ("", unpack("H32", ($newpwd ^ $newchal)));
----------------------------  FIN ------------------------------------------------------------------

  I don’t now.
  Thanks J

  -------- radius –XXX --------------

Fri Nov 27 15:35:29 2009 : Debug: Waking up in 4.9 seconds.
Fri Nov 27 15:35:34 2009 : Info: Cleaning up request 12 ID 0 with timestamp +5614
Fri Nov 27 15:35:34 2009 : Debug: Ready to process requests.
rad_recv: Access-Request packet from host 192.168.65.99 port 54942, id=0, length=229
        User-Name = "9799-8798-3665-6561"
        CHAP-Challenge = 0x6f2ac78657926dd875b49f0178ce89d7
        CHAP-Password = 0x00a2d83146dc31d330e294298fafb575c2
        NAS-IP-Address = 0.0.0.0
        Service-Type = Login-User
        Framed-IP-Address = 192.168.182.4
        Calling-Station-Id = "00-1C-BF-D3-88-70"
        Called-Station-Id = "00-0E-7F-FE-01-F9"
        NAS-Identifier = "nas01"
        Acct-Session-Id = "4b0fec8100000000"
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 0
        Message-Authenticator = 0x368ff43e6530b497663e3e8b09be3ea8
        WISPr-Logoff-URL = "http://192.168.182.1:3990/logoff"
Fri Nov 27 16:13:30 2009 : Info: +- entering group authorize {...}
Fri Nov 27 16:13:30 2009 : Info: ++[preprocess] returns ok
Fri Nov 27 16:13:30 2009 : Info: [chap] Setting 'Auth-Type := CHAP'
Fri Nov 27 16:13:30 2009 : Info: ++[chap] returns ok
Fri Nov 27 16:13:30 2009 : Info: ++[mschap] returns noop
Fri Nov 27 16:13:30 2009 : Info: [suffix] No '@' in User-Name = "9799-8798-3665-6561", looking up realm NULL
Fri Nov 27 16:13:30 2009 : Info: [suffix] No such realm "NULL"
Fri Nov 27 16:13:30 2009 : Info: ++[suffix] returns noop
Fri Nov 27 16:13:30 2009 : Info: [eap] No EAP-Message, not doing EAP
Fri Nov 27 16:13:30 2009 : Info: ++[eap] returns noop
Fri Nov 27 16:13:30 2009 : Info: ++[unix] returns notfound
Fri Nov 27 16:13:30 2009 : Info: ++[files] returns noop
Fri Nov 27 16:13:30 2009 : Info: [sql]  expand: %{User-Name} -> 9799-8798-3665-6561
Fri Nov 27 16:13:30 2009 : Info: [sql] sql_set_user escaped user --> '9799-8798-3665-6561'
Fri Nov 27 16:13:30 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Fri Nov 27 16:13:30 2009 : Info: [sql]  expand: SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radcheck           WHERE username = '9799-8798-3665-6561'           ORDER BY id
Fri Nov 27 16:13:30 2009 : Info: [sql] User found in radcheck table
Fri Nov 27 16:13:30 2009 : Info: [sql]  expand: SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '%{SQL-User-Name}'           ORDER BY id -> SELECT id, username, attribute, value, op           FROM radreply           WHERE username = '9799-8798-3665-6561'           ORDER BY id
Fri Nov 27 16:13:30 2009 : Info: [sql]  expand: SELECT groupname           FROM radusergroup           WHERE username = '%{SQL-User-Name}'           ORDER BY priority -> SELECT groupname           FROM radusergroup           WHERE username = '9799-8798-3665-6561'           ORDER BY priority
Fri Nov 27 16:13:30 2009 : Info: [sql]  expand: SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           Value, op           FROM radgroupcheck           WHERE groupname = '1hora'           ORDER BY id
Fri Nov 27 16:13:30 2009 : Info: [sql] User found in group 1hora
Fri Nov 27 16:13:30 2009 : Info: [sql]  expand: SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '%{Sql-Group}'           ORDER BY id -> SELECT id, groupname, attribute,           value, op           FROM radgroupreply           WHERE groupname = '1hora'           ORDER BY id
Fri Nov 27 16:13:30 2009 : Debug: rlm_sql (sql): Released sql socket id: 2
Fri Nov 27 16:13:30 2009 : Info: ++[sql] returns ok
Fri Nov 27 16:13:30 2009 : Info: ++[expiration] returns noop
Fri Nov 27 16:13:30 2009 : Info: ++[logintime] returns noop
Fri Nov 27 16:13:30 2009 : Info: [pap] Found existing Auth-Type, not changing it.
Fri Nov 27 16:13:30 2009 : Info: ++[pap] returns noop
Fri Nov 27 16:13:30 2009 : Debug: rlm_sqlcounter: Entering module authorize code
Fri Nov 27 16:13:30 2009 : Debug: sqlcounter_expand:  'SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='%{User-Name}''
Fri Nov 27 16:13:30 2009 : Info: [noresetcounter]       expand: SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='%{User-Name}' -> SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='9799-8798-3665-6561'
Fri Nov 27 16:13:30 2009 : Debug: sqlcounter_expand:  '%{sql:SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='9799-8798-3665-6561'}'
Fri Nov 27 16:13:30 2009 : Info: [noresetcounter] sql_xlat
Fri Nov 27 16:13:30 2009 : Info: [noresetcounter]       expand: %{User-Name} -> 9799-8798-3665-6561
Fri Nov 27 16:13:30 2009 : Info: [noresetcounter] sql_set_user escaped user --> '9799-8798-3665-6561'
Fri Nov 27 16:13:30 2009 : Info: [noresetcounter]       expand: SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='9799-8798-3665-6561' -> SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='9799-8798-3665-6561'
Fri Nov 27 16:13:30 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 1
Fri Nov 27 16:13:30 2009 : Info: [noresetcounter] row[0] returned NULL
Fri Nov 27 16:13:30 2009 : Debug: rlm_sql (sql): Released sql socket id: 1
Fri Nov 27 16:13:30 2009 : Info: [noresetcounter]       expand: %{sql:SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='9799-8798-3665-6561'} -> 
Fri Nov 27 16:13:30 2009 : Debug: rlm_sqlcounter: No integer found in string ""
Fri Nov 27 16:13:30 2009 : Info: ++[noresetcounter] returns noop
Fri Nov 27 16:13:30 2009 : Debug: rlm_sqlcounter: Entering module authorize code
Fri Nov 27 16:13:30 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair
Fri Nov 27 16:13:30 2009 : Info: ++[dailycounter] returns noop
Fri Nov 27 16:13:30 2009 : Debug: rlm_sqlcounter: Entering module authorize code
Fri Nov 27 16:13:30 2009 : Debug: rlm_sqlcounter: Could not find Check item value pair
Fri Nov 27 16:13:30 2009 : Info: ++[monthlycounter] returns noop
Fri Nov 27 16:13:30 2009 : Info: Found Auth-Type = CHAP
Fri Nov 27 16:13:30 2009 : Info: +- entering group CHAP {...}
Fri Nov 27 16:13:30 2009 : Info: [chap] login attempt by "9799-8798-3665-6561" with CHAP password
Fri Nov 27 16:13:30 2009 : Info: [chap] Using clear text password "P1s0S" for user 9799-8798-3665-6561 authentication.
Fri Nov 27 16:13:30 2009 : Info: [chap] Password check failed
Fri Nov 27 16:13:30 2009 : Info: ++[chap] returns reject
Fri Nov 27 16:13:30 2009 : Info: Failed to authenticate the user.
Fri Nov 27 16:13:30 2009 : Info: Using Post-Auth-Type Reject
Fri Nov 27 16:13:30 2009 : Info: +- entering group REJECT {...}
Fri Nov 27 16:13:30 2009 : Info: [attr_filter.access_reject]    expand: %{User-Name} -> 9799-8798-3665-6561
Fri Nov 27 16:13:30 2009 : Debug:  attr_filter: Matched entry DEFAULT at line 11
Fri Nov 27 16:13:30 2009 : Info: ++[attr_filter.access_reject] returns updated
Fri Nov 27 16:13:30 2009 : Info: Delaying reject of request 13 for 1 seconds
Fri Nov 27 16:13:30 2009 : Debug: Going to the next request
Fri Nov 27 16:13:30 2009 : Debug: Waking up in 0.9 seconds.
Fri Nov 27 16:13:31 2009 : Info: Sending delayed reject for request 13
Sending Access-Reject of id 0 to 192.168.65.99 port 54942
Fri Nov 27 16:13:31 2009 : Debug: Waking up in 4.9 seconds.
Fri Nov 27 16:13:36 2009 : Info: Cleaning up request 13 ID 0 with timestamp +7896
Fri Nov 27 16:13:36 2009 : Debug: Ready to process requests.

------------------------------  FIN  ------------------------------------------------------------------- 		 	   		  
_________________________________________________________________
Windows Live: Friends get your Flickr, Yelp, and Digg updates when they e-mail you.
http://www.microsoft.com/middleeast/windows/windowslive/see-it-in-action/soc...

chilli + freeradius + mysql : Password check failed

David BiTx0