sql returns fail for some stop requests
Amir Tal
amir at ccc.co.il
Sun Jul 22 12:56:07 CEST 2012
Adding unique key to the database results in the following being returned from rlm_sql,
What happen to accounting data when a duplicate entry is encountered?
In addition, currently there is no scheduled clearing of the data in radacct table, wont this increase in occurrence?
--
[sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> shimoni
[sql] sql_set_user escaped user --> 'shimoni'
[sql] expand: %{Acct-Input-Gigawords} -> 0
[sql] expand: %{Acct-Input-Octets} -> 0
[sql] expand: %{Acct-Output-Gigawords} -> 0
[sql] expand: %{Acct-Output-Octets} -> 0
[sql] expand: %{Acct-Delay-Time} -> 12
[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-22 02:03:28', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Error', acctstopdelay = '12', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.9:172.29.81.67:3280:96f8:1aa8:87fb:4d2:0062712021' AND username = 'shimoni' AND nasipaddress = '109.226.1.12'
[sql] expand: /var/log/radius/sqltrace.sql -> /var/log/radius/sqltrace.sql
rlm_sql_mysql: MYSQL check_error: 1062 received
[sql] Couldn't insert SQL accounting STOP record - Duplicate entry 'c6d3d253355b3dcf' for key 2
rlm_sql_mysql: MYSQL check_error: 1062 received
rlm_sql_mysql: Cannot store result
rlm_sql_mysql: MySQL error 'Duplicate entry 'c6d3d253355b3dcf' for key 2'
rlm_sql (sql): Released sql socket id: 11
++[sql] returns fail
--
[detail.moreshet] /var/log/radius/radacct/moreshet.relay expands to /var/log/radius/radacct/moreshet.relay
[sql] expand: %{Acct-Delay-Time} -> 0
[detail.moreshet] expand: %t -> Sun Jul 22 02:03:34 2012
[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-22 02:03:34', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Error', acctstopdelay = '0', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.9:172.24.245.233:2653:c9e:101:e0ba:4d2:0062712040' AND username = 'mosh19703' AND nasipaddress = '109.226.1.12'
[sql] expand: /var/log/radius/sqltrace.sql -> /var/log/radius/sqltrace.sql
[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 -> Sun Jul 22 02:03:34 2012
++[detail.moreshet] returns ok
rlm_sql_mysql: MYSQL check_error: 1062 received
[sql] Couldn't insert SQL accounting ALIVE record - Duplicate entry '923952cbd6569744' for key 2
rlm_sql_mysql: MYSQL check_error: 1062 received
rlm_sql_mysql: Cannot store result
rlm_sql_mysql: MySQL error 'Duplicate entry '923952cbd6569744' for key 2'
rlm_sql (sql): Released sql socket id: 27
++[sql] returns fail
--
Just wanted to state that I had started with the default provided configuration files,
Alredy changed the rlm_sql source code, default SQL queries, default DB structure.
There are still unclosed accounting packets existing.
Log shows a lot of warning messages:
rlm_sql (sql): Reserving sql socket id: 31
rlm_sql_mysql: query: UPDATE radacct SET acctstoptime = '2012-07-22 02:04:57', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Request', acctstopdelay = '0', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.17:172.23.184.73:dd94:1847:fcca:a66:4d2:0051412783' AND username = 'yali4780' AND nasipaddress = '109.226.1.20'
[sql] expand: %{Acct-Input-Gigawords} -> 0
[sql] expand: %{Acct-Input-Octets} -> 0
[sql] expand: %{Acct-Output-Gigawords} -> 0
[sql] expand: %{Acct-Output-Octets} -> 0
[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-22 02:04:57', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Error', acctstopdelay = '0', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.9:147.235.134.62:3742:41fe:4d2:5019:56ac253:0062712137' AND username = '8532433' AND nasipaddress = '109.226.1.12'
[sql] expand: /var/log/radius/sqltrace.sql -> /var/log/radius/sqltrace.sql
rlm_sql (sql): Reserving sql socket id: 30
rlm_sql_mysql: query: UPDATE radacct SET acctstoptime = '2012-07-22 02:04:57', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Error', acctstopdelay = '0', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.9:147.235.134.62:3742:41fe:4d2:5019:56ac253:0062712137' AND username = '8532433' AND nasipaddress = '109.226.1.12'
WARNING: Child is hung for request 5763408 in component <core> module <queue>.
WARNING: Child is hung for request 5763409 in component <core> module <queue>.
WARNING: Child is hung for request 5763410 in component <core> module <queue>.
rlm_sql (sql): Connected new DB handle, #20
rlm_sql (sql): Reserving sql socket id: 20
rlm_sql (sql): got socket 20 after skipping 0 unconnected handles, tried to reconnect 1 though
rlm_sql_mysql: query: UPDATE radacct SET acctstoptime = '2012-07-22 02:04:57', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Error', acctstopdelay = '9', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.17:172.20.11.9:a3b4:30bf:3c4d:3ae3:4d2:0051412759' AND username = 'l100200' AND nasipaddress = '109.226.1.20'
WARNING: Child is hung for request 5763411 in component <core> module <queue>.
WARNING: Child is hung for request 5763412 in component <core> module <queue>.
rlm_sql (sql): Connected new DB handle, #18
rlm_sql (sql): Reserving sql socket id: 18
rlm_sql (sql): got socket 18 after skipping 0 unconnected handles, tried to reconnect 1 though
rlm_sql_mysql: query: UPDATE radacct SET acctstoptime = '2012-07-22 02:04:57', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Request', acctstopdelay = '6', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.17:172.28.242.195:f4ad:67aa:a8d9:ffcf:4d2:0051412766' AND username = 'avico313' AND nasipaddress = '109.226.1.20'
rlm_sql (sql): Connected new DB handle, #9
rlm_sql (sql): Reserving sql socket id: 9
rlm_sql (sql): got socket 9 after skipping 0 unconnected handles, tried to reconnect 1 though
rlm_sql_mysql: query: UPDATE radacct SET acctstoptime = '2012-07-22 02:04:57', acctsessiontime = '0', acctinputoctets = '0' << 32 | '0', acctoutputoctets = '0' << 32 | '0', acctterminatecause = 'User-Request', acctstopdelay = '0', connectinfo_stop = '' WHERE acctsessionid = 'erx ip:109.226.0.17:172.20.5.237:f847:c445:f249:dfce:4d2:0051412782' AND username = 'sapir25' AND nasipaddress = '109.226.1.20'
Child is finally responsive for request 5755840
Child is finally responsive for request 5755841
Child is finally responsive for request 5758217
Child is finally responsive for request 5758218
Child is finally responsive for request 5758219
Child is finally responsive for request 5757227
Child is finally responsive for request 5758220
Child is finally responsive for request 5757228
Child is finally responsive for request 5757229
Child is finally responsive for request 5757230
Child is finally responsive for request 5758221
Child is finally responsive for request 5758222
Child is finally responsive for request 5758223
Child is finally responsive for request 5758224
WARNING: Child is hung for request 5763245 in component <core> module <queue>.
WARNING: Child is hung for request 5763246 in component <core> module <queue>.
WARNING: Child is hung for request 5763247 in component <core> module <queue>.
WARNING: Child is hung for request 5763248 in component <core> module <queue>.
WARNING: Child is hung for request 5763249 in component <core> module <queue>.
WARNING: Child is hung for request 5763063 in component <core> module <queue>.
WARNING: Child is hung for request 5763072 in component <core> module <queue>.
WARNING: Child is hung for request 5763073 in component <core> module <queue>.
WARNING: Child is hung for request 5763074 in component <core> module <queue>.
WARNING: Child is hung for request 5763075 in component <core> module <queue>.
Amir.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20120722/c627f44f/attachment-0001.html>
More information about the Freeradius-Users
mailing list