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.