add bb_info_msg was Re: Applets send errors to syslog during normal, successful operation
Deweloper
deweloper at wp.pl
Mon Mar 5 22:11:47 UTC 2018
On Sun, 4 Mar 2018 22:12:21 +0100
Tito <farmatito at tiscali.it> wrote:
> On 04/03/2018 20:05, Denys Vlasenko wrote:
> > On Wed, Feb 28, 2018 at 2:03 PM, Tito <farmatito at 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 at 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
If I interpret bloatcheck results properly, the above costs extra
45 B of code per call @x86-64.
> (and it doesn't seem to be needed that much until now).
In fact it is needed in many places, at least if you expect messages
with meaningful severity after turning on FEATURE_SYSLOG.
$ make bloatcheck
function old new delta
bb_vmsg - 515 +515
bb_info_msg - 150 +150
bb_vinfo_msg - 19 +19
static.log7 158 164 +6
log8 156 159 +3
log5 156 159 +3
syslog_level 1 - -1
crondlog 45 - -45
bb_verror_msg 519 19 -500
------------------------------------------------------------------------------
(add/remove: 3/2 grow/shrink: 3/1 up/down: 696/-546) Total: 150 bytes
text data bss dec hex filename
942213 5612 3104 950929 e8291 busybox_old
942364 5611 3104 951079 e8327 busybox_unstripped
--
diff --git a/include/libbb.h b/include/libbb.h
index f1ab1ca6f..f00cc8ffc 100644
--- a/include/libbb.h
+++ b/include/libbb.h
@@ -1273,7 +1273,6 @@ enum {
LOGMODE_BOTH = LOGMODE_SYSLOG + LOGMODE_STDIO,
};
extern const char *msg_eol;
-extern smallint syslog_level;
extern smallint logmode;
extern uint8_t xfunc_error_retval;
extern void (*die_func)(void);
@@ -1291,6 +1290,13 @@ extern void bb_perror_nomsg_and_die(void) NORETURN FAST_FUNC;
extern void bb_perror_nomsg(void) FAST_FUNC;
extern void bb_verror_msg(const char *s, va_list p, const char *strerr) FAST_FUNC;
extern void bb_logenv_override(void) FAST_FUNC;
+#if ENABLE_FEATURE_SYSLOG
+extern void bb_info_msg(const char *s, ...) __attribute__ ((format (printf, 1, 2))) FAST_FUNC;
+extern void bb_vinfo_msg(const char *s, va_list p, const char *strerr) FAST_FUNC;
+#else
+#define bb_info_msg bb_error_msg
+#define bb_vinfo_msg bb_verror_msg
+#endif
/* We need to export XXX_main from libbusybox
* only if we build "individual" binaries
diff --git a/libbb/verror_msg.c b/libbb/verror_msg.c
index 22c30357b..da0dbc8cd 100644
--- a/libbb/verror_msg.c
+++ b/libbb/verror_msg.c
@@ -11,13 +11,10 @@
# include <syslog.h>
#endif
-#if ENABLE_FEATURE_SYSLOG
-smallint syslog_level = LOG_ERR;
-#endif
smallint logmode = LOGMODE_STDIO;
const char *msg_eol = "\n";
-void FAST_FUNC bb_verror_msg(const char *s, va_list p, const char* strerr)
+static void bb_vmsg(int syslog_level, const char *s, va_list p, const char* strerr)
{
char *msg, *msg1;
char stack_msg[80];
@@ -103,7 +100,7 @@ void FAST_FUNC bb_verror_msg(const char *s, va_list p, const char* strerr)
#ifdef VERSION_WITH_WRITEV
/* Code size is approximately the same, but currently it's the only user
* of writev in entire bbox. __libc_writev in uclibc is ~50 bytes. */
-void FAST_FUNC bb_verror_msg(const char *s, va_list p, const char* strerr)
+static void bb_msg(int syslog_level, const char *s, va_list p, const char* strerr)
{
int strerr_len, msgeol_len;
struct iovec iov[3];
@@ -154,13 +151,18 @@ void FAST_FUNC bb_verror_msg(const char *s, va_list p, const char* strerr)
}
# if ENABLE_FEATURE_SYSLOG
if (logmode & LOGMODE_SYSLOG) {
- syslog(LOG_ERR, "%s", msgc);
+ syslog(syslog_level, "%s", msgc);
}
# endif
free(msgc);
}
+
#endif
+void FAST_FUNC bb_verror_msg(const char *s, va_list p, const char* strerr)
+{
+ bb_vmsg(LOG_ERR, s, p, strerr);
+}
void FAST_FUNC bb_error_msg_and_die(const char *s, ...)
{
@@ -180,3 +182,21 @@ void FAST_FUNC bb_error_msg(const char *s, ...)
bb_verror_msg(s, p, NULL);
va_end(p);
}
+
+#if ENABLE_FEATURE_SYSLOG
+
+void FAST_FUNC bb_vinfo_msg(const char *s, va_list p, const char* strerr)
+{
+ bb_vmsg(LOG_INFO, s, p, strerr);
+}
+
+void FAST_FUNC bb_info_msg(const char *s, ...)
+{
+ va_list p;
+
+ va_start(p, s);
+ bb_vinfo_msg(s, p, NULL);
+ va_end(p);
+}
+
+#endif
diff --git a/miscutils/crond.c b/miscutils/crond.c
index f6580a9d4..72762a236 100644
--- a/miscutils/crond.c
+++ b/miscutils/crond.c
@@ -181,9 +181,7 @@ static void crondlog(unsigned level, const char *msg, va_list va)
* need not touch syslog_level
* (they are ok with LOG_ERR default).
*/
- syslog_level = LOG_INFO;
- bb_verror_msg(msg, va, /* strerr: */ NULL);
- syslog_level = LOG_ERR;
+ bb_vinfo_msg(msg, va, /* strerr: */ NULL);
}
}
diff --git a/networking/ifplugd.c b/networking/ifplugd.c
index 9bc1a075f..9b7f578a2 100644
--- a/networking/ifplugd.c
+++ b/networking/ifplugd.c
@@ -326,7 +326,7 @@ static int run_script(const char *action)
char *argv[5];
int r;
- bb_error_msg("executing '%s %s %s'", G.script_name, G.iface, action);
+ bb_info_msg("executing '%s %s %s'", G.script_name, G.iface, action);
argv[0] = (char*) G.script_name;
argv[1] = (char*) G.iface;
@@ -345,7 +345,7 @@ static int run_script(const char *action)
bb_unsetenv_and_free(env_PREVIOUS);
bb_unsetenv_and_free(env_CURRENT);
- bb_error_msg("exit code: %d", r & 0xff);
+ bb_info_msg("exit code: %d", r & 0xff);
return (option_mask32 & FLAG_IGNORE_RETVAL) ? 0 : r;
}
@@ -365,7 +365,7 @@ static void up_iface(void)
if (!(ifrequest.ifr_flags & IFF_UP)) {
ifrequest.ifr_flags |= IFF_UP;
/* Let user know we mess up with interface */
- bb_error_msg("upping interface");
+ bb_info_msg("upping interface");
if (network_ioctl(SIOCSIFFLAGS, &ifrequest, "setting interface flags") < 0) {
if (errno != ENODEV)
xfunc_die();
@@ -414,7 +414,7 @@ static void maybe_up_new_iface(void)
(uint8_t)(ifrequest.ifr_hwaddr.sa_data[5]));
}
- bb_error_msg("using interface %s%s with driver<%s> (version: %s)",
+ bb_info_msg("using interface %s%s with driver<%s> (version: %s)",
G.iface, buf, driver_info.driver, driver_info.version);
}
#endif
@@ -447,7 +447,7 @@ static smallint detect_link(void)
logmode = sv_logmode;
if (status != IFSTATUS_ERR) {
G.api_method_num = i;
- bb_error_msg("using %s detection mode", method_table[i].name);
+ bb_info_msg("using %s detection mode", method_table[i].name);
break;
}
}
@@ -632,7 +632,7 @@ int ifplugd_main(int argc UNUSED_PARAM, char **argv)
/* | (1 << SIGCHLD) - run_script does not use it anymore */
, record_signo);
- bb_error_msg("started: %s", bb_banner);
+ bb_info_msg("started: %s", bb_banner);
if (opts & FLAG_MONITOR) {
struct ifreq ifrequest;
@@ -649,7 +649,7 @@ int ifplugd_main(int argc UNUSED_PARAM, char **argv)
iface_status_str = strstatus(iface_status);
if (opts & FLAG_MONITOR) {
- bb_error_msg("interface %s",
+ bb_info_msg("interface %s",
G.iface_exists ? "exists"
: "doesn't exist, waiting");
}
@@ -657,7 +657,7 @@ int ifplugd_main(int argc UNUSED_PARAM, char **argv)
* by potentially lying that it really exists */
if (G.iface_exists) {
- bb_error_msg("link is %s", iface_status_str);
+ bb_info_msg("link is %s", iface_status_str);
}
if ((!(opts & FLAG_NO_STARTUP)
@@ -710,7 +710,7 @@ int ifplugd_main(int argc UNUSED_PARAM, char **argv)
if (G.iface_exists < 0) /* error */
goto exiting;
if (iface_exists_old != G.iface_exists) {
- bb_error_msg("interface %sappeared",
+ bb_info_msg("interface %sappeared",
G.iface_exists ? "" : "dis");
if (G.iface_exists)
maybe_up_new_iface();
@@ -728,7 +728,7 @@ int ifplugd_main(int argc UNUSED_PARAM, char **argv)
iface_status_str = strstatus(iface_status);
if (iface_status_old != iface_status) {
- bb_error_msg("link is %s", iface_status_str);
+ bb_info_msg("link is %s", iface_status_str);
if (delay_time) {
/* link restored its old status before
diff --git a/networking/ntpd.c b/networking/ntpd.c
index 17e5c7da6..772d35104 100644
--- a/networking/ntpd.c
+++ b/networking/ntpd.c
@@ -1033,7 +1033,7 @@ step_time(double offset)
}
tval = tvn.tv_sec;
strftime_YYYYMMDDHHMMSS(buf, sizeof(buf), &tval);
- bb_error_msg("setting time to %s.%06u (offset %+fs)", buf, (unsigned)tvn.tv_usec, offset);
+ bb_info_msg("setting time to %s.%06u (offset %+fs)", buf, (unsigned)tvn.tv_usec, offset);
/* Correct various fields which contain time-relative values: */
@@ -1958,7 +1958,7 @@ recv_and_process_peer_pkt(peer_t *p)
p->reachable_bits |= 1;
if ((MAX_VERBOSE && G.verbose) || (option_mask32 & OPT_w)) {
- bb_error_msg("reply from %s: offset:%+f delay:%f status:0x%02x strat:%d refid:0x%08x rootdelay:%f reach:0x%02x",
+ bb_info_msg("reply from %s: offset:%+f delay:%f status:0x%02x strat:%d refid:0x%08x rootdelay:%f reach:0x%02x",
p->p_dotted,
offset,
p->lastpkt_delay,
diff --git a/networking/udhcp/dhcpc.c b/networking/udhcp/dhcpc.c
index 35694fbe3..2786dc04b 100644
--- a/networking/udhcp/dhcpc.c
+++ b/networking/udhcp/dhcpc.c
@@ -728,7 +728,7 @@ static NOINLINE int send_discover(uint32_t xid, uint32_t requested)
*/
add_client_options(&packet);
- bb_error_msg("sending %s", "discover");
+ bb_info_msg("sending %s", "discover");
return raw_bcast_from_client_config_ifindex(&packet, INADDR_ANY);
}
@@ -772,7 +772,7 @@ static NOINLINE int send_select(uint32_t xid, uint32_t server, uint32_t requeste
add_client_options(&packet);
temp_addr.s_addr = requested;
- bb_error_msg("sending select for %s", inet_ntoa(temp_addr));
+ bb_info_msg("sending select for %s", inet_ntoa(temp_addr));
return raw_bcast_from_client_config_ifindex(&packet, INADDR_ANY);
}
@@ -813,7 +813,7 @@ static NOINLINE int send_renew(uint32_t xid, uint32_t server, uint32_t ciaddr)
add_client_options(&packet);
temp_addr.s_addr = server;
- bb_error_msg("sending renew to %s", inet_ntoa(temp_addr));
+ bb_info_msg("sending renew to %s", inet_ntoa(temp_addr));
return bcast_or_ucast(&packet, ciaddr, server);
}
@@ -842,7 +842,7 @@ static NOINLINE int send_decline(/*uint32_t xid,*/ uint32_t server, uint32_t req
udhcp_add_simple_option(&packet, DHCP_SERVER_ID, server);
- bb_error_msg("sending %s", "decline");
+ bb_info_msg("sending %s", "decline");
return raw_bcast_from_client_config_ifindex(&packet, INADDR_ANY);
}
#endif
@@ -862,7 +862,7 @@ static int send_release(uint32_t server, uint32_t ciaddr)
udhcp_add_simple_option(&packet, DHCP_SERVER_ID, server);
- bb_error_msg("sending %s", "release");
+ bb_info_msg("sending %s", "release");
/* Note: normally we unicast here since "server" is not zero.
* However, there _are_ people who run "address-less" DHCP servers,
* and reportedly ISC dhcp client and Windows allow that.
@@ -1113,7 +1113,7 @@ static void change_listen_mode(int new_mode)
/* Called only on SIGUSR1 */
static void perform_renew(void)
{
- bb_error_msg("performing DHCP renew");
+ bb_info_msg("performing DHCP renew");
switch (state) {
case BOUND:
change_listen_mode(LISTEN_KERNEL);
@@ -1147,11 +1147,11 @@ static void perform_release(uint32_t server_addr, uint32_t requested_ip)
temp_addr.s_addr = server_addr;
strcpy(buffer, inet_ntoa(temp_addr));
temp_addr.s_addr = requested_ip;
- bb_error_msg("unicasting a release of %s to %s",
+ bb_info_msg("unicasting a release of %s to %s",
inet_ntoa(temp_addr), buffer);
send_release(server_addr, requested_ip); /* unicast */
}
- bb_error_msg("entering released state");
+ bb_info_msg("entering released state");
/*
* We can be here on: SIGUSR2,
* or on exit (SIGTERM) and -R "release on quit" is specified.
@@ -1389,7 +1389,7 @@ int udhcpc_main(int argc UNUSED_PARAM, char **argv)
/* Create pidfile */
write_pidfile(client_config.pidfile);
/* Goes to stdout (unless NOMMU) and possibly syslog */
- bb_error_msg("started, v"BB_VER);
+ bb_info_msg("started, v"BB_VER);
/* Set up the signal pipe */
udhcp_sp_setup();
/* We want random_xid to be random... */
@@ -1610,7 +1610,7 @@ int udhcpc_main(int argc UNUSED_PARAM, char **argv)
timeout = INT_MAX;
continue;
case SIGTERM:
- bb_error_msg("received %s", "SIGTERM");
+ bb_info_msg("received %s", "SIGTERM");
goto ret0;
}
@@ -1772,7 +1772,7 @@ int udhcpc_main(int argc UNUSED_PARAM, char **argv)
#endif
/* enter bound state */
temp_addr.s_addr = packet.yiaddr;
- bb_error_msg("lease of %s obtained, lease time %u",
+ bb_info_msg("lease of %s obtained, lease time %u",
inet_ntoa(temp_addr), (unsigned)lease_seconds);
requested_ip = packet.yiaddr;
diff --git a/networking/zcip.c b/networking/zcip.c
index 94e49adcb..7ca7eb740 100644
--- a/networking/zcip.c
+++ b/networking/zcip.c
@@ -195,7 +195,7 @@ static int run(char *argv[3], const char *param, uint32_t nip)
putenv(env_ip);
fmt -= 3;
}
- bb_error_msg(fmt, argv[2], argv[0], addr);
+ bb_info_msg(fmt, argv[2], argv[0], addr);
status = spawn_and_wait(argv + 1);
if (nip != 0)
bb_unsetenv_and_free(env_ip);
@@ -339,7 +339,7 @@ int zcip_main(int argc UNUSED_PARAM, char **argv)
#if BB_MMU
bb_daemonize(0 /*was: DAEMON_CHDIR_ROOT*/);
#endif
- bb_error_msg("start, interface %s", argv_intf);
+ bb_info_msg("start, interface %s", argv_intf);
}
// Run the dynamic address negotiation protocol,
More information about the busybox
mailing list