Menu ▾ ▴

Coova Not responding to login / Hotspot not responding

Help
Carlos Agraz
2016-01-23
2022-08-19
1 2 > >> (Page 1 of 2)

  • Carlos Agraz

    Carlos Agraz - 2016-01-23

    Hi Guys

    I've been having trouble make the splash page authentication. After trying to log with several users (both new and the dvdwalt from default installation) I get the same error
    1 Hotspot not responding

    Latest Challenge could not be fetched from hotspot

    2 Coova Not responding to login

    requests Coova Not responding to login request

    I read and did most of the recommendations from the forum but with no luck (check that both secret keys are the same, etc.)

    Has anyone had the same problem?

    I’m running a home server with Ubuntu 14.04 and NGINX

     

  • Nguyen Nam

    Nguyen Nam - 2016-01-30

    yes same here. Just re-installed RD and ran into exactly same problem. Will dig to see whats wrong

     
    Thumbnail
    rd_request2.jpg

  • Nguyen Nam

    Nguyen Nam - 2016-01-30

    Hello,
    Looking at the rdConnect.js, I found this piece of code that generate error.
    var urlStatus = 'http://'+uamIp+':'+uamPort+'/json/status';
    $.ajax({url: urlStatus + "?callback=?", dataType: "jsonp",timeout: ajaxTimeout})

    Since my AP was behind couple NAT, there is no way for RD to connect with AP with that ajax call (sorry I'm not PHP developer). So how the UAM supposed to work here?
    Regards,
    Nguyen

     

  • Nguyen Nam

    Nguyen Nam - 2016-01-30

    Wow stupid me. The call was from desktop browser to AP, so its supposed to get through. Wireshark capture show this:

    1783 114.853315000 192.168.9.173 192.168.7.1 HTTP 865 GET /json/logon?callback=jQuery111307570531470701098_1454147163966&username=click_to_connect%40&password=ee9942be2753979c5a3db08c10a125a2&_=1454147163975 HTTP/1.1

    The problem is lying with Coova, cause it not responded after 5-6 HTTP calls.

    Will keep working on coova side

     

  • Nahom

    Nahom - 2016-01-30

    You need to make sure that you have added either nasid (your access point) or ssid to the "Dynamic keys" of the "Dynamic login pages" tab.

     

  • Nguyen Nam

    Nguyen Nam - 2016-01-30

    Yes nasid was added to Dynamic Keys of Dynamic Login Pages. The Dynamic Login Pages show as expected.

    Keep tracing I saw that the JSON interface working, cause Coova make a query into radiusd of RD. But then it stop working with:

    Sat Jan 30 17:21:20 2016 : Info: Ready to process requests.
    Sat Jan 30 17:21:20 2016 : Error: Ignoring request to authentication address * port 1812 from unknown client 192.168.0.11 port 57371

    And Coova JSON stop responding after that. Quite weird

     

  • Nahom

    Nahom - 2016-01-30

    Oh ok, I remember now. You need to add the nasid to the "optional info" tab of the nas tab of the nas devices applet

     

  • Nguyen Nam

    Nguyen Nam - 2016-01-30

    Hmmmm, cant get it. Something wrong with click_to_connect permanent user. How can it be wrong? It's just an account created as permanent user (phong@dd-wrt) in this case, with dd-wrt as suffix. All was supplied, and it dont work???? Password dont match? SMH

    Nguyen

    rad_recv: Access-Request packet from host 192.168.0.11 port 59238, id=75, length=280
    ChilliSpot-Version = "1.3.0"
    User-Name = "phong@dd-wrt"
    User-Password = "\264\325P\237\267\311l"
    Service-Type = Login-User
    Acct-Session-Id = "56ac954a00000001"
    Framed-IP-Address = 192.168.7.13
    NAS-Port-Type = Wireless-802.11
    NAS-Port = 1
    NAS-Port-Id = "00000001"
    Calling-Station-Id = "10-2A-B3-68-94-3E"
    Called-Station-Id = "C4-6E-1F-E9-94-CC"
    NAS-IP-Address = 192.168.7.1
    NAS-Identifier = "dd-wrt"
    WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
    WISPr-Location-Name = "My_HotSpot"
    WISPr-Logoff-URL = "http://192.168.7.1:3990/logoff"
    Message-Authenticator = 0x0ef55c65470782f2c733926bfe04647a
    Sat Jan 30 17:50:16 2016 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
    Sat Jan 30 17:50:16 2016 : Info: +group authorize {
    Sat Jan 30 17:50:16 2016 : Info: ++[preprocess] = ok
    Sat Jan 30 17:50:16 2016 : Info: ++policy rewrite.calling_station_id {
    Sat Jan 30 17:50:16 2016 : Info: +++? if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (Calling-Station-Id) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: expand: %{Calling-Station-Id} -> 10-2A-B3-68-94-3E
    Sat Jan 30 17:50:16 2016 : Info: expand: policy.mac-addr -> policy.mac-addr
    Sat Jan 30 17:50:16 2016 : Info: expand: ^%{config:policy.mac-addr}$ -> ^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
    Sat Jan 30 17:50:16 2016 : Info: ++++update request {
    Sat Jan 30 17:50:16 2016 : Info: expand: %{1}-%{2}-%{3}-%{4}-%{5}-%{6} -> 10-2A-B3-68-94-3E
    Sat Jan 30 17:50:16 2016 : Info: expand: %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} -> 10-2a-b3-68-94-3e
    Sat Jan 30 17:50:16 2016 : Info: ++++} # update request = noop
    Sat Jan 30 17:50:16 2016 : Info: ++++[updated] = updated
    Sat Jan 30 17:50:16 2016 : Info: +++} # if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Info: ++} # policy rewrite.calling_station_id = updated
    Sat Jan 30 17:50:16 2016 : Info: ++[chap] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[mschap] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[digest] = noop
    Sat Jan 30 17:50:16 2016 : Info: [suffix] Looking up realm "dd-wrt" for User-Name = "phong@dd-wrt"
    Sat Jan 30 17:50:16 2016 : Info: [suffix] No such realm "dd-wrt"
    Sat Jan 30 17:50:16 2016 : Info: ++[suffix] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++? if (!EAP-Message)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating !(EAP-Message) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++? if (!EAP-Message) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++if (!EAP-Message) {
    Sat Jan 30 17:50:16 2016 : Info: +++policy RADIUSdesk_main {
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (request:User-Name =~ /^([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})$/i)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (request:User-Name =~ /^([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})$/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (request:User-Name =~ /^([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})$/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'}" == 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' -> SELECT count(username) FROM radcheck WHERE radcheck.username='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'} -> 6
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'}" != 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}' -> SELECT count(username) FROM radcheck WHERE radcheck.username='10-2a-b3-68-94-3e'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'}" != 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'}" != 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1}")
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1 -> SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='phong@dd-wrt' and attribute='Rd-Mac-Check' and value=1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++update control {
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT value FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Device-Owner' -> SELECT value FROM radcheck WHERE radcheck.username='phong@dd-wrt' and attribute='Rd-Device-Owner'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: SQL query did not return any results
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT value FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Device-Owner'} ->
    Sat Jan 30 17:50:16 2016 : Info: ++++} # update control = noop
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{control:Rd-Tmp-Owner}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Tmp-Owner} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Tmp-Owner}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{control:Rd-Tmp-Owner}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++else else {
    Sat Jan 30 17:50:16 2016 : Info: +++++policy RADIUSdesk_user_check {
    Sat Jan 30 17:50:16 2016 : Info: [sql] expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: [sql] sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 2
    Sat Jan 30 17:50:16 2016 : 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 = 'phong@dd-wrt' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Info: [sql] User found in radcheck table
    Sat Jan 30 17:50:16 2016 : 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 = 'phong@dd-wrt' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'phong@dd-wrt' ORDER BY priority
    Sat Jan 30 17:50:16 2016 : Info: [sql] Checking profile 5M-every-hour
    Sat Jan 30 17:50:16 2016 : Info: [sql] sql_set_user escaped user --> '5M-every-hour'
    Sat Jan 30 17:50:16 2016 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '5M-every-hour' ORDER BY priority
    Sat Jan 30 17:50:16 2016 : 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 = '5M-every-hour' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Info: [sql] User found in group 5M-every-hour
    Sat Jan 30 17:50:16 2016 : 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 = '5M-every-hour' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 2
    Sat Jan 30 17:50:16 2016 : Info: ++++++[sql] = ok
    Sat Jan 30 17:50:16 2016 : Info: ++++++? if (ok)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (ok) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++? if (ok) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++if (ok) {
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Account-Disabled}")&&("%{control:Rd-Account-Disabled}" == 1))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Account-Disabled} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-Account-Disabled}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Rd-Account-Disabled}" == 1)
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Account-Disabled}")&&("%{control:Rd-Account-Disabled}" == 1)) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Account-Activation-Time}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Account-Activation-Time} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Account-Activation-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Account-Activation-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Realm}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Realm} -> Residence Inn
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++if ("%{control:Rd-Realm}") {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++update request {
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Realm} -> Residence Inn
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # update request = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # if ("%{control:Rd-Realm}") = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Auth-Type}")&&("%{control:Rd-Auth-Type}" != 'sql'))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Auth-Type} ->
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-Auth-Type}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Rd-Auth-Type}" != 'sql')
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Auth-Type}")&&("%{control:Rd-Auth-Type}" != 'sql')) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_data_counter {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard'))
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Total-Data) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Reset-Type-Data) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Cap-Type-Data == 'hard') -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard')) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard')) {
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair ChilliSpot-Version = 1.3.0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Password = \264\325P\237\267\311l
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Service-Type = Login-User
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Identifier = dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-ID = isocc=,cc=,ac=,network=Coova,
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Calling-Station-Id = 10-2a-b3-68-94-3e
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Framed-IP-Address = 192.168.7.13
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Name = phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Message-Authenticator = 0x0ef55c65470782f2c733926bfe04647a
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Type = Wireless-802.11
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Logoff-URL = http://192.168.7.1:3990/logoff
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Acct-Session-Id = 56ac954a00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-IP-Address = 192.168.7.1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Id = 00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-Name = My_HotSpot
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Called-Station-Id = C4-6E-1F-E9-94-CC
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Mac-Counter-Data = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Type-Data = dynamic
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Profile = 5M-every-hour
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Account-Disabled = 0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Cleartext-Password = phong
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Total-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Tmp-Owner =
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-User-Type = user
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Start-Time = 1454147416
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Interval-Data = 3600
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Cap-Type-Data = hard
    Sat Jan 30 17:50:16 2016 : Info: +++++++++[pl_reset_time_for_data] = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if (updated)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (updated) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if (updated) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++if (updated) {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Tmp-Avail-Data}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Tmp-Avail-Data} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Tmp-Avail-Data}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Tmp-Avail-Data}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++else else {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id))
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Mac-Counter-Data) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (request:Calling-Station-Id) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id)) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id)) {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++++update control {
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT IFNULL(SUM(acctinputoctets - GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)) + SUM(acctoutputoctets -GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)),0) FROM radacct WHERE username='%{request:User-Name}' AND callingstationid='%{request:Calling-Station-Id}' AND UNIX_TIMESTAMP(acctstarttime) + acctsessiontime > '%{control:Rd-Start-Time}' -> SELECT IFNULL(SUM(acctinputoctets - GREATEST((1454147416 - UNIX_TIMESTAMP(acctstarttime)), 0)) + SUM(acctoutputoctets -GREATEST((1454147416 - UNIX_TIMESTAMP(acctstarttime)), 0)),0) FROM radacct WHERE username='phong@dd-wrt' AND callingstationid='10-2a-b3-68-94-3e' AND UNIX_TIMESTAMP(acctstarttime) + acctsessiontime > '1454147416'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT IFNULL(SUM(acctinputoctets - GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)) + SUM(acctoutputoctets -GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)),0) FROM radacct WHERE username='%{request:User-Name}' AND callingstationid='%{request:Calling-Station-Id}' AND UNIX_TIMESTAMP(acctstarttime) + acctsessiontime > '%{control:Rd-Start-Time}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++++} # update control = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++} # if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id)) = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++} # else else = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++} # if (updated) = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Rd-Tmp-Avail-Data does not exist. Set it equal to 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair ChilliSpot-Version = 1.3.0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Password = \264\325P\237\267\311l
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Service-Type = Login-User
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Identifier = dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-ID = isocc=,cc=,ac=,network=Coova,
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Calling-Station-Id = 10-2a-b3-68-94-3e
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Framed-IP-Address = 192.168.7.13
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Name = phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Message-Authenticator = 0x0ef55c65470782f2c733926bfe04647a
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Type = Wireless-802.11
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Logoff-URL = http://192.168.7.1:3990/logoff
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Acct-Session-Id = 56ac954a00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-IP-Address = 192.168.7.1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair SQL-User-Name = phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Id = 00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-Name = My_HotSpot
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Called-Station-Id = C4-6E-1F-E9-94-CC
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair ChilliSpot-Max-Total-Octets = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Mikrotik-Total-Limit = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Mac-Counter-Data = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Profile = 5M-every-hour
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Type-Data = dynamic
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Used-Data = 0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Account-Disabled = 0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Tmp-Avail-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Cleartext-Password = phong
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-User-Type = user
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Total-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Tmp-Owner =
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Interval-Data = 3600
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Start-Time = 1454147416
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Cap-Type-Data = hard
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Avail-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Info: +++++++++[pl_check_usage_data] = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard')) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_data_counter = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_time_counter {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Time)&&(control:Rd-Reset-Type-Time)&&(control:Rd-Cap-Type-Time == 'hard'))
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Total-Time) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping (control:Rd-Reset-Type-Time)
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping (control:Rd-Cap-Type-Time == 'hard')
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Time)&&(control:Rd-Reset-Type-Time)&&(control:Rd-Cap-Type-Time == 'hard')) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_time_counter = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_voucher_check {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Voucher}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Voucher} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Voucher}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Voucher}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_voucher_check = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_realm_nas_check {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-Identifier}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{request:NAS-Identifier} -> dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{request:NAS-Identifier}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-Identifier}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++if ("%{request:NAS-Identifier}") {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' -> SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Realm}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Realm} -> Residence Inn
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++if ("%{control:Rd-Realm}") {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ("%{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'}" == 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}' -> SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='dd-wrt' AND realms.name='Residence Inn'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ("%{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++} # if ("%{control:Rd-Realm}") = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++++} # if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # if ("%{request:NAS-Identifier}") = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-IP-Address}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{request:NAS-IP-Address} -> 192.168.7.1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{request:NAS-IP-Address}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-IP-Address}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++if ("%{request:NAS-IP-Address}") {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}' -> SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='192.168.7.1'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # if ("%{request:NAS-IP-Address}") = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_realm_nas_check = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_user_ssid_check {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Ssid-Check}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Ssid-Check} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Ssid-Check}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Ssid-Check}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_user_ssid_check = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++} # if (ok) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++} # policy RADIUSdesk_user_check = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++} # else else = updated
    Sat Jan 30 17:50:16 2016 : Info: +++} # policy RADIUSdesk_main = updated
    Sat Jan 30 17:50:16 2016 : Info: ++} # if (!EAP-Message) = updated
    Sat Jan 30 17:50:16 2016 : Info: ++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Info: ++[files] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[expiration] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[logintime] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++policy RADIUSdesk_session_timeout {
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{reply:Session-Timeout}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{reply:Session-Timeout} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{reply:Session-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{reply:Session-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++else else {
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (("%{control:Rd-Avail-Time}")&&("%{control:Rd-Voucher-Timeout}"))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Avail-Time} ->
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-Avail-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Rd-Voucher-Timeout}")
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (("%{control:Rd-Avail-Time}")&&("%{control:Rd-Voucher-Timeout}")) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Avail-Time}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Avail-Time} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Avail-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Avail-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Voucher-Timeout}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Voucher-Timeout} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Voucher-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Voucher-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++} # else else = updated
    Sat Jan 30 17:50:16 2016 : Info: ++} # policy RADIUSdesk_session_timeout = updated
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='device')&&(!"%{control:Auth-Type}"))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-User-Type} -> user
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-User-Type}" =='device') -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Auth-Type}")
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='device')&&(!"%{control:Auth-Type}")) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='voucher-device')&&(!"%{control:Auth-Type}"))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-User-Type} -> user
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-User-Type}" =='voucher-device') -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Auth-Type}")
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='voucher-device')&&(!"%{control:Auth-Type}")) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++[pap] = updated
    Sat Jan 30 17:50:16 2016 : Info: +} # group authorize = updated
    Sat Jan 30 17:50:16 2016 : Info: Found Auth-Type = PAP
    Sat Jan 30 17:50:16 2016 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
    Sat Jan 30 17:50:16 2016 : Info: +group PAP {
    Sat Jan 30 17:50:16 2016 : Info: [pap] login attempt with password "´ÕP?·Él"
    Sat Jan 30 17:50:16 2016 : Info: [pap] Using clear text password "phong"
    Sat Jan 30 17:50:16 2016 : Info: [pap] Passwords don't match
    Sat Jan 30 17:50:16 2016 : Info: ++[pap] = reject
    Sat Jan 30 17:50:16 2016 : Info: +} # group PAP = reject
    Sat Jan 30 17:50:16 2016 : Info: Failed to authenticate the user.
    Sat Jan 30 17:50:16 2016 : Info: Using Post-Auth-Type Reject
    Sat Jan 30 17:50:16 2016 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
    Sat Jan 30 17:50:16 2016 : Info: +group REJECT {
    Sat Jan 30 17:50:16 2016 : Info: [attr_filter.access_reject] expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: attr_filter: Matched entry DEFAULT at line 11
    Sat Jan 30 17:50:16 2016 : Info: ++[attr_filter.access_reject] = updated
    Sat Jan 30 17:50:16 2016 : Info: ++? if (reply:Reply-Message =~ /You are already logged in/i)
    Sat Jan 30 17:50:16 2016 : Info: (Attribute reply:Reply-Message was not found)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (reply:Reply-Message =~ /You are already logged in/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++? if (reply:Reply-Message =~ /You are already logged in/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++policy RADIUSdesk_last_reject {
    Sat Jan 30 17:50:16 2016 : Info: +++? if (EAP-Message)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (EAP-Message) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if (EAP-Message) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(username) FROM permanent_users where username='%{User-Name}' -> SELECT count(username) FROM permanent_users where username='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 2
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 2
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) {
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: %{reply:Reply-Message} ->
    Sat Jan 30 17:50:16 2016 : Info: ... expanding second conditional
    Sat Jan 30 17:50:16 2016 : Info: expand: UPDATE permanent_users SET last_reject_time=now(),last_reject_nas='%{NAS-IP-Address}',last_reject_message='%{%{reply:Reply-Message}:-N/A}' where username='%{User-Name}' -> UPDATE permanent_users SET last_reject_time=now(),last_reject_nas='192.168.7.1',last_reject_message='N/A' where username='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:UPDATE permanent_users SET last_reject_time=now(),last_reject_nas='%{NAS-IP-Address}',last_reject_message='%{%{reply:Reply-Message}:-N/A}' where username='%{User-Name}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: +++} # if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(name) FROM devices where name='%{Calling-Station-Id}' -> SELECT count(name) FROM devices where name='10-2a-b3-68-94-3e'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(name) FROM vouchers where name='%{User-Name}' -> SELECT count(name) FROM vouchers where name='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++} # policy RADIUSdesk_last_reject = updated
    Sat Jan 30 17:50:16 2016 : Info: +} # group REJECT = updated
    Sat Jan 30 17:50:16 2016 : Info: Delaying reject of request 15 for 1 seconds
    Sat Jan 30 17:50:16 2016 : Debug: Going to the next request
    Sat Jan 30 17:50:16 2016 : Debug: Waking up in 0.9 seconds.
    Sat Jan 30 17:50:17 2016 : Info: Sending delayed reject for request 15
    Sending Access-Reject of id 75 to 192.168.0.11 port 59238
    Sat Jan 30 17:50:17 2016 : Debug: Waking up in 4.9 seconds.

     

  • Nguyen Nam

    Nguyen Nam - 2016-01-30

    Hmmmm, cant get it. Something wrong with click_to_connect permanent user. How can it be wrong? It's just an account created as permanent user (phong@dd-wrt) in this case, with dd-wrt as suffix. All was supplied, and it dont work???? Password dont match? SMH

    Nguyen

    rad_recv: Access-Request packet from host 192.168.0.11 port 59238, id=75, length=280
    ChilliSpot-Version = "1.3.0"
    User-Name = "phong@dd-wrt"
    User-Password = "\264\325P\237\267\311l"
    Service-Type = Login-User
    Acct-Session-Id = "56ac954a00000001"
    Framed-IP-Address = 192.168.7.13
    NAS-Port-Type = Wireless-802.11
    NAS-Port = 1
    NAS-Port-Id = "00000001"
    Calling-Station-Id = "10-2A-B3-68-94-3E"
    Called-Station-Id = "C4-6E-1F-E9-94-CC"
    NAS-IP-Address = 192.168.7.1
    NAS-Identifier = "dd-wrt"
    WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova,"
    WISPr-Location-Name = "My_HotSpot"
    WISPr-Logoff-URL = "http://192.168.7.1:3990/logoff"
    Message-Authenticator = 0x0ef55c65470782f2c733926bfe04647a
    Sat Jan 30 17:50:16 2016 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
    Sat Jan 30 17:50:16 2016 : Info: +group authorize {
    Sat Jan 30 17:50:16 2016 : Info: ++[preprocess] = ok
    Sat Jan 30 17:50:16 2016 : Info: ++policy rewrite.calling_station_id {
    Sat Jan 30 17:50:16 2016 : Info: +++? if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i)
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (Calling-Station-Id) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: expand: %{Calling-Station-Id} -> 10-2A-B3-68-94-3E
    Sat Jan 30 17:50:16 2016 : Info: expand: policy.mac-addr -> policy.mac-addr
    Sat Jan 30 17:50:16 2016 : Info: expand: ^%{config:policy.mac-addr}$ -> ^([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})[^0-9a-f]?([0-9a-f]{2})$
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) {
    Sat Jan 30 17:50:16 2016 : Info: ++++update request {
    Sat Jan 30 17:50:16 2016 : Info: expand: %{1}-%{2}-%{3}-%{4}-%{5}-%{6} -> 10-2A-B3-68-94-3E
    Sat Jan 30 17:50:16 2016 : Info: expand: %{tolower:%{1}-%{2}-%{3}-%{4}-%{5}-%{6}} -> 10-2a-b3-68-94-3e
    Sat Jan 30 17:50:16 2016 : Info: ++++} # update request = noop
    Sat Jan 30 17:50:16 2016 : Info: ++++[updated] = updated
    Sat Jan 30 17:50:16 2016 : Info: +++} # if ((Calling-Station-Id) && "%{Calling-Station-Id}" =~ /^%{config:policy.mac-addr}$/i) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Info: ++} # policy rewrite.calling_station_id = updated
    Sat Jan 30 17:50:16 2016 : Info: ++[chap] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[mschap] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[digest] = noop
    Sat Jan 30 17:50:16 2016 : Info: [suffix] Looking up realm "dd-wrt" for User-Name = "phong@dd-wrt"
    Sat Jan 30 17:50:16 2016 : Info: [suffix] No such realm "dd-wrt"
    Sat Jan 30 17:50:16 2016 : Info: ++[suffix] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++? if (!EAP-Message)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating !(EAP-Message) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++? if (!EAP-Message) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++if (!EAP-Message) {
    Sat Jan 30 17:50:16 2016 : Info: +++policy RADIUSdesk_main {
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (request:User-Name =~ /^([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})$/i)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (request:User-Name =~ /^([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})$/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (request:User-Name =~ /^([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})[-:]+([0-9a-f]{2})$/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'}" == 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' -> SELECT count(username) FROM radcheck WHERE radcheck.username='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'} -> 6
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:User-Name}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'}" != 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}' -> SELECT count(username) FROM radcheck WHERE radcheck.username='10-2a-b3-68-94-3e'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'}" != 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{sql:SELECT count(username) FROM radcheck WHERE radcheck.username='%{request:Calling-Station-Id}'}" != 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1}")
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1 -> SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='phong@dd-wrt' and attribute='Rd-Mac-Check' and value=1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{sql:SELECT count(radcheck.username) FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Mac-Check' and value=1}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++update control {
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT value FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Device-Owner' -> SELECT value FROM radcheck WHERE radcheck.username='phong@dd-wrt' and attribute='Rd-Device-Owner'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: SQL query did not return any results
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT value FROM radcheck WHERE radcheck.username='%{request:User-Name}' and attribute='Rd-Device-Owner'} ->
    Sat Jan 30 17:50:16 2016 : Info: ++++} # update control = noop
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{control:Rd-Tmp-Owner}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Tmp-Owner} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Tmp-Owner}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? if ("%{control:Rd-Tmp-Owner}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++else else {
    Sat Jan 30 17:50:16 2016 : Info: +++++policy RADIUSdesk_user_check {
    Sat Jan 30 17:50:16 2016 : Info: [sql] expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: [sql] sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 2
    Sat Jan 30 17:50:16 2016 : 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 = 'phong@dd-wrt' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Info: [sql] User found in radcheck table
    Sat Jan 30 17:50:16 2016 : 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 = 'phong@dd-wrt' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'phong@dd-wrt' ORDER BY priority
    Sat Jan 30 17:50:16 2016 : Info: [sql] Checking profile 5M-every-hour
    Sat Jan 30 17:50:16 2016 : Info: [sql] sql_set_user escaped user --> '5M-every-hour'
    Sat Jan 30 17:50:16 2016 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = '5M-every-hour' ORDER BY priority
    Sat Jan 30 17:50:16 2016 : 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 = '5M-every-hour' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Info: [sql] User found in group 5M-every-hour
    Sat Jan 30 17:50:16 2016 : 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 = '5M-every-hour' ORDER BY id
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 2
    Sat Jan 30 17:50:16 2016 : Info: ++++++[sql] = ok
    Sat Jan 30 17:50:16 2016 : Info: ++++++? if (ok)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (ok) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++? if (ok) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++if (ok) {
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Account-Disabled}")&&("%{control:Rd-Account-Disabled}" == 1))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Account-Disabled} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-Account-Disabled}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Rd-Account-Disabled}" == 1)
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Account-Disabled}")&&("%{control:Rd-Account-Disabled}" == 1)) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Account-Activation-Time}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Account-Activation-Time} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Account-Activation-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Account-Activation-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Realm}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Realm} -> Residence Inn
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++if ("%{control:Rd-Realm}") {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++update request {
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Realm} -> Residence Inn
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # update request = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # if ("%{control:Rd-Realm}") = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Auth-Type}")&&("%{control:Rd-Auth-Type}" != 'sql'))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Auth-Type} ->
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-Auth-Type}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Rd-Auth-Type}" != 'sql')
    Sat Jan 30 17:50:16 2016 : Info: +++++++? if (("%{control:Rd-Auth-Type}")&&("%{control:Rd-Auth-Type}" != 'sql')) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_data_counter {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard'))
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Total-Data) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Reset-Type-Data) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Cap-Type-Data == 'hard') -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard')) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard')) {
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair ChilliSpot-Version = 1.3.0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Password = \264\325P\237\267\311l
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Service-Type = Login-User
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Identifier = dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-ID = isocc=,cc=,ac=,network=Coova,
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Calling-Station-Id = 10-2a-b3-68-94-3e
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Framed-IP-Address = 192.168.7.13
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Name = phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Message-Authenticator = 0x0ef55c65470782f2c733926bfe04647a
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Type = Wireless-802.11
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Logoff-URL = http://192.168.7.1:3990/logoff
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Acct-Session-Id = 56ac954a00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-IP-Address = 192.168.7.1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Id = 00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-Name = My_HotSpot
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Called-Station-Id = C4-6E-1F-E9-94-CC
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Mac-Counter-Data = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Type-Data = dynamic
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Profile = 5M-every-hour
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Account-Disabled = 0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Cleartext-Password = phong
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Total-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Tmp-Owner =
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-User-Type = user
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Start-Time = 1454147416
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Interval-Data = 3600
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Cap-Type-Data = hard
    Sat Jan 30 17:50:16 2016 : Info: +++++++++[pl_reset_time_for_data] = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if (updated)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (updated) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if (updated) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++if (updated) {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Tmp-Avail-Data}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Tmp-Avail-Data} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Tmp-Avail-Data}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Tmp-Avail-Data}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++else else {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id))
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Mac-Counter-Data) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (request:Calling-Station-Id) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id)) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id)) {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++++update control {
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT IFNULL(SUM(acctinputoctets - GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)) + SUM(acctoutputoctets -GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)),0) FROM radacct WHERE username='%{request:User-Name}' AND callingstationid='%{request:Calling-Station-Id}' AND UNIX_TIMESTAMP(acctstarttime) + acctsessiontime > '%{control:Rd-Start-Time}' -> SELECT IFNULL(SUM(acctinputoctets - GREATEST((1454147416 - UNIX_TIMESTAMP(acctstarttime)), 0)) + SUM(acctoutputoctets -GREATEST((1454147416 - UNIX_TIMESTAMP(acctstarttime)), 0)),0) FROM radacct WHERE username='phong@dd-wrt' AND callingstationid='10-2a-b3-68-94-3e' AND UNIX_TIMESTAMP(acctstarttime) + acctsessiontime > '1454147416'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT IFNULL(SUM(acctinputoctets - GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)) + SUM(acctoutputoctets -GREATEST((%{control:Rd-Start-Time} - UNIX_TIMESTAMP(acctstarttime)), 0)),0) FROM radacct WHERE username='%{request:User-Name}' AND callingstationid='%{request:Calling-Station-Id}' AND UNIX_TIMESTAMP(acctstarttime) + acctsessiontime > '%{control:Rd-Start-Time}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++++} # update control = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++} # if ((control:Rd-Mac-Counter-Data)&&(request:Calling-Station-Id)) = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++} # else else = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++} # if (updated) = noop
    Sat Jan 30 17:50:16 2016 : Info: +++++++++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Rd-Tmp-Avail-Data does not exist. Set it equal to 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair ChilliSpot-Version = 1.3.0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Password = \264\325P\237\267\311l
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Service-Type = Login-User
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Identifier = dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-ID = isocc=,cc=,ac=,network=Coova,
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Calling-Station-Id = 10-2a-b3-68-94-3e
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Framed-IP-Address = 192.168.7.13
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Name = phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Message-Authenticator = 0x0ef55c65470782f2c733926bfe04647a
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Type = Wireless-802.11
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Logoff-URL = http://192.168.7.1:3990/logoff
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Acct-Session-Id = 56ac954a00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-IP-Address = 192.168.7.1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair SQL-User-Name = phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair NAS-Port-Id = 00000001
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair WISPr-Location-Name = My_HotSpot
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Called-Station-Id = C4-6E-1F-E9-94-CC
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair ChilliSpot-Max-Total-Octets = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Mikrotik-Total-Limit = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Mac-Counter-Data = 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair User-Profile = 5M-every-hour
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Type-Data = dynamic
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Realm = Residence Inn
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Used-Data = 0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Account-Disabled = 0
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Tmp-Avail-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Cleartext-Password = phong
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-User-Type = user
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Total-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Tmp-Owner =
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Reset-Interval-Data = 3600
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Start-Time = 1454147416
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Cap-Type-Data = hard
    Sat Jan 30 17:50:16 2016 : Debug: rlm_perl: Added pair Rd-Avail-Data = 5000000
    Sat Jan 30 17:50:16 2016 : Info: +++++++++[pl_check_usage_data] = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # if ((control:Rd-Total-Data)&&(control:Rd-Reset-Type-Data)&&(control:Rd-Cap-Type-Data == 'hard')) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_data_counter = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_time_counter {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Time)&&(control:Rd-Reset-Type-Time)&&(control:Rd-Cap-Type-Time == 'hard'))
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating (control:Rd-Total-Time) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping (control:Rd-Reset-Type-Time)
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping (control:Rd-Cap-Type-Time == 'hard')
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ((control:Rd-Total-Time)&&(control:Rd-Reset-Type-Time)&&(control:Rd-Cap-Type-Time == 'hard')) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_time_counter = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_voucher_check {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Voucher}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Voucher} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Voucher}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Voucher}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_voucher_check = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_realm_nas_check {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-Identifier}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{request:NAS-Identifier} -> dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{request:NAS-Identifier}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-Identifier}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++if ("%{request:NAS-Identifier}") {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' -> SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Realm}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Realm} -> Residence Inn
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++? if ("%{control:Rd-Realm}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++if ("%{control:Rd-Realm}") {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ("%{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'}" == 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}' -> SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='dd-wrt' AND realms.name='Residence Inn'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++++? if ("%{sql:SELECT COUNT(nas.nasname) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id LEFT JOIN realms ON realms.id=na_realms.realm_id WHERE nas.nasidentifier='%{request:NAS-Identifier}' AND realms.name='%{control:Rd-Realm}'}" == 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++++} # if ("%{control:Rd-Realm}") = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++++} # if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasidentifier='%{request:NAS-Identifier}'}" > 0) = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # if ("%{request:NAS-Identifier}") = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-IP-Address}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{request:NAS-IP-Address} -> 192.168.7.1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{request:NAS-IP-Address}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{request:NAS-IP-Address}") -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++if ("%{request:NAS-IP-Address}") {
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}' -> SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='192.168.7.1'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 3
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++++? if ("%{sql:SELECT COUNT(na_realms.id) AS count FROM nas LEFT JOIN na_realms ON nas.id=na_realms.na_id WHERE nas.nasname='%{request:NAS-IP-Address}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++} # if ("%{request:NAS-IP-Address}") = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_realm_nas_check = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++++policy RADIUSdesk_user_ssid_check {
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Ssid-Check}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Ssid-Check} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Ssid-Check}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++++++? if ("%{control:Rd-Ssid-Check}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++++++} # policy RADIUSdesk_user_ssid_check = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++++} # if (ok) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++++} # policy RADIUSdesk_user_check = updated
    Sat Jan 30 17:50:16 2016 : Info: ++++} # else else = updated
    Sat Jan 30 17:50:16 2016 : Info: +++} # policy RADIUSdesk_main = updated
    Sat Jan 30 17:50:16 2016 : Info: ++} # if (!EAP-Message) = updated
    Sat Jan 30 17:50:16 2016 : Info: ++ ... skipping else for request 15: Preceding "if" was taken
    Sat Jan 30 17:50:16 2016 : Info: ++[files] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[expiration] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++[logintime] = noop
    Sat Jan 30 17:50:16 2016 : Info: ++policy RADIUSdesk_session_timeout {
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{reply:Session-Timeout}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{reply:Session-Timeout} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{reply:Session-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{reply:Session-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++else else {
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (("%{control:Rd-Avail-Time}")&&("%{control:Rd-Voucher-Timeout}"))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Avail-Time} ->
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-Avail-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Rd-Voucher-Timeout}")
    Sat Jan 30 17:50:16 2016 : Info: ++++? if (("%{control:Rd-Avail-Time}")&&("%{control:Rd-Voucher-Timeout}")) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Avail-Time}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Avail-Time} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Avail-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Avail-Time}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Voucher-Timeout}")
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-Voucher-Timeout} ->
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{control:Rd-Voucher-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++++? elsif ("%{control:Rd-Voucher-Timeout}") -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++} # else else = updated
    Sat Jan 30 17:50:16 2016 : Info: ++} # policy RADIUSdesk_session_timeout = updated
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='device')&&(!"%{control:Auth-Type}"))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-User-Type} -> user
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-User-Type}" =='device') -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Auth-Type}")
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='device')&&(!"%{control:Auth-Type}")) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='voucher-device')&&(!"%{control:Auth-Type}"))
    Sat Jan 30 17:50:16 2016 : Info: expand: %{control:Rd-User-Type} -> user
    Sat Jan 30 17:50:16 2016 : Info: ?? Evaluating ("%{control:Rd-User-Type}" =='voucher-device') -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ?? Skipping ("%{control:Auth-Type}")
    Sat Jan 30 17:50:16 2016 : Info: ++? if (("%{control:Rd-User-Type}" =='voucher-device')&&(!"%{control:Auth-Type}")) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++[pap] = updated
    Sat Jan 30 17:50:16 2016 : Info: +} # group authorize = updated
    Sat Jan 30 17:50:16 2016 : Info: Found Auth-Type = PAP
    Sat Jan 30 17:50:16 2016 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
    Sat Jan 30 17:50:16 2016 : Info: +group PAP {
    Sat Jan 30 17:50:16 2016 : Info: [pap] login attempt with password "´ÕP?·Él"
    Sat Jan 30 17:50:16 2016 : Info: [pap] Using clear text password "phong"
    Sat Jan 30 17:50:16 2016 : Info: [pap] Passwords don't match
    Sat Jan 30 17:50:16 2016 : Info: ++[pap] = reject
    Sat Jan 30 17:50:16 2016 : Info: +} # group PAP = reject
    Sat Jan 30 17:50:16 2016 : Info: Failed to authenticate the user.
    Sat Jan 30 17:50:16 2016 : Info: Using Post-Auth-Type Reject
    Sat Jan 30 17:50:16 2016 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
    Sat Jan 30 17:50:16 2016 : Info: +group REJECT {
    Sat Jan 30 17:50:16 2016 : Info: [attr_filter.access_reject] expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Debug: attr_filter: Matched entry DEFAULT at line 11
    Sat Jan 30 17:50:16 2016 : Info: ++[attr_filter.access_reject] = updated
    Sat Jan 30 17:50:16 2016 : Info: ++? if (reply:Reply-Message =~ /You are already logged in/i)
    Sat Jan 30 17:50:16 2016 : Info: (Attribute reply:Reply-Message was not found)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (reply:Reply-Message =~ /You are already logged in/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++? if (reply:Reply-Message =~ /You are already logged in/i) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++policy RADIUSdesk_last_reject {
    Sat Jan 30 17:50:16 2016 : Info: +++? if (EAP-Message)
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating (EAP-Message) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if (EAP-Message) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(username) FROM permanent_users where username='%{User-Name}' -> SELECT count(username) FROM permanent_users where username='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 2
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 2
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) -> TRUE
    Sat Jan 30 17:50:16 2016 : Info: +++if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) {
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: %{reply:Reply-Message} ->
    Sat Jan 30 17:50:16 2016 : Info: ... expanding second conditional
    Sat Jan 30 17:50:16 2016 : Info: expand: UPDATE permanent_users SET last_reject_time=now(),last_reject_nas='%{NAS-IP-Address}',last_reject_message='%{%{reply:Reply-Message}:-N/A}' where username='%{User-Name}' -> UPDATE permanent_users SET last_reject_time=now(),last_reject_nas='192.168.7.1',last_reject_message='N/A' where username='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 1
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:UPDATE permanent_users SET last_reject_time=now(),last_reject_nas='%{NAS-IP-Address}',last_reject_message='%{%{reply:Reply-Message}:-N/A}' where username='%{User-Name}'} -> 1
    Sat Jan 30 17:50:16 2016 : Info: +++} # if ("%{sql:SELECT count(username) FROM permanent_users where username='%{User-Name}'}" > 0) = updated
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(name) FROM devices where name='%{Calling-Station-Id}' -> SELECT count(name) FROM devices where name='10-2a-b3-68-94-3e'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 0
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM devices where name='%{Calling-Station-Id}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'}" > 0)
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat
    Sat Jan 30 17:50:16 2016 : Info: expand: %{User-Name} -> phong@dd-wrt
    Sat Jan 30 17:50:16 2016 : Info: sql_set_user escaped user --> 'phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Info: expand: SELECT count(name) FROM vouchers where name='%{User-Name}' -> SELECT count(name) FROM vouchers where name='phong@dd-wrt'
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Reserving sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: sql_xlat finished
    Sat Jan 30 17:50:16 2016 : Debug: rlm_sql (sql): Released sql socket id: 4
    Sat Jan 30 17:50:16 2016 : Info: expand: %{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'} -> 0
    Sat Jan 30 17:50:16 2016 : Info: ? Evaluating ("%{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: +++? if ("%{sql:SELECT count(name) FROM vouchers where name='%{User-Name}'}" > 0) -> FALSE
    Sat Jan 30 17:50:16 2016 : Info: ++} # policy RADIUSdesk_last_reject = updated
    Sat Jan 30 17:50:16 2016 : Info: +} # group REJECT = updated
    Sat Jan 30 17:50:16 2016 : Info: Delaying reject of request 15 for 1 seconds
    Sat Jan 30 17:50:16 2016 : Debug: Going to the next request
    Sat Jan 30 17:50:16 2016 : Debug: Waking up in 0.9 seconds.
    Sat Jan 30 17:50:17 2016 : Info: Sending delayed reject for request 15
    Sending Access-Reject of id 75 to 192.168.0.11 port 59238
    Sat Jan 30 17:50:17 2016 : Debug: Waking up in 4.9 seconds.

     

  • Nahom

    Nahom - 2016-01-30

    Is the password phong?
    It needs to be the same as the first part of the username (i.e the one before the @ sign)

     

    • Nguyen Nam

      Nguyen Nam - 2016-02-01

      Well thanks. It was a mismatch of HS_UAMSECRET. Going a long way to debug, but glad to get it working :)

       

  • Bariamis Panagiotis

    Bariamis Panagiotis - 2016-05-22

    Hello can you please give advise how you made it working ?
    I have come to the same problem .
    Have changed HS_UAMSECRET , however there is no UAMSCRET page in cloudtrax and openmesh formware 6xx . Where can i put htis field ?

     

  • Panos Goumas

    Panos Goumas - 2018-02-17

    Hi there. I have the same problem The hotspot is not responding to status quiries.I am working on Mikrotik.Anybody knows for this problem?!!

     

    • sameer naik

      sameer naik - 2019-07-16

      Hello panos .have you found solution for the problem ,beacause i am also facing the same issue ,
      please help me out

       

      Last edit: sameer naik 2019-07-16

  • Kuldeep Rana

    Kuldeep Rana - 2019-08-21

    Hello sammer and Ponos, have you found the solution for this issue. i am also facing same problem when i am login

     

  • Yevi

    Yevi - 2019-10-04

    Hello,
    It seems to be a cross-origin resource sharing (CORS) problem.
    Adding $(if http-header == "Access-Control-Allow-Origin")http://yourdomain.com$(endif) to the login.html may help.

     

    • RazaMetaL

      RazaMetaL - 2021-10-08

      Right now it is not enough the user of Access-Control_Allow-Origin. If you open the login page with Firefox, you can login, but not if you use Chrome.

      To make possible the login working with Mikrotik and RadiusDesk, the communication must be using https. You can use a self signed cert on nginx and mikrotik.

      Steps to use mikrotik hotspot with https: https://wiki.mikrotik.com/wiki/Manual:Hotspot_HTTPS_example

      There is necesary to modify variables $(link-status) and $(link-logout) needed by RadiusDesk on the mikrotik login html page, modify the login.html and replace it like as follows:

              <input type="hidden" name="link_status" value="https://$(hostname)/$(target-dir)status">
        <input type="hidden" name="link_logout" value="https://$(hostname)/$(target-dir)logout">

      Hope this helps to someone with the same problem.

       

  • Stanley Thomas

    Stanley Thomas - 2021-10-14

    This problem is noticed in 2017 VM and Chrome, Edge browsers. What needs to be done for coovachilli NAS?

     

    • Dirk van der Walt

      Dirk van der Walt - 2021-10-14

      Hi guys,

      Yes since the Zero day fixes for Chrome came out a week or so ago things broke on most Android devices.

      Fortunately not all is lost and there is a way to get it working again.

      • If your login page is served from a public IP it now HAS TO be served over HTTPS.
      • If it is not served over HTTPS and there is a callback to the Coova Controller which is running on a private network, Chrome will block the request. (CORS rules which they now made more strict)
      • Once you serve the login page over HTTPS another rule applies. You can not do a less secure AJAX (http) call to the private network.
      • To fix this you have to compile and configure Coova Chilli to serve the JSON over HTTPS.
      • To do this you either have to create a self signed certificate (which probably will cause problems with the CA certificate not on the user's device)
      • Alternatively you can use a proper certificate signed by a valid CA.
      • The FQDN for that certificate then has to resolve to the UAM IP of CoovaChilli for the checks that the client does pass. (DNS does allow you to do A records for Private Network Addresses)

      Hope this will be helpful.

      Regards

       

  • Stanley Thomas

    Stanley Thomas - 2021-10-14

    Hi Dirk,

    What happens in case the NAS is connecting to the server over VPN?

     

    • Dirk van der Walt

      Dirk van der Walt - 2021-10-14

      Hi Stanley,

      I am not sure what Chrome will do when the login page is also served on a private network.
      (So the callback will be on initiated from a private network to a private network)
      That was my next tests that I wanted to do and check, however this problem set me back a whole lot of days on my schedule.

       

      • Dirk van der Walt

        Dirk van der Walt - 2021-10-14

        To answer my own question on serving the login page on a private network.
        It seems Chrome is OK with that.

        I served the page from my local development machine while connected to the captive Portal over HTTP and then the callbacks were to Coova on that same network and it worked fine on Chrome

         

  • Stanley Thomas

    Stanley Thomas - 2021-10-14

    Yes a couple of weeks here Dirk. It's been driving me nuts.

    I just checked. It works on private network.

     
    👍
    1

    • Dirk van der Walt

      Dirk van der Walt - 2021-10-14

      I was reading an interesting article last week about how we've now gone the full circle with Google. (Like its been with Microsoft in the old days)

      Google now suggest developers test pro-actively to discover things that Google might break with their changes and the writer of the article was like so why do we have standards and standards bodies

      I'm sure these changes they made did not just affected the Captive Portals but also may other setups and applications

       

  • Stanley Thomas

    Stanley Thomas - 2021-10-14

    Although the radius works fine I can't seem to load the login page over VPN. Looks like a routing issue. The connected device does not have routing rules to that network. How can I push the route to 10.X network traffic via chilli to the device? Can the /etc/chilli/up.sh file be used?

     

    Last edit: Stanley Thomas 2021-10-15
    Thumbnail
    RD login NA.jpeg
1 2 > >> (Page 1 of 2)

Log in to post a comment.

Want the latest updates on software, tech news, and AI?
Get latest updates about software, tech news, and AI from SourceForge directly in your inbox once a month.