[Chilli] chilliJSON: request timed out (or reply is not valid JS)
Le Tran Dat
trandatnh at gmail.com
Tue Dec 3 08:01:26 UTC 2013
Hi all,
I trying to troubleshoot why CoovaChilli can not read radius's reply
message:
*You are already logged in - access denied*
If an account is already logged in to radius and another attempt to use the
same account to log on then CoovaChilli should show the message "*You are
already logged in - access denied".*
In my case, CoovaChilli keeps showing waiting page. This is my CoovaChilli
+ Radius debug log
*Radius: - Rejected "You are already logged in - access denied".*
> rad_recv: Accounting-Request packet from host 192.168.0.101 port 37822,
> id=65, length=207
> ChilliSpot-Version = "1.3.0"
> ChilliSpot-Attr-10 = 0x00000002
> Event-Timestamp = "Dec 2 2013 14:52:41 GMT"
> User-Name = "win"
> Acct-Input-Octets = 183
> Acct-Output-Octets = 104
> Acct-Input-Gigawords = 0
> Acct-Output-Gigawords = 0
> Acct-Input-Packets = 3
> Acct-Output-Packets = 2
> Acct-Session-Time = 73
> Acct-Terminate-Cause = User-Request
> Acct-Status-Type = Stop
> Acct-Session-Id = "529d89bb00000001"
> Framed-IP-Address = 192.168.1.2
> NAS-Port-Type = Wireless-802.11
> NAS-Port = 1
> NAS-Port-Id = "00000001"
> Calling-Station-Id = "00-0E-35-A1-5A-B9"
> Called-Station-Id = "04-F0-21-0A-EC-C0"
> NAS-IP-Address = 192.168.1.1
> NAS-Identifier = "nas01"
> WARNING: Empty preacct section. Using default return values.
> # Executing section accounting from file /etc/raddb/sites/default
> +- entering group accounting {...}
> [sql] expand: %{User-Name} -> win
> [sql] sql_set_user escaped user --> 'win'
> [sql] expand: %{Acct-Input-Gigawords} -> 0
> [sql] expand: %{Acct-Input-Octets} -> 183
> [sql] expand: %{Acct-Output-Gigawords} -> 0
> [sql] expand: %{Acct-Output-Octets} -> 104
> [sql] expand: %{Acct-Delay-Time} ->
> [sql] ... expanding second conditional
> [sql] expand: UPDATE radacct SET acctstoptime
> = '%S', acctsessiontime = '%{Acct-Session-Time}',
> acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 |
> '%{%{Acct-Input-Octets}:-0}',
> acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 |
> '%{%{Acct-Output-Octets}:-0}',
> acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay
> = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop =
> '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}'
> AND username = '%{SQL-User-Name}' AND
> nasipaddress = '%{NAS-IP-Address}'; delete FROM kickuser
> where user_mac = '%{Calling-Station-Id}' -> UPDATE
> radacct SET acctstoptime = '2013-12-03 07:36:37',
> acctsessiontime = '73', acctinputoctets = '0' <<
> 32 |
> rlm_sql (sql): Reserving sql socket id: 4
> rlm_sql (sql): Released sql socket id: 4
> ++[sql] returns ok
> ++[exec] returns noop
> Sending Accounting-Response of id 65 to 192.168.0.101 port 37822
> Finished request 0.
> Cleaning up request 0 ID 65 with timestamp +8
> Going to the next request
> Ready to process requests.
> rad_recv: Access-Request packet from host 192.168.0.101 port 37474,
> id=193, length=238
> ChilliSpot-Version = "1.3.0"
> User-Name = "pc_free"
> CHAP-Challenge = 0xbdee061bf023b7419ebf2ab5f72558ef
> CHAP-Password = 0x000c106595a19c42d402c69a3e0ef60e14
> Service-Type = Login-User
> Acct-Session-Id = "529d8a0500000001"
> Framed-IP-Address = 192.168.1.2
> NAS-Port-Type = Wireless-802.11
> NAS-Port = 1
> NAS-Port-Id = "00000001"
> Calling-Station-Id = "00-0E-35-A1-5A-B9"
> Called-Station-Id = "04-F0-21-0A-EC-C0"
> NAS-IP-Address = 192.168.1.1
> NAS-Identifier = "nas01"
> WISPr-Logoff-URL = "http://192.168.1.1:3990/logoff"
> Message-Authenticator = 0xd915b0c9f65d05890df3f013da5eb1ff
> # Executing section authorize from file /etc/raddb/sites/default
> +- entering group authorize {...}
> [chap] Setting 'Auth-Type := CHAP'
> ++[chap] returns ok
> [sql] expand: %{User-Name} -> pc_free
> [sql] sql_set_user escaped user --> 'pc_free'
> rlm_sql (sql): Reserving sql socket id: 3
> [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 = 'pc_free' ORDER BY id
> [sql] User found in radcheck table
> [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 = 'pc_free' ORDER BY id
> [sql] expand: SELECT groupname FROM radusergroup
> WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT
> groupname FROM radusergroup WHERE username = 'pc_free'
> ORDER BY priority
> [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 = '4' ORDER BY id
> [sql] User found in group 4
> [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 = '4' ORDER BY id
> rlm_sql (sql): Released sql socket id: 3
> ++[sql] returns ok
> ++? if (notfound)
> ? Evaluating (notfound) -> FALSE
> ++? if (notfound) -> FALSE
> rlm_sqlcounter: Entering module authorize code
> rlm_sqlcounter: Could not find Check item value pair
> ++[max-total-octets] returns noop
> ++? if (reject)
> ? Evaluating (reject) -> FALSE
> ++? if (reject) -> FALSE
> rlm_sqlcounter: Entering module authorize code
> rlm_sqlcounter: Could not find Check item value pair
> ++[max-total-dl-octets] returns noop
> ++? if (reject)
> ? Evaluating (reject) -> FALSE
> ++? if (reject) -> FALSE
> rlm_sqlcounter: Entering module authorize code
> rlm_sqlcounter: Could not find Check item value pair
> ++[max-total-ul-octets] returns noop
> ++? if (reject)
> ? Evaluating (reject) -> FALSE
> ++? if (reject) -> FALSE
> rlm_sqlcounter: Entering module authorize code
> rlm_sqlcounter: Could not find Check item value pair
> ++[max-session-timeout] returns noop
> ++? if (reject)
> ? Evaluating (reject) -> FALSE
> ++? if (reject) -> FALSE
> rlm_sqlcounter: Entering module authorize code
> rlm_sqlcounter: Could not find Check item value pair
> ++[accessperiod] returns noop
> ++? if (reject)
> ? Evaluating (reject) -> FALSE
> ++? if (reject) -> FALSE
> Found Auth-Type = CHAP
> # Executing group from file /etc/raddb/sites/default
> +- entering group CHAP {...}
> [chap] login attempt by "pc_free" with CHAP password
> [chap] Using clear text password "123123" for user pc_free authentication.
> [chap] chap user pc_free authenticated succesfully
> ++[chap] returns ok
> ++? if (reject)
> ? Evaluating (reject) -> FALSE
> ++? if (reject) -> FALSE
> # Executing section session from file /etc/raddb/sites/default
> +- entering group session {...}
> [sql] expand: %{User-Name} -> pc_free
> [sql] sql_set_user escaped user --> 'pc_free'
> [sql] expand: SELECT COUNT(*) FROM radacct
> WHERE username = '%{SQL-User-Name}'
> AND calledstationid = '%{Called-Station-Id}'
> AND calledstationid = '%{Called-Station-Id}'
> AND acctstoptime IS NULL -> SELECT COUNT(*)
> FROM radacct WHERE username =
> 'pc_free' AND calledstationid =
> '04-F0-21-0A-EC-C0' AND calledstationid =
> '04-F0-21-0A-EC-C0' AND acctstoptime IS NULL
> rlm_sql (sql): Reserving sql socket id: 2
> [sql] expand: SELECT radacctid, acctsessionid, username,
> nasipaddress, nasportid, framedipaddress,
> callingstationid, framedprotocol
> FROM radacct WHERE username =
> '%{SQL-User-Name}' AND calledstationid =
> '%{Called-Station-Id}' AND calledstationid
> = '%{Called-Station-Id}' AND acctstoptime IS
> NULL -> SELECT radacctid, acctsessionid, username,
> nasipaddress, nasportid, framedipaddress,
> callingstationid, framedprotocol FROM
> radacct WHERE username = 'pc_free'
> AND calledstationid = '04-F0-21-0A-EC-C0'
> AND calledstationid = '04-F0-21-0A-EC-C0'
> AND acctstoptime IS NULL
> checkrad: No NAS type, or type "other" not checking
> checkrad: No NAS type, or type "other" not checking
> rlm_sql (sql): Released sql socket id: 2
> ++[sql] returns ok
>
>
>
>
>
> *Delaying reject of request 1 for 1 seconds Going to the next
> requestWaking up in 0.9 seconds.Sending delayed reject for request 1Sending
> Access-Reject of id 193 to 192.168.0.101 port 37474 Reply-Message :=
> "\r\nYou are already logged in - access denied\r\n\n"*
> Waking up in 4.9 seconds.
> Cleaning up request 1 ID 193 with timestamp +21
> Ready to process requests.
*CoovaChilli log:*
> chilliController.logon( "pc_free" , "123123 " )
> chilliController.logon: asking for a new challenge
> chilliJSON: getting http://1.0.0.1/json/status . Waiting for reply ...
> enter chilliJSON.reply
> chilliJSON: JSON reply received in 63 ms
> version = 1.0
> clientState = 0
> challenge = bdee061bf023b7419ebf2ab5f72558ef
> location = [object Object]
> name = HotSpot
> redir = [object Object]
> originalURL = http://www.google.com.sg/
> redirectionURL =
> logoutURL = http://192.168.1.1:3990/logoff
> ipAddress = 192.168.1.2
> macAddress = 00-0E-35-A1-5A-B9
> Entering logonStep 2
> chilliController.logonStep2: Got challenge =
> bdee061bf023b7419ebf2ab5f72558ef
> chilliController.logonStep2: Calculating CHAP-Password =
> 0c106595a19c42d402c69a3e0ef60e14
>
> *chilliJSON: getting
> http://1.0.0.1/json/logon?username=pc_free&response=0c106595a19c42d402c69a3e0ef60e14&userurl=http%3a%2f%2fwww.google.com.sg%2f
> <http://1.0.0.1/json/logon?username=pc_free&response=0c106595a19c42d402c69a3e0ef60e14&userurl=http%3a%2f%2fwww.google.com.sg%2f>
> . Waiting for reply ... chilliJSON: request timed out (or reply is not
> valid JS)*
I attached logs of successful case as well
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.coova.org/pipermail/chilli/attachments/20131203/a89ec16b/attachment-0001.html>
-------------- next part --------------
rad_recv: Access-Request packet from host 192.168.0.101 port 41360, id=201, length=234
ChilliSpot-Version = "1.3.0"
User-Name = "win"
CHAP-Challenge = 0x08d4e2b8583eb807d297b3c31d6486d2
CHAP-Password = 0x00b646ade54a0a7fcbb2acd99763c4404e
Service-Type = Login-User
Acct-Session-Id = "529d8b1400000001"
Framed-IP-Address = 192.168.1.2
NAS-Port-Type = Wireless-802.11
NAS-Port = 1
NAS-Port-Id = "00000001"
Calling-Station-Id = "00-0E-35-A1-5A-B9"
Called-Station-Id = "04-F0-21-0A-EC-C0"
NAS-IP-Address = 192.168.1.1
NAS-Identifier = "nas01"
WISPr-Logoff-URL = "http://192.168.1.1:3990/logoff"
Message-Authenticator = 0xe8d082a6011655514db2c0943bd7b477
# Executing section authorize from file /etc/raddb/sites/default
+- entering group authorize {...}
[chap] Setting 'Auth-Type := CHAP'
++[chap] returns ok
[sql] expand: %{User-Name} -> win
[sql] sql_set_user escaped user --> 'win'
rlm_sql (sql): Reserving sql socket id: 0
[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 = 'win' ORDER BY id
[sql] User found in radcheck table
[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 = 'win' ORDER BY id
[sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'win' ORDER BY priority
[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 = '4' ORDER BY id
[sql] User found in group 4
[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 = '4' ORDER BY id
rlm_sql (sql): Released sql socket id: 0
++[sql] returns ok
++? if (notfound)
? Evaluating (notfound) -> FALSE
++? if (notfound) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-total-octets] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-total-dl-octets] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-total-ul-octets] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-session-timeout] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[accessperiod] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
Found Auth-Type = CHAP
# Executing group from file /etc/raddb/sites/default
+- entering group CHAP {...}
[chap] login attempt by "win" with CHAP password
[chap] Using clear text password "123123" for user win authentication.
[chap] chap user win authenticated succesfully
++[chap] returns ok
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
# Executing section session from file /etc/raddb/sites/default
+- entering group session {...}
[sql] expand: %{User-Name} -> win
[sql] sql_set_user escaped user --> 'win'
[sql] expand: SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND calledstationid = '%{Called-Station-Id}' AND calledstationid = '%{Called-Station-Id}' AND acctstoptime IS NULL -> SELECT COUNT(*) FROM radacct WHERE username = 'win' AND calledstationid = '04-F0-21-0A-EC-C0' AND calledstationid = '04-F0-21-0A-EC-C0' AND acctstoptime IS NULL
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
++[sql] returns ok
WARNING: Empty post-auth section. Using default return values.
Sending Access-Accept of id 201 to 192.168.0.101 port 41360
ChilliSpot-Bandwidth-Max-Up := 102400
ChilliSpot-Bandwidth-Max-Down := 102400
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Accounting-Request packet from host 192.168.0.101 port 37822, id=67, length=159
ChilliSpot-Version = "1.3.0"
ChilliSpot-Attr-10 = 0x00000002
Event-Timestamp = "Dec 2 2013 14:57:12 GMT"
User-Name = "win"
Acct-Status-Type = Start
Acct-Session-Id = "529d8b1400000001"
Framed-IP-Address = 192.168.1.2
NAS-Port-Type = Wireless-802.11
NAS-Port = 1
NAS-Port-Id = "00000001"
Calling-Station-Id = "00-0E-35-A1-5A-B9"
Called-Station-Id = "04-F0-21-0A-EC-C0"
NAS-IP-Address = 192.168.1.1
NAS-Identifier = "nas01"
WARNING: Empty preacct section. Using default return values.
# Executing section accounting from file /etc/raddb/sites/default
+- entering group accounting {...}
[sql] expand: %{User-Name} -> win
[sql] sql_set_user escaped user --> 'win'
[sql] expand: %{Acct-Delay-Time} ->
[sql] ... expanding second conditional
[sql] WARNING: Unknown module "X-Ascend-Session-Svr-Key" in string expansion "%"
[sql] ... expanding second conditional
[sql] expand: %{Tropos-Average-RSSI} ->
[sql] ... expanding second conditional
[sql] expand: %{ChilliSpot-DHCP-Hostname} ->
[sql] ... expanding second conditional
[sql] expand: %{ChilliSpot-DHCP-Vendor-Class-Id} ->
[sql] ... expanding second conditional
[sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay, xascendsessionsvrkey, rssi, hostname, hostarch, groupname ) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
++[sql] returns ok
++[exec] returns noop
Sending Accounting-Response of id 67 to 192.168.0.101 port 37822
Finished request 4.
Cleaning up request 4 ID 67 with timestamp +280
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 3 ID 201 with timestamp +280
Ready to process requests.
-------------- next part --------------
rad_recv: Accounting-Request packet from host 192.168.0.101 port 37822, id=65, length=207
ChilliSpot-Version = "1.3.0"
ChilliSpot-Attr-10 = 0x00000002
Event-Timestamp = "Dec 2 2013 14:52:41 GMT"
User-Name = "win"
Acct-Input-Octets = 183
Acct-Output-Octets = 104
Acct-Input-Gigawords = 0
Acct-Output-Gigawords = 0
Acct-Input-Packets = 3
Acct-Output-Packets = 2
Acct-Session-Time = 73
Acct-Terminate-Cause = User-Request
Acct-Status-Type = Stop
Acct-Session-Id = "529d89bb00000001"
Framed-IP-Address = 192.168.1.2
NAS-Port-Type = Wireless-802.11
NAS-Port = 1
NAS-Port-Id = "00000001"
Calling-Station-Id = "00-0E-35-A1-5A-B9"
Called-Station-Id = "04-F0-21-0A-EC-C0"
NAS-IP-Address = 192.168.1.1
NAS-Identifier = "nas01"
WARNING: Empty preacct section. Using default return values.
# Executing section accounting from file /etc/raddb/sites/default
+- entering group accounting {...}
[sql] expand: %{User-Name} -> win
[sql] sql_set_user escaped user --> 'win'
[sql] expand: %{Acct-Input-Gigawords} -> 0
[sql] expand: %{Acct-Input-Octets} -> 183
[sql] expand: %{Acct-Output-Gigawords} -> 0
[sql] expand: %{Acct-Output-Octets} -> 104
[sql] expand: %{Acct-Delay-Time} ->
[sql] ... expanding second conditional
[sql] expand: UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'; delete FROM kickuser where user_mac = '%{Calling-Station-Id}' -> UPDATE radacct SET acctstoptime = '2013-12-03 07:36:37', acctsessiontime = '73', acctinputoctets = '0' << 32 |
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
++[sql] returns ok
++[exec] returns noop
Sending Accounting-Response of id 65 to 192.168.0.101 port 37822
Finished request 0.
Cleaning up request 0 ID 65 with timestamp +8
Going to the next request
Ready to process requests.
rad_recv: Access-Request packet from host 192.168.0.101 port 37474, id=193, length=238
ChilliSpot-Version = "1.3.0"
User-Name = "pc_free"
CHAP-Challenge = 0xbdee061bf023b7419ebf2ab5f72558ef
CHAP-Password = 0x000c106595a19c42d402c69a3e0ef60e14
Service-Type = Login-User
Acct-Session-Id = "529d8a0500000001"
Framed-IP-Address = 192.168.1.2
NAS-Port-Type = Wireless-802.11
NAS-Port = 1
NAS-Port-Id = "00000001"
Calling-Station-Id = "00-0E-35-A1-5A-B9"
Called-Station-Id = "04-F0-21-0A-EC-C0"
NAS-IP-Address = 192.168.1.1
NAS-Identifier = "nas01"
WISPr-Logoff-URL = "http://192.168.1.1:3990/logoff"
Message-Authenticator = 0xd915b0c9f65d05890df3f013da5eb1ff
# Executing section authorize from file /etc/raddb/sites/default
+- entering group authorize {...}
[chap] Setting 'Auth-Type := CHAP'
++[chap] returns ok
[sql] expand: %{User-Name} -> pc_free
[sql] sql_set_user escaped user --> 'pc_free'
rlm_sql (sql): Reserving sql socket id: 3
[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 = 'pc_free' ORDER BY id
[sql] User found in radcheck table
[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 = 'pc_free' ORDER BY id
[sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'pc_free' ORDER BY priority
[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 = '4' ORDER BY id
[sql] User found in group 4
[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 = '4' ORDER BY id
rlm_sql (sql): Released sql socket id: 3
++[sql] returns ok
++? if (notfound)
? Evaluating (notfound) -> FALSE
++? if (notfound) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-total-octets] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-total-dl-octets] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-total-ul-octets] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[max-session-timeout] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[accessperiod] returns noop
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
Found Auth-Type = CHAP
# Executing group from file /etc/raddb/sites/default
+- entering group CHAP {...}
[chap] login attempt by "pc_free" with CHAP password
[chap] Using clear text password "123123" for user pc_free authentication.
[chap] chap user pc_free authenticated succesfully
++[chap] returns ok
++? if (reject)
? Evaluating (reject) -> FALSE
++? if (reject) -> FALSE
# Executing section session from file /etc/raddb/sites/default
+- entering group session {...}
[sql] expand: %{User-Name} -> pc_free
[sql] sql_set_user escaped user --> 'pc_free'
[sql] expand: SELECT COUNT(*) FROM radacct WHERE username = '%{SQL-User-Name}' AND calledstationid = '%{Called-Station-Id}' AND calledstationid = '%{Called-Station-Id}' AND acctstoptime IS NULL -> SELECT COUNT(*) FROM radacct WHERE username = 'pc_free' AND calledstationid = '04-F0-21-0A-EC-C0' AND calledstationid = '04-F0-21-0A-EC-C0' AND acctstoptime IS NULL
rlm_sql (sql): Reserving sql socket id: 2
[sql] expand: SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND calledstationid = '%{Called-Station-Id}' AND calledstationid = '%{Called-Station-Id}' AND acctstoptime IS NULL -> SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = 'pc_free' AND calledstationid = '04-F0-21-0A-EC-C0' AND calledstationid = '04-F0-21-0A-EC-C0' AND acctstoptime IS NULL
checkrad: No NAS type, or type "other" not checking
checkrad: No NAS type, or type "other" not checking
rlm_sql (sql): Released sql socket id: 2
++[sql] returns ok
Delaying reject of request 1 for 1 seconds
Going to the next request
Waking up in 0.9 seconds.
Sending delayed reject for request 1
Sending Access-Reject of id 193 to 192.168.0.101 port 37474
Reply-Message := "\r\nYou are already logged in - access denied\r\n\n"
Waking up in 4.9 seconds.
Cleaning up request 1 ID 193 with timestamp +21
Ready to process requests.
-------------- next part --------------
chilliController.logon( "win" , "123123 " )
chilliController.logon: asking for a new challenge
scriptElement: http://1.0.0.1/json/status?callback=chilliJSON.reply&0.8985460929106921
chilliJSON: getting http://1.0.0.1/json/status . Waiting for reply ...
enter chilliJSON.reply
chilliJSON: JSON reply received in 275 ms
version = 1.0
clientState = 0
challenge = 08d4e2b8583eb807d297b3c31d6486d2
location = [object Object]
name = HotSpot
redir = [object Object]
originalURL =
redirectionURL =
logoutURL = http://192.168.1.1:3990/logoff
ipAddress = 192.168.1.2
macAddress = 00-0E-35-A1-5A-B9
Entering logonStep 2
chilliController.logonStep2: Got challenge = 08d4e2b8583eb807d297b3c31d6486d2
chilliController.logonStep2: Calculating CHAP-Password = b646ade54a0a7fcbb2acd99763c4404e
scriptElement: http://1.0.0.1/json/logon?username=win&response=b646ade54a0a7fcbb2acd99763c4404e&userurl=http%3a%2f%2fwww.google.com.sg%2f&callback=chilliJSON.reply&0.18908492452464998
chilliJSON: getting http://1.0.0.1/json/logon?username=win&response=b646ade54a0a7fcbb2acd99763c4404e&userurl=http%3a%2f%2fwww.google.com.sg%2f . Waiting for reply ...
enter chilliJSON.reply
chilliJSON: JSON reply received in 43 ms
version = 1.0
clientState = 1
redir = [object Object]
originalURL = http://www.google.com.sg/
redirectionURL =
logoutURL = http://192.168.1.1:3990/logoff
ipAddress = 192.168.1.2
macAddress = 00-0E-35-A1-5A-B9
session = [object Object]
sessionId = 529d8b1400000001
userName = win
startTime = 1385996232
sessionTimeout = 0
idleTimeout = 300
accounting = [object Object]
sessionTime = 0
idleTime = 0
inputOctets = 0
outputOctets = 0
inputGigawords = 0
outputGigawords = 0
viewPoint = client
chilliController.processReply: Calling onUpdate. clienState = 1
Update UI is called. chilliController.clientState = 1
-------------- next part --------------
chilliController.processReply: Calling onUpdate. clienState = 0
Update UI is called. chilliController.clientState = 0
chilliController.logon( "pc_free" , "123123 " )
chilliController.logon: asking for a new challenge
chilliJSON: getting http://1.0.0.1/json/status . Waiting for reply ...
enter chilliJSON.reply
chilliJSON: JSON reply received in 63 ms
version = 1.0
clientState = 0
challenge = bdee061bf023b7419ebf2ab5f72558ef
location = [object Object]
name = HotSpot
redir = [object Object]
originalURL = http://www.google.com.sg/
redirectionURL =
logoutURL = http://192.168.1.1:3990/logoff
ipAddress = 192.168.1.2
macAddress = 00-0E-35-A1-5A-B9
Entering logonStep 2
chilliController.logonStep2: Got challenge = bdee061bf023b7419ebf2ab5f72558ef
chilliController.logonStep2: Calculating CHAP-Password = 0c106595a19c42d402c69a3e0ef60e14
chilliJSON: getting http://1.0.0.1/json/logon?username=pc_free&response=0c106595a19c42d402c69a3e0ef60e14&userurl=http%3a%2f%2fwww.google.com.sg%2f . Waiting for reply ...
chilliJSON: request timed out (or reply is not valid JS)
More information about the Chilli
mailing list