'Re: [RESEND PATCH] add bb_info_msg was Re: Applets send errors to syslog during normal, successful o'

[prev in list] [next in list] [prev in thread] [next in thread] 

List:       busybox
Subject:    Re: [RESEND PATCH] add bb_info_msg was Re: Applets send errors to syslog during normal, successful o
From:       Tito <farmatito () tiscali ! it>
Date:       2018-03-04 21:12:21
Message-ID: 274dade6-e585-7df7-3ba1-a792eba060b5 () tiscali ! it
[Download RAW message or body]

On 04/03/2018 20:05, Denys Vlasenko wrote:
> On Wed, Feb 28, 2018 at 2:03 PM, Tito <farmatito@tiscali.it> wrote:
>> Hi,
>>
>> forgot to add the [PATCH] tag so I resend it.
>>
>> Ciao,
>> Tito
>>
>> On 04/02/2018 19:53, Denys Vlasenko wrote:
>>>
>>> On Thu, Nov 30, 2017 at 9:51 PM, Tito <farmatito@tiscali.it> wrote:
>>>>
>>>> On 11/30/2017 08:26 PM, Deweloper wrote:
>>>>>
>>>>> Many applets are daemons (or can be run as daemons) and send messages to
>>>>> syslog. The problem is that the messages don't have accurate,
>>>>> individually
>>>>> assigned severity; they are all LOG_ERR. Effectively, system
>>>>> administrator sees
>>>>> a lot of ERRORs in the log even when everything goes well. It seems that
>>>>> libbb
>>>>> provides only bb_error_msg() as a convenient way to print a message
>>>>> (including
>>>>> sending it to syslog), while a more generic function taking severity as
>>>>> well
>>>>> would be needed instead. grep -r 'syslog(' shows that only some
>>>>> loginutils call
>>>>> syslog() directly. In other places bb_error_msg() is used even for
>>>>> informational or verbose debugging messages. Just have a look at output
>>>>> of
>>>>> grep -r 'bb_error_msg('
>>>>>
>>>>> Do you have an idea how to clean this up? Shouldn't these messages be
>>>>> sent to a
>>>>> new function, e.g. bb_msg(), which would additionally take "severity"
>>>>> argument?
>>>
>>>
>>> The "severity" arg usually ends up being a PITA.
>>> For example, it's rather unreadable.
>>> Then, it tends to proliferate: after you have errors/not-errors,
>>> then someone wants critical/errors/not-errors/debug - which adds
>>> another dimension to coding every error message: "what severity is it?!"
>>>
>>>
>>>> 4) create a function that changes syslog_level to LOG_INFO, add it to
>>>> libbb,
>>>>      and then change the code of the applets accordingly, for example:
>>>>
>>>> void FAST_FUNC bb_info_msg(const char *s, ...)
>>>> {
>>>>           va_list p;
>>>> #if ENABLE_FEATURE_SYSLOG
>>>>           smallint syslog_level_old =  syslog_level;
>>>>           syslog_level = LOG_INFO;
>>>> #endif
>>>>           va_start(p, s);
>>>>           bb_verror_msg(s, p, NULL);
>>>> #if ENABLE_FEATURE_SYSLOG
>>>>           syslog_level = syslog_level_old;
>>>> #endif
>>>>           va_end(p);
>>>> }
>>>
>>>
>>> I like this. Feel free to send patches doing this.
>>>
>>>> I wonder if the compiler could be so smart to see that this is
>>>> the same as bb_error_msg when  ENABLE_FEATURE_SYSLOG is not set
>>>> and optimize it out.
>>>
>>>
>>> #if !ENABLE_FEATURE_SYSLOG
>>> #define bb_info_msg(...) bb_error_msg(__VA_ARGS__)
>>> #endif
>>>
>>
>> Hi,
>> attached you will find a patch that adds bb_info_msg function to libbb.
>> This patch is tested with and without CONFIG_SYSLOG
>> set but there are no users yet.
>>
>> Ciao,
>> Tito
>>
>> --- include/libbb.h.orig        2018-02-04 23:27:22.000000000 +0100
>> +++ include/libbb.h     2018-02-04 23:43:08.054064117 +0100
>> @@ -1277,6 +1277,11 @@ extern void (*die_func)(void);
>>   extern void xfunc_die(void) NORETURN FAST_FUNC;
>>   extern void bb_show_usage(void) NORETURN FAST_FUNC;
>>   extern void bb_error_msg(const char *s, ...) __attribute__ ((format
>> (printf, 1, 2))) FAST_FUNC;
>> +#if ENABLE_FEATURE_SYSLOG
>> +extern void bb_info_msg(const char *s, ...) __attribute__ ((format (printf,
>> 1, 2))) FAST_FUNC;
>> +#else
>> +#define bb_info_msg(...)       bb_error_msg(__VA_ARGS__)
>> +#endif
>>   extern void bb_error_msg_and_die(const char *s, ...) __attribute__
>> ((noreturn, format (printf, 1, 2))) FAST_FUNC;
>>   extern void bb_perror_msg(const char *s, ...) __attribute__ ((format
>> (printf, 1, 2))) FAST_FUNC;
>>   extern void bb_simple_perror_msg(const char *s) FAST_FUNC;
>> --- libbb/verror_msg.c.orig     2017-07-24 00:27:51.000000000 +0200
>> +++ libbb/verror_msg.c  2018-02-05 00:54:09.587081933 +0100
>> @@ -180,3 +180,17 @@ void FAST_FUNC bb_error_msg(const char *
>>          bb_verror_msg(s, p, NULL);
>>          va_end(p);
>>   }
>> +
>> +#if ENABLE_FEATURE_SYSLOG
>> +void FAST_FUNC bb_info_msg(const char *s, ...)
>> +{
>> +       va_list p;
>> +       smallint syslog_level_old =  syslog_level;
>> +
>> +       syslog_level = LOG_INFO;
>> +       va_start(p, s);
>> +       bb_verror_msg(s, p, NULL);
>> +       syslog_level = syslog_level_old;
>> +       va_end(p);
>> +}
>> +#endif
> 
> 
> I'm thinking about it and I think this looks good at first glance,
> but in practice has usability problems.
> 
> You can see these problems more clearly when you imagine
> yourself coding and having to decide whether a given "error" condition
> (e.g. failure to open a file) should be bb_error_msg
> or bb_info_msg?
> 
> Well, it depends on *what file it is*.
> 
> If you fail to open "/proc/cmdline", this is probably not
> something unexpected and worthy of logging to syslog.
> If modprobe encounters this condition, it can simply assume
> kernel command line had no module params.
> 
> OTOH, crond failing to open its logfile is unexpected.
> 
> How libbb function open_or_warn() supposed to decide this?
> 
> I really hate having yet another flavor of it,
> open_or_warn_loudly(). For one, *the caller of open_or_warn()*
> may not know the severity either.
> 
> Putting my admin hat on, I say that I become much happier
> when I set up my boxes to have separate logs for separate
> services/daemons. No mixing of unrelated messages.
> No "one daemon spammed the log overnight with gazillions of messages,
> rotating everybody else's logs into oblivion".
> 
> Maybe centralized syslog is not the best design?
> 
> The downside is that there is no one central log to look for
> "serious problems", you need to chase down "which one of my
> services spews errors to its log?". This was never a big problem
> for me, but maybe it is for someone else, on bigger systems?
> 
> I imagine this may be solved by adding a "send this to syslog"
> pattern(s) on a per-service basis.
> 
> E.g. log every service separately, but if admin wants to see
> ntpd time steps in syslog as well, as indication
> of something going seriously wrong, the pattern would be "setting time to":
> 
> 2016-09-26_21:02:57.79012 ntpd: reply from 83.167.252.118: delay
> 0.491095 is too high, ignoring
> 2016-09-26_21:03:01.02105 ntpd: current time is 2016-09-26 23:02:59.805699
> 2016-09-26_21:03:01.02113 ntpd: setting time to 2016-09-26
> 23:03:01.020781 (offset +1.215082s)
> 2016-09-26_21:03:01.02255 ntpd: update from:92.62.233.2
> offset:+0.000000 delay:0.996227 jitter:0.487573 clock drift:-4.413ppm
> tc:4
> 
Hi,
I see your point, forget about this bb_info_msg stuff.
The same result can still be achieved by using:

syslog_level = LOG_INFO
bb_error_msg(...)
syslog_level = LOG_ERR

if needed (and it doesn't seem to be needed that much until now).
Ciao,
Tito
_______________________________________________
busybox mailing list
busybox@busybox.net
http://lists.busybox.net/mailman/listinfo/busybox
[prev in list] [next in list] [prev in thread] [next in thread] 