Probmels with sqlcounter module in FreeRADIUS 2.1.12
Andrei Petru Mura
mapandrei at gmail.com
Fri Jun 29 09:58:21 CEST 2012
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 at fajar.net> wrote:
> On Thu, Jun 28, 2012 at 7:34 PM, Andrei Petru Mura <mapandrei at 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120629/55c057eb/attachment-0001.html>
More information about the Freeradius-Users
mailing list