Buffered SQL Setup Not Reading Detail File
I believe I've setup buffered SQL correctly in my configuration, and I do have some data that's made it into SQL... I used the default buffered-sql in sites-enabled on RHEL 6... In my sites-enabled/default, I have it logging to a detail file (and not SQL). I also have the sites-enabled/buffered-sql where the listen section has the detail file and the accounting section has sql-acct listed. I then have a file /etc/raddb called sql-acct where I've defined sql-acct (I also have a separate sql called sql-auth for authentication). The detail files are written (daily) and a detail.work is created, but it hangs and never disappears (nor written to the database). There only warnings/errors I see at all are: Mon Nov 7 15:51:12 2011 : Info: [sql-acct] stop packet with zero session length. [user 'user@realm.com', nas '10.99.0.39'] Mon Nov 7 15:52:31 2011 : Info: # Executing section accounting from file /etc/raddb/sites-enabled/default Mon Nov 7 15:52:31 2011 : Info: +- entering group accounting {...} Mon Nov 7 15:52:31 2011 : Info: [detail] expand: /var/log/radius/radacct/detail-%Y%m%d -> /var/log/radius/radacct/detail-20111107 Mon Nov 7 15:52:31 2011 : Info: [detail] /var/log/radius/radacct/detail-%Y%m%d expands to /var/log/radius/radacct/detail-20111107 Mon Nov 7 15:52:31 2011 : Info: [detail] expand: %t -> Mon Nov 7 15:52:31 2011 Mon Nov 7 15:52:31 2011 : Info: ++[detail] returns ok Mon Nov 7 15:52:31 2011 : Info: ++[unix] returns noop Mon Nov 7 15:52:31 2011 : Info: [radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp Mon Nov 7 15:52:31 2011 : Info: [radutmp] expand: %{User-Name} -> user@realm.com Mon Nov 7 15:52:31 2011 : Info: ++[radutmp] returns ok Any ideas on how to troubleshoot/fix this? Thanks, GG
Uncommenting: if (noop) { ok } solved the issue. Thank you very much. GG On Mon, Nov 7, 2011 at 4:20 PM, Alan DeKok <aland@deployingradius.com> wrote:
Gary T. Giesen wrote:
Mon Nov 7 15:51:12 2011 : Info: [sql-acct] stop packet with zero session length. [user 'user@realm.com', nas '10.99.0.39']
Read raddb/sites-available/default. Look for "zero".
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
I spoke too soon, that does not seem to have solved the issue.... On Mon, Nov 7, 2011 at 4:49 PM, Gary T. Giesen <giesen@snickers.org> wrote:
Uncommenting:
if (noop) { ok }
solved the issue.
Thank you very much.
GG
On Mon, Nov 7, 2011 at 4:20 PM, Alan DeKok <aland@deployingradius.com> wrote:
Gary T. Giesen wrote:
Mon Nov 7 15:51:12 2011 : Info: [sql-acct] stop packet with zero session length. [user 'user@realm.com', nas '10.99.0.39']
Read raddb/sites-available/default. Look for "zero".
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
I made the change to the configuration, watch the server go a little nuts with writing SQL to the database, and then it stops, and I'm still stuck with a detail.work file that's not getting processed... On Mon, Nov 7, 2011 at 5:46 PM, Gary T. Giesen <giesen@snickers.org> wrote:
I spoke too soon, that does not seem to have solved the issue....
On Mon, Nov 7, 2011 at 4:49 PM, Gary T. Giesen <giesen@snickers.org> wrote:
Uncommenting:
if (noop) { ok }
solved the issue.
Thank you very much.
GG
On Mon, Nov 7, 2011 at 4:20 PM, Alan DeKok <aland@deployingradius.com> wrote:
Gary T. Giesen wrote:
Mon Nov 7 15:51:12 2011 : Info: [sql-acct] stop packet with zero session length. [user 'user@realm.com', nas '10.99.0.39']
Read raddb/sites-available/default. Look for "zero".
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Tue, Nov 8, 2011 at 5:47 AM, Gary T. Giesen <giesen@snickers.org> wrote:
I made the change to the configuration, watch the server go a little nuts with writing SQL to the database, and then it stops, and I'm still stuck with a detail.work file that's not getting processed...
As usual, if something doesn't work, post the debug log. Anyway, here's some things so could try: - make sure you use latest 2.1.12. There are many improvements/bug fix there compared to previous, so it won't hurt to upgrade - put the noop -> ok block inside the detail reader virtual server (just in case you only uncomment it on default) - if the debug log complains about something in particular, try creating a specific unlang block to force that condition to an "ok" -- Fajar
I tried adding the noop block to the detail reader and doesn't seem to make a difference. I'm still seeing this suspicious debug: Tue Nov 8 10:34:18 2011 : Debug: [<thread>] server buffered-sql { Tue Nov 8 10:34:18 2011 : Debug: [<thread>] # Executing section preacct from file /etc/raddb/sites-enabled/buffered-sql Tue Nov 8 10:34:18 2011 : Debug: [<thread>] +- entering group preacct {...} Tue Nov 8 10:34:18 2011 : Debug: ++[preprocess] returns ok Tue Nov 8 10:34:18 2011 : Debug: ++[acct_unique] returns noop Tue Nov 8 10:34:18 2011 : Debug: ++[files] returns noop Tue Nov 8 10:34:18 2011 : Debug: # Executing section accounting from file /etc/raddb/sites-enabled/buffered-sql Tue Nov 8 10:34:18 2011 : Debug: +- entering group accounting {...} Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{Stripped-User-Name} -> Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] ... expanding second conditional Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{User-Name} -> user@realm.com Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{%{User-Name}:-DEFAULT} -> user@realm.com Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> user@realm.com Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] sql_set_user escaped user --> 'user@realm.com' Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{Acct-Input-Gigawords} -> Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] ... expanding second conditional Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{Acct-Input-Octets} -> 90 Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{Acct-Output-Gigawords} -> Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] ... expanding second conditional Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{Acct-Output-Octets} -> 76 Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: %{Acct-Delay-Time} -> 40725 Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: UPDATE radacct_stop 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_stop SET acctstoptime = '2011-11-08 10:34:18', acctsessiontime = '0', acctinputoctets = '0' << 32 | '90', Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] expand: stop packet with zero session length. [user '%{User-Name}', nas '%{NAS-IP-Address}'] -> stop packet with zero session length. [user 'user@realm.com', nas '10.99.0.39'] Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] stop packet with zero session length. [user 'user@realm.com', nas '10.99.0.39'] Tue Nov 8 10:34:18 2011 : Debug: ++[sql-acct] returns noop Tue Nov 8 10:34:18 2011 : Debug: } # server buffered-sql Tue Nov 8 10:34:18 2011 : Debug: Detail - No response configured for request 1929. Will retry in 30 seconds Tue Nov 8 10:34:18 2011 : Debug: Finished request 1929. Tue Nov 8 10:34:19 2011 : Debug: Cleaning up request 1929 ID 15923 with timestamp +166 Any suggestions on unlang to work around it (I've never used it before). GG
Hi,
I tried adding the noop block to the detail reader and doesn't seem to make a difference. I'm still seeing this suspicious debug:
Alan Dekok already told you this " Read raddb/sites-available/default. Look for "zero". " the trouble is, if you HAVE a zero thats sneaked in, then theres be troubles... so you need a wrapper around your sql-buffer reader...eg sql { invalid = 2 fail = 2 } if (fail || noop || invalid) { ok } in the buffered-sql (that syntax might work, take care!) or, even better, make sure the situation where the detail file gets such a thing doesnt happen in the first place eg, in your virtual server accounting section... if (Acct-Session-Time != 0) { detail } else { ok } alan
Alan, Thanks for your help, the problem was that I had 3 months of detail data previously that did have the problem. I misunderstood that adding Alan Dekok's block would fix the problem for my older data. I'm going to work on making sure it doesn't happen again, but for the time being my server is happily plowing through the detail data. Much thanks, GG On Tue, Nov 8, 2011 at 11:10 AM, Alan Buxey <A.L.M.Buxey@lboro.ac.uk> wrote:
Hi,
I tried adding the noop block to the detail reader and doesn't seem to make a difference. I'm still seeing this suspicious debug:
Alan Dekok already told you this
" Read raddb/sites-available/default. Look for "zero". "
the trouble is, if you HAVE a zero thats sneaked in, then theres be troubles... so you need a wrapper around your sql-buffer reader...eg
sql { invalid = 2 fail = 2 } if (fail || noop || invalid) { ok }
in the buffered-sql (that syntax might work, take care!)
or, even better, make sure the situation where the detail file gets such a thing doesnt happen in the first place eg, in your virtual server accounting section...
if (Acct-Session-Time != 0) { detail } else { ok }
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Gary T. Giesen wrote:
I tried adding the noop block to the detail reader and doesn't seem to make a difference. I'm still seeing this suspicious debug: ... Tue Nov 8 10:34:18 2011 : Debug: [sql-acct] stop packet with zero session length. [user 'user@realm.com', nas '10.99.0.39'] Tue Nov 8 10:34:18 2011 : Debug: ++[sql-acct] returns noop Tue Nov 8 10:34:18 2011 : Debug: } # server buffered-sql
So... you did *not* enable the "if (noop) { ok }" configuration after the "sql-acct" module. The configuration in raddb/sites-available/default is *documented*. It explains what is going on, and what happens when you make that change. The idea is for you to read it, understand it, and apply it wherever necessary. Simply uncommenting a few lines means you're *not* thinking about it. Alan DeKok.
Gary T. Giesen wrote:
I made the change to the configuration, watch the server go a little nuts with writing SQL to the database, and then it stops, and I'm still stuck with a detail.work file that's not getting processed...
As always, debug mode. You can use "raddebug" to debug a running server. Alan DeKok.
participants (4)
-
Alan Buxey -
Alan DeKok -
Fajar A. Nugraha -
Gary T. Giesen