default linelog Accounting-Request handling broken?
Hi, I made my own instance of linelog and configured it just like the default, i.e. it has: format = "..." reference = "%{%{Packet-Type}:-format}" Accounting-Request { Start = "..." unknown = "..." } However, I'm not getting the Accounting-Request block interpreted at all, it just reverts to the format variable. As a workaround I set it to: format = "%S This is a log message for %{User-Name} for packet type: %{Packet-Type} (%{request:Acct-Status-Type})" and I get this at debug level 2: [myownlittle_linelog] expand: %{Packet-Type} -> Accounting-Request [myownlittle_linelog] expand: %{%{Packet-Type}:-format} -> Accounting-Request [myownlittle_linelog] Entry ".Accounting-Request" is not a variable assignment [myownlittle_linelog] expand: /var/log/freeradius/linelog -> /var/log/freeradius/linelog [myownlittle_linelog] expand: %S This is a log message for %{User-Name} for packet type: %{Packet-Type} (%{request:Acct-Status-Type}) -> 2009-11-25 02:17:02 This is a log message for user@example.tld for packet type: Accounting-Request (Start) ++[myownlittle_linelog] returns ok AFAICT from reading rlm_linelog.c, that looks like cf_reference_item() worked, but cf_item_is_pair() didn't. Well, that actually makes perfect sense. Just to verify, I added: if (cf_item_is_section(ci)) { radlog(L_ERR, "Entry \"%s\" is a section and we expected a plain variable", line); } And I got that logged. Aren't we missing a critical block of code here? :) -- 2. That which causes joy or happiness.
Josip Rodin wrote:
Hi,
I made my own instance of linelog and configured it just like the default, i.e. it has:
format = "..." reference = "%{%{Packet-Type}:-format}"
That's used for logging per-packet information.
Accounting-Request { Start = "..." unknown = "..." }
See the comments right above that entry for the *correct* reference to use for accounting requests. Alan DeKok.
On Wed, Nov 25, 2009 at 08:50:32AM +0100, Alan DeKok wrote:
I made my own instance of linelog and configured it just like the default, i.e. it has:
format = "..." reference = "%{%{Packet-Type}:-format}"
That's used for logging per-packet information.
Accounting-Request { Start = "..." unknown = "..." }
See the comments right above that entry for the *correct* reference to use for accounting requests.
OK, that actually makes sense. But it makes no sense to have that commented out while the below block is *not* commented out. Please either uncomment it both or comment it both, this makes for one confusing example :) -- 2. That which causes joy or happiness.
On Wed, Nov 25, 2009 at 02:33:30AM +0100, Josip Rodin wrote:
[myownlittle_linelog] expand: %{%{Packet-Type}:-format} -> Accounting-Request [myownlittle_linelog] Entry ".Accounting-Request" is not a variable assignment
Speaking of which, while browsing 558c51a711d7a326604eda0fc51040cbda2b77a8 I just noticed that it would be good for these error messages be elevated so that users can see them outside of debug mode. Specifically: RDEBUG2("Badly formatted variable: %s", *from); RDEBUG2("Badly formatted variable: %s", p); RDEBUG2("No trailing :- after variable at %s", p); RDEBUG2("Invalid text after :- at %s", p); Those should be error log, while: RDEBUG2("Improperly nested variable; %%{%s}", p); RDEBUG2("WARNING: Deprecated conditional expansion \":-\". See \"man unlang\" for details"); RDEBUG2("WARNING: Unknown module \"%s\" in string expansion \"%%%s\"", xlat_name, *from); Those looks like info messages. -- 2. That which causes joy or happiness.
Josip Rodin wrote:
Speaking of which, while browsing 558c51a711d7a326604eda0fc51040cbda2b77a8 I just noticed that it would be good for these error messages be elevated so that users can see them outside of debug mode. Specifically:
RDEBUG2("Badly formatted variable: %s", *from); RDEBUG2("Badly formatted variable: %s", p); RDEBUG2("No trailing :- after variable at %s", p); RDEBUG2("Invalid text after :- at %s", p);
Those should be error log, while:
RDEBUG2("Improperly nested variable; %%{%s}", p); RDEBUG2("WARNING: Deprecated conditional expansion \":-\". See \"man unlang\" for details"); RDEBUG2("WARNING: Unknown module \"%s\" in string expansion \"%%%s\"", xlat_name, *from);
Those looks like info messages.
Are you sure you want these messages for *every* packet? Wouldn't it be better to warn about mis-configurations in debug mode only? Alan DeKok.
On Sun, Dec 06, 2009 at 07:43:49PM +0100, Alan DeKok wrote:
Josip Rodin wrote:
Speaking of which, while browsing 558c51a711d7a326604eda0fc51040cbda2b77a8 I just noticed that it would be good for these error messages be elevated so that users can see them outside of debug mode. Specifically:
RDEBUG2("Badly formatted variable: %s", *from); RDEBUG2("Badly formatted variable: %s", p); RDEBUG2("No trailing :- after variable at %s", p); RDEBUG2("Invalid text after :- at %s", p);
Those should be error log, while:
RDEBUG2("Improperly nested variable; %%{%s}", p); RDEBUG2("WARNING: Deprecated conditional expansion \":-\". See \"man unlang\" for details"); RDEBUG2("WARNING: Unknown module \"%s\" in string expansion \"%%%s\"", xlat_name, *from);
Those looks like info messages.
Are you sure you want these messages for *every* packet? Wouldn't it be better to warn about mis-configurations in debug mode only?
People should want to know as soon as possible if their configuration is has syntax errors - it's likely that the same issue can have bad effects on the functionality they want. Thinking about it, people on high-traffic sites might get bothered with extra logs and extra disk space usage. But, those are the same kind of people who will not use debug mode because of its disk space issues. -- 2. That which causes joy or happiness.
Josip Rodin wrote:
People should want to know as soon as possible if their configuration is has syntax errors - it's likely that the same issue can have bad effects on the functionality they want.
I agree. They should "test" their configuration before putting it live into a production environment. Testing should involve running it in debugging mode.
Thinking about it, people on high-traffic sites might get bothered with extra logs and extra disk space usage. But, those are the same kind of people who will not use debug mode because of its disk space issues.
It doesn't take any disk space to run it in debugging mode for tests. For everyone else, getting 1000 log messages/s because of a configuration typo is a *bad* thing. Alan DeKok.
On Sun, Dec 06, 2009 at 08:34:41PM +0100, Alan DeKok wrote:
Josip Rodin wrote:
People should want to know as soon as possible if their configuration is has syntax errors - it's likely that the same issue can have bad effects on the functionality they want.
I agree. They should "test" their configuration before putting it live into a production environment. Testing should involve running it in debugging mode.
Thinking about it, people on high-traffic sites might get bothered with extra logs and extra disk space usage. But, those are the same kind of people who will not use debug mode because of its disk space issues.
It doesn't take any disk space to run it in debugging mode for tests.
For everyone else, getting 1000 log messages/s because of a configuration typo is a *bad* thing.
There are some critical conditionals in the above. Ultimately the question is whether you can really expect most users to be perfect citizens who follow all the recommendations and don't ever make errors in production environments, or if you don't expect much of them and assume that they are best served by getting clear error messages whenever and however they manage to screw things up. People whose servers do 1k operations/s are the ones who can be assumed to be already prepared for the situation where the log volume increases by a magnitude, for whatever reason. -- 2. That which causes joy or happiness.
Hi,
People whose servers do 1k operations/s are the ones who can be assumed to be already prepared for the situation where the log volume increases by a magnitude, for whatever reason.
err, no - the reason? most of our logging of RADIUS stuff does into fast DBs - hosted elsewhere. therefore local logging is actually an issue - and we certainly wouldnt want these 'complaints' printed out with every single packet. what might be good would be for the daemon to just STOP if it came across certain issues and got the admin to sort out their config - the nice deprecated :- issue, for example ;-) alan
On Sun, Dec 06, 2009 at 09:54:31PM +0000, Alan Buxey wrote:
Hi,
People whose servers do 1k operations/s are the ones who can be assumed to be already prepared for the situation where the log volume increases by a magnitude, for whatever reason.
err, no - the reason? most of our logging of RADIUS stuff does into fast DBs - hosted elsewhere. therefore local logging is actually an issue - and we certainly wouldnt want these 'complaints' printed out with every single packet.
what might be good would be for the daemon to just STOP if it came across certain issues and got the admin to sort out their config - the nice deprecated :- issue, for example ;-)
So you fit the bill anyway - if you're prepared for a completely dead FreeRADIUS, you're prepared for the situation such as a logging issue. -- 2. That which causes joy or happiness.
Hi,
So you fit the bill anyway - if you're prepared for a completely dead FreeRADIUS, you're prepared for the situation such as a logging issue.
not at all. dead radiusd not an issue compared to several gigabytes of sudden unexpected log behaviour due to an issue at remote proxy, for example. our servers are geared up for a virtual environment with pretty much lack of local disk space and remote disk at a 'premium' compared to fast DB access for the requirements we need. if you change the 'profile' of the server - ie it suddenly is disk hungry, then people have to change their server setup and layout. not good. alan
On Tue, Dec 08, 2009 at 09:59:32AM +0000, Alan Buxey wrote:
Hi,
So you fit the bill anyway - if you're prepared for a completely dead FreeRADIUS, you're prepared for the situation such as a logging issue.
not at all. dead radiusd not an issue compared to several gigabytes of sudden unexpected log behaviour due to an issue at remote proxy, for example. our servers are geared up for a virtual environment with pretty much lack of local disk space and remote disk at a 'premium' compared to fast DB access for the requirements we need.
if you change the 'profile' of the server - ie it suddenly is disk hungry, then people have to change their server setup and layout. not good.
How could local configuration parsing be an issue caused by a remote proxy? This code does not parse remote input, IIRC. Again, my point was that people who are prepared to immediately intervene in a dead radiusd are most commonly are prepared to immediately intervene in a faulty configuration file. -- 2. That which causes joy or happiness.
Hi,
Again, my point was that people who are prepared to immediately intervene in a dead radiusd are most commonly are prepared to immediately intervene in a faulty configuration file.
revisiting the early messages in this thread clearly indicate a desire for much more verbose logging of proxy issues....almost, if not exactly, a per-packer log when errors arise. that is a 'bad thing' IMHO. much better to have the current situation. you could argue - and I'll agree with it - that a tool like raddebug could be used to attach to the process and view the debug of proxy issues live and inline - just as it can be used for verbose client logging on a chosen station when not running the daemon in full debug. alan
On Tue, Dec 08, 2009 at 11:32:36AM +0000, Alan Buxey wrote:
Hi,
Again, my point was that people who are prepared to immediately intervene in a dead radiusd are most commonly are prepared to immediately intervene in a faulty configuration file.
revisiting the early messages in this thread clearly indicate a desire for much more verbose logging of proxy issues....almost, if not exactly, a per-packer log when errors arise. that is a 'bad thing' IMHO. much better to have the current situation. you could argue - and I'll agree with it - that a tool like raddebug could be used to attach to the process and view the debug of proxy issues live and inline - just as it can be used for verbose client logging on a chosen station when not running the daemon in full debug.
But the proxy state logging is not a priori per-packet, it's based on status check events. Only if each packet changes the proxy status (?!), then you'll get as many status check logs as there are packets. (This discussion is getting annoyingly circular.) -- 2. That which causes joy or happiness.
Josip Rodin wrote:
But the proxy state logging is not a priori per-packet, it's based on status check events. Only if each packet changes the proxy status (?!), then you'll get as many status check logs as there are packets.
Ah... that's the misunderstanding. The messages which should be debug-only, and not log file are *exactly* those messages which will be logged on every packet. This includes: - configuration typos (e.g. improper expansions) - "failed to do X with this packet" - anything else "per packet". Logging *state changes* is OK. e.g. "this packet caused the proxy to decide that the home server is down". That happens for *one* packet, when the home server changes state. The messages you've asked to make "log file" would result in per-packet errors, not general state change errors. That's why I'm reluctant to make those changes. Alan DeKok.
Hi,
The messages you've asked to make "log file" would result in per-packet errors, not general state change errors. That's why I'm reluctant to make those changes.
exactly. chuck me EVERYTHING in debug mode. i'll take the hit..i NEED the info... but in general use - status change only... it'd be nice if SNMPTRAPs could be generated too natively but thats a different issue. alan
On Tue, Dec 08, 2009 at 11:02:30PM +0100, Alan DeKok wrote:
Logging *state changes* is OK. e.g. "this packet caused the proxy to decide that the home server is down". That happens for *one* packet, when the home server changes state.
The messages you've asked to make "log file" would result in per-packet errors, not general state change errors. That's why I'm reluctant to make those changes.
Yes, I understood that originally. The gist of the rationale for the current behaviour is quite clear, but even so, many users would nevertheless be best served by many per-packet errors being more clearly visible, because even when they enable debug level 2+, they get a huge amount of output that is hard for them to handle. Errors don't particularly stand out in the crowd, and that isn't practical. Perhaps the best compromise for some of these issues would be what the Linux kernel folks did with WARN_ONCE() or printk_once(). -- 2. That which causes joy or happiness.
Josip Rodin wrote:
Yes, I understood that originally. The gist of the rationale for the current behaviour is quite clear, but even so, many users would nevertheless be best served by many per-packet errors being more clearly visible, because even when they enable debug level 2+, they get a huge amount of output that is hard for them to handle. Errors don't particularly stand out in the crowd, and that isn't practical.
Good point.
Perhaps the best compromise for some of these issues would be what the Linux kernel folks did with WARN_ONCE() or printk_once().
I'll look into that. Alan DeKok.
participants (3)
-
Alan Buxey -
Alan DeKok -
Josip Rodin