sql returns fail for some stop requests
Amir Tal
amir at ccc.co.il
Sun Jul 15 14:15:46 CEST 2012
(sorry if this is duplicate)
i have modified the sql queries and removed unnecessary whitespace,
but am still getting some queries cut-off in the log.
the main issue is with accounting stop requests.
(i am using the default queries provided with freeradius 2.1.12 - dialup.conf)
is there a way to increase the space/memory available for sql queries?
the main issue is with accounting stop requests.
in addition i have found the following in the logs:
rlm_sql (sql): There are no DB handles to use! skipped 0, tried to connect 0
++[sql] returns fail
number of DB connections has already been raised from the default 5 to 25,
this is a rare error, but it still exists, might be related.
Amir.
From: Amir Tal
Sent: Wednesday, July 11, 2012 4:48 PM
To: 'freeradius-users at lists.freeradius.org'
Subject: sql returns fail for some stop requests
Freeradius ver 2.1.12, configured to use ldap for auth, sql for acct.
Sometimes users' sessions get stuck and have to be closed manualy (simultaneous use is turned on for all users).
After extensive debugging I have found the following in the logs (radius -X)
[<thread>] # Executing section preacct from file /etc/raddb/sites-enabled/default
[<thread>] +- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 14117776,Client-IP-Address = xx.xx.xx.xx,NAS-IP-Address = xx.xx.xx.xx,Acct-Session-Id = "erx ip:109.226.0.9:147.235.234.115:1e47:6248:14c2:8b6a:5dac845:0060992452",Use
r-Name = "xxxxxxxxx at ccc"'
[acct_unique] Acct-Unique-Session-ID = "d49ba42fa077f5f0".
++[acct_unique] returns ok
[suffix] Looking up realm "ccc" for User-Name = "xxxxxxxxx at ccc"
[suffix] Found realm "ccc"
[suffix] Adding Stripped-User-Name = "xxxxxxxxx"
[suffix] Adding Realm = "ccc"
[suffix] Accounting realm is LOCAL.
++[suffix] returns ok
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> xx.xx.xx.xx
[detail] expand: /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /var/log/radius/radacct/xx.xx.xx.xx/detail-20120711
[detail] /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/radius/radacct/xx.xx.xx.xx/detail-20120711
[detail] expand: %t -> Wed Jul 11 02:03:45 2012
Cleaning up request 12612249 ID 93 with timestamp +729235
++[detail] returns ok
[detail.moreshet] expand: /var/log/radius/radacct/moreshet.relay -> /var/log/radius/radacct/moreshet.relay
[detail.moreshet] /var/log/radius/radacct/moreshet.relay expands to /var/log/radius/radacct/moreshet.relay
[detail.moreshet] expand: %t -> Wed Jul 11 02:03:45 2012
++[detail.moreshet] returns ok
++[unix] returns ok
[sql] expand: %{Stripped-User-Name} -> xxxxxxxxx
[sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> xxxxxxxxx
[sql] sql_set_user escaped user --> 'xxxxxxxxx'
[sql] expand: %{Acct-Input-Gigawords} -> 0
[sql] expand: %{Acct-Input-Octets} -> 4001
[sql] expand: %{Acct-Output-Gigawords} -> 0
[sql] expand: %{Acct-Output-Octets} -> 8134
[sql] expand: %{Acct-Delay-Time} -> 0
[sql] expand: UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}' -> UPDATE radacct SET acctstoptime = '2012-07-11 02:03:45', acctsessiontime = '517', acctinputoctets = '0' << 32 | '4001', acctoutputoctets = '0' << 32 |
[sql] expand: /var/log/radius/sqltrace.sql -> /var/log/radius/sqltrace.sql
Cleaning up request 12612250 ID 95 with timestamp +729235
++[sql] returns fail
Thread 20 got semaphore
Thread 19 got semaphore
It seems the last SQL query line is cut off for some reason, this only happens on some connections, while others are stopped correctly.
Not specific to users or time of day.
Versions information:
cat /etc/issue :
CentOS release 5.6 (Final)
Kernel \r on an \m
rpm -qa | grep radius :
freeradius2-python-2.1.12-7
freeradius2-ldap-2.1.12-7
freeradius2-2.1.12-7
freeradius2-krb5-2.1.12-7
freeradius2-mysql-2.1.12-7
freeradius2-utils-2.1.12-7
freeradius2-postgresql-2.1.12-7
freeradius2-perl-2.1.12-7
freeradius2-unixODBC-2.1.12-7
additional logs and/or information can be provided if required.
Help would be appreciated.
The Cloud has no limit !
[cid:image001.jpg at 01CD629C.B663DAB0]<http://www.ccc.co.il/>
Amir Tal
Systems Automation Expert
Cloud Services
Direct: 972-(0)3-9201471
Fax: 972-(0)-3-9201442
www.ccc.co.il<http://www.ccc.co.il/> [cid:image002.png at 01CD629C.B663DAB0] <http://www.facebook.com/triplec.il>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120715/0b38d918/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image001.jpg
Type: image/jpeg
Size: 12763 bytes
Desc: image001.jpg
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120715/0b38d918/attachment-0001.jpg>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image002.png
Type: image/png
Size: 845 bytes
Desc: image002.png
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120715/0b38d918/attachment-0001.png>
More information about the Freeradius-Users
mailing list