RE: sql returns fail for some stop requests
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.
Amir Tal wrote:
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?
It SHOULD run the normal query, followed by the "alt" query.
In addition, currently there is no scheduled clearing of the data in radacct table, wont this increase in occurrence?
Yes. Accounting is about storing data. If you want to delete data, it's one line of SQL.
[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'
OK... it SHOULD run the "alt" query here, to UPDATE the record.
WARNING: Child is hung for request 5763411 in component <core> module <queue>. WARNING: Child is hung for request 5763412 in component <core> module <queue>.
And that's a problem. Your SQL database is slow. Fix it. Alan DeKok.
On 22 Jul 2012, at 11:56, Amir Tal wrote:
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 --
Can you please build against the current v2.1.x HEAD; the debug output doesn't make sense when checking through the rlm_sql.c code. Could you also post your dialup.conf file. -Arran
participants (3)
-
Alan DeKok -
Amir Tal -
Arran Cudbard-Bell