rlm_sql_null driver sometimes writes truncated lines
I'm currently using the rlm_sql_null driver to write accounting updates to a flat file, which are then sent up to an external database using radsqlrelay. On a very small percentage of the records (Maybe once out of every million records or so), one of the lines gets truncated in the output file, causing it to be merged with the next record. Here is one such example. About halfway through the line, you can see where the first sql statement is only partially written, and then the next UPDATE starts all on the same line (AND AcctStopTime UPDATE radacct). radsqlrelay does not handle this gracefully. When it fails to execute the invalid SQL it just goes into an infinite loop, trying to execute that same SQL statement over and over. Given the infrequency that it happens, I'm not sure that it would feasible to get debug output from radiusd when it happens, although I'm open to suggestions on how to capture any useful info. Wondering if anybody has seen anything like before? I'm currently running the freeradius-3.0.13-6.el7.x86_64 rpm from the EPEL repo for CentOS 7. It doesn't happen often, but we're generating millions of accounting updates a day across hundreds of freeradius servers, so it has been popping up somewhere just about every day. UPDATE radacct SET FramedIPAddress = NULLIF('172.21.22.24', '')::inet, AcctSessionTime = 600, AcctInterval = (1520393120 - EXTRACT(EPOCH FROM (COALESCE(AcctUpdateTime, AcctStartTime)))), AcctUpdateTime = TO_TIMESTAMP(1520393120), AcctInputOctets = (('0'::bigint << 32) + '0'::bigint), AcctOutputOctets = (('0'::bigint << 32) + '0'::bigint) WHERE (AcctUniqueId = 'fb8de85671b07d2387ec982a42bb4ea4') AND AcctStopTime UPDATE radacct SET AcctStopTime = TO_TIMESTAMP(1520396146), AcctUpdateTime = TO_TIMESTAMP(1520396146), AcctSessionTime = COALESCE(10806, (1520396146 - EXTRACT(EPOCH FROM(AcctStartTime)))), AcctInputOctets = (('0'::bigint << 32) + '0'::bigint), AcctOutputOctets = (('0'::bigint << 32) + '0'::bigint), AcctTerminateCause = '', FramedIPAddress = NULLIF('172.21.22.61', '')::inet, ConnectInfo_stop = '' WHERE (AcctUniqueId = '1c43554feb67bd56087b0656fefdad17') AND AcctStopTime IS NULL; Shawn Asmussen
might be when something like logrotate is being called - how are you restarting the daemon in that process if it occurs? also, why that method rather than just using buffered_sql virtual server? alan
Well, logrotate is doing a systemctl reload-or-try-restart radiusd, and from the system unit file, it looks like that's resulting in sending a HUP signal to radiusd. Will radiusd potentially throw some of the data away in that case if it's in the middle of a write when it gets the HUP signal? I'm not actually familiar with the details of using buffered_sql, but I'll look into it if it might be something that accomplishes what we need. The current method was chosen because the database server that the accounting data is being written to might occasionally be unavailable, so we wanted to be able to accumulate the accounting updates and have them get caught up on when the database server becomes available again, but if buffered_sql will accomplish that in a better way, I'm definitely open to it. Looks like I have some reading to do. On Thu, Mar 8, 2018 at 2:05 PM, Alan Buxey <alan.buxey@gmail.com> wrote:
might be when something like logrotate is being called - how are you restarting the daemon in that process if it occurs?
also, why that method rather than just using buffered_sql virtual server?
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/ list/users.html
On Mar 8, 2018, at 3:25 PM, Shawn Asmussen <shawn.asmussen@gmail.com> wrote:
I'm currently using the rlm_sql_null driver to write accounting updates to a flat file, which are then sent up to an external database using radsqlrelay. On a very small percentage of the records (Maybe once out of every million records or so), one of the lines gets truncated in the output file, causing it to be merged with the next record. Here is one such example. About halfway through the line, you can see where the first sql statement is only partially written, and then the next UPDATE starts all on the same line (AND AcctStopTime UPDATE radacct). radsqlrelay does not handle this gracefully. When it fails to execute the invalid SQL it just goes into an infinite loop, trying to execute that same SQL statement over and over. Given the infrequency that it happens, I'm not sure that it would feasible to get debug output from radiusd when it happens, although I'm open to suggestions on how to capture any useful info. Wondering if anybody has seen anything like before? I'm currently running the freeradius-3.0.13-6.el7.x86_64 rpm from the EPEL repo for CentOS 7.
Try the v3.0.x branch from github. We've found and fixed a few issues with locking since 3.0.13. Alan DeKok.
participants (3)
-
Alan Buxey -
Alan DeKok -
Shawn Asmussen