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