1. So, in fact I optimized my counter.conf files following the wiki page related to Rlm_sqlcounter module (http://wiki.freeradius.org/Rlm_sqlcounter) 2. I also followed the radius debug trace, but being relatively new to FR, I neglect to put it in my post. I beg your pardon! Following your thoughts, bellow is the debug output for FR running `radiusd -XXX`: rad_recv: Access-Request packet from host 127.0.0.1 port 54430, id=87, length=269 ChilliSpot-Version = "1.2.9" User-Name = "test1" User-Password = "test1" Service-Type = Login-User Acct-Session-Id = "4fed56ba00000001" Framed-IP-Address = 10.3.1.10 NAS-Port-Type = Wireless-802.11 NAS-Port = 1 NAS-Port-Id = "00000001" Calling-Station-Id = "00-25-22-83-95-C5" Called-Station-Id = "F8-D1-11-05-93-01" NAS-IP-Address = 10.3.1.1 NAS-Identifier = "nas-2" WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova," WISPr-Location-Name = "My_HotSpot" WISPr-Logoff-URL = "http://10.3.1.1:3001/logoff" Message-Authenticator = 0x5ba554bf22d10f59fec9c79a1524e690 Fri Jun 29 10:20:06 2012 : Info: # Executing section authorize from file /netnfork/radius//etc/raddb/sites-enabled/default Fri Jun 29 10:20:06 2012 : Info: +- entering group authorize {...} Fri Jun 29 10:20:06 2012 : Info: ++[preprocess] returns ok Fri Jun 29 10:20:06 2012 : Info: ++[chap] returns noop Fri Jun 29 10:20:06 2012 : Info: [suffix] No '@' in User-Name = "test1", looking up realm NULL Fri Jun 29 10:20:06 2012 : Info: [suffix] No such realm "NULL" Fri Jun 29 10:20:06 2012 : Info: ++[suffix] returns noop Fri Jun 29 10:20:06 2012 : Info: [eap] No EAP-Message, not doing EAP Fri Jun 29 10:20:06 2012 : Info: ++[eap] returns noop Fri Jun 29 10:20:06 2012 : Info: [sql] expand: %{User-Name} -> test1 Fri Jun 29 10:20:06 2012 : Info: [sql] sql_set_user escaped user --> 'test1' Fri Jun 29 10:20:06 2012 : Debug: rlm_sql (sql): Reserving sql socket id: 2 Fri Jun 29 10:20:06 2012 : 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 = 'test1' ORDER BY id Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: Status: PGRES_TUPLES_OK Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: query affected rows = 2 , fields = 5 Fri Jun 29 10:20:06 2012 : Info: [sql] User found in radcheck table Fri Jun 29 10:20:06 2012 : 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 = 'test1' ORDER BY id Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: Status: PGRES_TUPLES_OK Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: query affected rows = 0 , fields = 5 Fri Jun 29 10:20:06 2012 : Info: [sql] expand: SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}' ORDER BY priority -> SELECT GroupName FROM radusergroup WHERE UserName='test1' ORDER BY priority Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: Status: PGRES_TUPLES_OK Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: query affected rows = 0 , fields = 1 Fri Jun 29 10:20:06 2012 : Debug: rlm_sql (sql): Released sql socket id: 2 Fri Jun 29 10:20:06 2012 : Info: ++[sql] returns ok Fri Jun 29 10:20:06 2012 : Debug: rlm_sqlcounter: Entering module authorize code Fri Jun 29 10:20:06 2012 : Debug: sqlcounter_expand: 'SELECT SUM(AcctSessionTime - GREATER((1340953200 - AcctStartTime::ABSTIME::INT4), 0)) FROM radacct WHERE UserName='%{User-Name}' AND AcctStartTime::ABSTIME::INT4 + AcctSessionTime > '1340953200'' Fri Jun 29 10:20:06 2012 : Info: [hourlycounter] expand: SELECT SUM(AcctSessionTime - GREATER((1340953200 - AcctStartTime::ABSTIME::INT4), 0)) FROM radacct WHERE UserName='%{User-Name}' AND AcctStartTime::ABSTIME::INT4 + AcctSessionTime > '1340953200' -> SELECT SUM(AcctSessionTime - GREATER((1340953200 - AcctStartTime::ABSTIME::INT4), 0)) FROM radacct WHERE UserName='test1' AND AcctStartTime::ABSTIME::INT4 + AcctSessionTime > '1340953200' Fri Jun 29 10:20:06 2012 : Debug: WARNING: Please replace '%S' with '${sqlmod-inst}' Fri Jun 29 10:20:06 2012 : Debug: sqlcounter_expand: '%{sql:SELECT SUM(AcctSessionTime - GREATER((1340953200 - AcctStartTime::ABSTIME::INT4), 0)) FROM radacct WHERE UserName='test1' AND AcctStartTime::ABSTIME::INT4 + AcctSessionTime > '1340953200'}' Fri Jun 29 10:20:06 2012 : Info: [hourlycounter] sql_xlat Fri Jun 29 10:20:06 2012 : Info: [hourlycounter] expand: %{User-Name} -> test1 Fri Jun 29 10:20:06 2012 : Info: [hourlycounter] sql_set_user escaped user --> 'test1' Fri Jun 29 10:20:06 2012 : Info: [hourlycounter] expand: SELECT SUM(AcctSessionTime - GREATER((1340953200 - AcctStartTime::ABSTIME::INT4), 0)) FROM radacct WHERE UserName='test1' AND AcctStartTime::ABSTIME::INT4 + AcctSessionTime > '1340953200' -> SELECT SUM(AcctSessionTime - GREATER((1340953200 - AcctStartTime::ABSTIME::INT4), 0)) FROM radacct WHERE UserName='test1' AND AcctStartTime::ABSTIME::INT4 + AcctSessionTime > '1340953200' Fri Jun 29 10:20:06 2012 : Debug: rlm_sql (sql): Reserving sql socket id: 1 Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: Status: PGRES_TUPLES_OK Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: query affected rows = 1 , fields = 1 Fri Jun 29 10:20:06 2012 : Info: [hourlycounter] sql_xlat finished Fri Jun 29 10:20:06 2012 : Debug: rlm_sql (sql): Released sql socket id: 1 Fri Jun 29 10:20:06 2012 : Info: [hourlycounter] expand: %{sql:SELECT SUM(AcctSessionTime - GREATER((1340953200 - AcctStartTime::ABSTIME::INT4), 0)) FROM radacct WHERE UserName='test1' AND AcctStartTime::ABSTIME::INT4 + AcctSessionTime > '1340953200'} -> //***1 Look here!!! Fri Jun 29 10:20:06 2012 : Debug: rlm_sqlcounter: No integer found in string "" Fri Jun 29 10:20:06 2012 : Info: ++[hourlycounter] returns noop //***1 Fri Jun 29 10:20:06 2012 : Info: ++[pap] returns updated Fri Jun 29 10:20:06 2012 : Info: Found Auth-Type = PAP Fri Jun 29 10:20:06 2012 : Info: # Executing group from file /netnfork/radius//etc/raddb/sites-enabled/default Fri Jun 29 10:20:06 2012 : Info: +- entering group PAP {...} Fri Jun 29 10:20:06 2012 : Info: [pap] login attempt with password "test1" Fri Jun 29 10:20:06 2012 : Info: [pap] Using clear text password "test1" Fri Jun 29 10:20:06 2012 : Info: [pap] User authenticated successfully Fri Jun 29 10:20:06 2012 : Info: ++[pap] returns ok Fri Jun 29 10:20:06 2012 : Info: # Executing section post-auth from file /netnfork/radius//etc/raddb/sites-enabled/default Fri Jun 29 10:20:06 2012 : Info: +- entering group post-auth {...} Fri Jun 29 10:20:06 2012 : Info: ++[exec] returns noop //***2 Look here Sending Access-Accept of id 87 to 127.0.0.1 port 54430 //***2 Fri Jun 29 10:20:06 2012 : Info: Finished request 1. Fri Jun 29 10:20:06 2012 : Debug: Going to the next request Fri Jun 29 10:20:06 2012 : Debug: Waking up in 4.9 seconds. rad_recv: Accounting-Request packet from host 127.0.0.1 port 56325, id=47, length=216 ChilliSpot-Version = "1.2.9" ChilliSpot-Attr-10 = 0x00000002 Event-Timestamp = "Jun 29 2012 10:20:06 EEST" User-Name = "test1" Acct-Status-Type = Start Acct-Session-Id = "4fed56ba00000001" Framed-IP-Address = 10.3.1.10 NAS-Port-Type = Wireless-802.11 NAS-Port = 1 NAS-Port-Id = "00000001" Calling-Station-Id = "00-25-22-83-95-C5" Called-Station-Id = "F8-D1-11-05-93-01" NAS-IP-Address = 10.3.1.1 NAS-Identifier = "nas-2" WISPr-Location-ID = "isocc=,cc=,ac=,network=Coova," WISPr-Location-Name = "My_HotSpot" Fri Jun 29 10:20:06 2012 : Info: # Executing section preacct from file /netnfork/radius//etc/raddb/sites-enabled/default Fri Jun 29 10:20:06 2012 : Info: +- entering group preacct {...} Fri Jun 29 10:20:06 2012 : Info: ++[preprocess] returns ok Fri Jun 29 10:20:06 2012 : Info: [acct_unique] Hashing 'NAS-Port = 1,Client-IP-Address = 127.0.0.1,NAS-IP-Address = 10.3.1.1,Acct-Session-Id = "4fed56ba00000001",User-Name = "test1"' Fri Jun 29 10:20:06 2012 : Info: [acct_unique] Acct-Unique-Session-ID = "c2ef1ad94ab8e1c1". Fri Jun 29 10:20:06 2012 : Info: ++[acct_unique] returns ok Fri Jun 29 10:20:06 2012 : Info: [suffix] No '@' in User-Name = "test1", looking up realm NULL Fri Jun 29 10:20:06 2012 : Info: [suffix] No such realm "NULL" Fri Jun 29 10:20:06 2012 : Info: ++[suffix] returns noop Fri Jun 29 10:20:06 2012 : Info: ++[files] returns noop Fri Jun 29 10:20:06 2012 : Info: # Executing section accounting from file /netnfork/radius//etc/raddb/sites-enabled/default Fri Jun 29 10:20:06 2012 : Info: +- entering group accounting {...} Fri Jun 29 10:20:06 2012 : Info: [detail] expand: %{Packet-Src-IP-Address} -> 127.0.0.1 Fri Jun 29 10:20:06 2012 : Info: [detail] expand: /netnfork/radius//var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /netnfork/radius//var/log/radius/radacct/127.0.0.1/detail-20120629 Fri Jun 29 10:20:06 2012 : Info: [detail] /netnfork/radius//var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /netnfork/radius//var/log/radius/radacct/ 127.0.0.1/detail-20120629 Fri Jun 29 10:20:06 2012 : Info: [detail] expand: %t -> Fri Jun 29 10:20:06 2012 Fri Jun 29 10:20:06 2012 : Info: ++[detail] returns ok Fri Jun 29 10:20:06 2012 : Info: [radutmp] expand: /netnfork/radius//var/log/radius/radutmp -> /netnfork/radius//var/log/radius/radutmp Fri Jun 29 10:20:06 2012 : Info: [radutmp] expand: %{User-Name} -> test1 Fri Jun 29 10:20:06 2012 : Info: ++[radutmp] returns ok Fri Jun 29 10:20:06 2012 : Info: [sql] expand: %{User-Name} -> test1 Fri Jun 29 10:20:06 2012 : Info: [sql] sql_set_user escaped user --> 'test1' Fri Jun 29 10:20:06 2012 : Info: [sql] expand: %{NAS-Port} -> 1 Fri Jun 29 10:20:06 2012 : Info: [sql] expand: %{Acct-Delay-Time} -> Fri Jun 29 10:20:06 2012 : Info: [sql] ... expanding second conditional Fri Jun 29 10:20:06 2012 : Info: [sql] expand: INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctAuthentic, ConnectInfo_start, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, XAscendSessionSvrKey) VALUES('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', NULLIF('%{Realm}', ''), '%{NAS-IP-Address}', %{%{NAS-Port}:-NULL}, '%{NAS-Port-Type}', ('%S'::timestamp - '%{%{Acct-Delay-Time}:-0}'::interval), '%{Acct-Authentic}', '%{Connect-Info}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', NULLIF('%{Framed-IP-Address}', '')::inet, 0, '%{X-Ascend-Session-Svr-Key}') -> INSERT INTO radacct (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctAuthentic, ConnectInfo_start, CalledStationId, CallingStationId, ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay, Fri Jun 29 10:20:06 2012 : Debug: rlm_sql (sql): Reserving sql socket id: 0 Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: Status: PGRES_COMMAND_OK Fri Jun 29 10:20:06 2012 : Debug: rlm_sql_postgresql: query affected rows = 1 Fri Jun 29 10:20:06 2012 : Debug: rlm_sql (sql): Released sql socket id: 0 Fri Jun 29 10:20:06 2012 : Info: ++[sql] returns ok Sending Accounting-Response of id 47 to 127.0.0.1 port 56325 Fri Jun 29 10:20:06 2012 : Info: Finished request 2. Fri Jun 29 10:20:06 2012 : Info: Cleaning up request 2 ID 47 with timestamp +263 Fri Jun 29 10:20:06 2012 : Debug: Going to the next request Fri Jun 29 10:20:06 2012 : Debug: Waking up in 4.9 seconds. Fri Jun 29 10:20:11 2012 : Info: Cleaning up request 1 ID 87 with timestamp +263 Fri Jun 29 10:20:11 2012 : Info: Ready to process requests. when I authenticate for the second time the user (after logged it out), I get some more lines in the debug output, and also the Session-Timeout attribute is send. Bellow are some lines that appear in plus to the first debug track: For //***1 the lines are: Fri Jun 29 10:25:43 2012 : Debug: rlm_sqlcounter: Check item is greater than query result Fri Jun 29 10:25:43 2012 : Debug: rlm_sqlcounter: Authorized user test3, check_item=60, counter=10 Fri Jun 29 10:25:43 2012 : Debug: rlm_sqlcounter: Sent Reply-Item for user test3, Type=Session-Timeout, value=50 Fri Jun 29 10:25:43 2012 : Info: ++[hourlycounter] returns ok For //***2 Sending Access-Accept of id 117 to 127.0.0.1 port 39595 Session-Timeout = 50 So, as you can see from my comments, the Session-Timeout attribute isn't present in the radius response debug from the first login. The second time when it appears, it is caluculated correctly. For now I think that I have an issue with FR, so I don't go further to my chillispot NAS yet. Do you have some suggestions? N.B. 1. I changed the counter module name from dailycounter to hourlycounter, for clearness. 2. Also, in the good working scenario debug trace, I logged in with test3 username. (to clarify the username incompatibilities from the two debug output) 3. If you need also the second debug trace entirely, just let me know. On Thu, Jun 28, 2012 at 3:50 PM, Fajar A. Nugraha <list@fajar.net> wrote:
On Thu, Jun 28, 2012 at 7:34 PM, Andrei Petru Mura <mapandrei@gmail.com> wrote:
id | username | attribute | op | value
-----+------------------------+----------------------------+----+------------
167 | test1 | Password | := | test1 168 | test1 | Max-Daily-Session | := | 60
The problem is that every time when I authenticate for the first time per hour (because the sqlcounter is resetted hourly), with username test1, I can access the services given by freeradius an unlimited time.
That's not right. - Did you read the wiki? - Did you try to run FR in debug mode? Did it send Session-Timeout attribute? Was it calculated correctly? - Does your NAS honor Session-Timeout attribute?
IIRC some NAS (e.g. chillispot) ignores some attributes (e.g. Acct-Interim-Interval) if it's too small (e.g <= 60 seconds). That might be the case in your setup (although the attribute here is different).
-- Fajar - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html