Merge pull request #140 from garlick/issue#139

reduce log noise

src/libcommon/error.c

@@ -24,7 +24,6 @@
 #include "error.h"
 
 static char *err_prog = NULL; /* basename of calling program */
-static bool err_ttyvalid = true; /* use stderr until told otherwise */
 
 #define ERROR_BUFLEN 1024
 
@@ -38,14 +37,6 @@ void err_init(char *prog)
  err_prog = p ? p + 1 : prog;
 }
 
-/*
- * Accessor function for syslog_enable.
- */
-void err_notty(void)
-{
- err_ttyvalid = false;
-}
-
 /* helper for err, err_exit */
 static void _verr(bool errno_valid, const char *fmt, va_list ap)
 {
@@ -55,17 +46,10 @@ static void _verr(bool errno_valid, const char *fmt, va_list ap)
  assert(err_prog != NULL);
 
  vsnprintf(buf, ERROR_BUFLEN, fmt, ap); /* overflow ignored on purpose */
- if (errno_valid) {
- if (err_ttyvalid)
- fprintf(stderr, "%s: %s: %s\n", err_prog, buf, strerror(er));
- else
- syslog(LOG_ERR, "%s: %s", buf, strerror(er));
- } else {
- if (err_ttyvalid)
- fprintf(stderr, "%s: %s\n", err_prog, buf);
- else
- syslog(LOG_ERR, "%s", buf);
- }
+ if (errno_valid)
+ fprintf(stderr, "%s: %s: %s\n", err_prog, buf, strerror(er));
+ else
+ fprintf(stderr, "%s: %s\n", err_prog, buf);
 }
 
 /*

src/libcommon/error.h

@@ -15,7 +15,6 @@
 #include <stdarg.h>
 
 void err_init(char *prog);
-void err_notty(void);
 void err_exit(bool errno_valid, const char *fmt, ...)
  __attribute__ ((format (printf, 2, 3)));
 void err(bool errno_valid, const char *fmt, ...)

src/powerman/client.c

@@ -640,28 +640,37 @@ static void _telemetry_printf(int client_id, const char *fmt, ...)
  }
 }
 
+/* See chaos/powerman#138.
+ * We don't want these messages syslogged when we run the test suite,
+ * so send them to stderr and when powerman is run as a system service,
+ * systemd redirects stderr to the journal which also usually goes to syslog.
+ */
 static void log_state_change(Client *c)
 {
- char *action = NULL;
- char *hosts;
- char *with_errors = " with errors";
  int level = conf_get_plug_log_level();
+ const char *action;
+ char *hosts;
 
- if (c->cmd->com == PM_POWER_ON)
- action = "powered on";
- if (c->cmd->com == PM_POWER_OFF)
- action = "powered off";
- if (c->cmd->com == PM_POWER_CYCLE)
- action = "power cycled";
- if (c->cmd->com == PM_RESET)
- action = "reset";
-
- if (!action)
- return;
-
+ switch (c->cmd->com) {
+ case PM_POWER_ON:
+ action = "powered on";
+ break;
+ case PM_POWER_OFF:
+ action = "powered off";
+ break;
+ case PM_POWER_CYCLE:
+ action = "power cycled";
+ break;
+ case PM_RESET:
+ action = "reset";
+ break;
+ default:
+ return;
+ }
  hosts = _xhostlist_ranged_string(c->cmd->hl);
- syslog(level, "%s %s%s", action, hosts,
- (c->cmd->error == true ? with_errors : ""));
+ // N.B. systemd journal groks <level> prefix
+ fprintf(stderr, "<%d>%s %s%s\n", level, action, hosts,
+ (c->cmd->error == true ? " with errors" : ""));
  xfree(hosts);
 }
 
@@ -998,7 +1007,7 @@ static void _handle_read(Client * c)
  }
  if (n == 0) {
  c->client_quit = true;
- err(false, "client read returned EOF");
+ dbg(DBG_CLIENT, "client read returned EOF");
  return;
  }
  if (dropped != 0)
@@ -1093,8 +1102,6 @@ void cli_post_poll(xpollfd_t pfd)
 
  if (flags & XPOLLERR)
  err(false, "client poll: error");
- if (flags & XPOLLHUP)
- err(false, "client poll: hangup");
  if (flags & XPOLLNVAL)
  err(false, "client poll: fd not open");
  if (flags & (XPOLLERR | XPOLLNVAL))

src/powerman/debug.c

@@ -28,12 +28,6 @@
 #define DBG_BUFLEN 1024
 
 static unsigned long dbg_channel_mask = 0;
-static bool dbg_ttyvalid = true;
-
-void dbg_notty(void)
-{
- dbg_ttyvalid = false;
-}
 
 void dbg_setmask(unsigned long mask)
 {
@@ -81,12 +75,8 @@ void dbg_wrapped(unsigned long channel, const char *fmt, ...)
  vsnprintf(buf, DBG_BUFLEN, fmt, ap); /* overflow ignored on purpose */
  va_end(ap);
 
- if (dbg_ttyvalid)
- fprintf(stderr, "%s %s: %s\n",
- _time(), _channel_name(channel), buf);
- else
- syslog(LOG_DEBUG, "%s: %s",
- _channel_name(channel), buf);
+ fprintf(stderr, "%s %s: %s\n",
+ _time(), _channel_name(channel), buf);
  }
 }
 

src/powerman/debug.h

@@ -31,7 +31,6 @@
  { 0, NULL } \
 }
 
-void dbg_notty(void);
 void dbg_setmask(unsigned long mask);
 void dbg_wrapped(unsigned long channel, const char *fmt, ...)
  __attribute__ ((format (printf, 2, 3)));

src/powerman/device_pipe.c

@@ -92,9 +92,12 @@ bool pipe_connect(Device * dev)
  (void)dup2(fd[1], STDIN_FILENO);
  (void)dup2(fd[1], STDOUT_FILENO);
  (void)close(fd[1]);
+ (void)close(fd[0]);
  execv(pd->argv[0], pd->argv);
  err_exit(true, "exec %s", pd->argv[0]);
  } else { /* parent */
+ (void)close(fd[1]);
+
  nonblock_set(fd[0]);
 
  dev->fd = fd[0];
@@ -104,7 +107,7 @@ bool pipe_connect(Device * dev)
 
  pd->cpid = pid;
 
- err(false, "_pipe_connect(%s): opened", dev->name);
+ dbg(DBG_DEVICE, "_pipe_connect(%s): opened", dev->name);
  }
 
  return (dev->connect_state == DEV_CONNECTED);
@@ -135,11 +138,19 @@ void pipe_disconnect(Device * dev)
  if (waitpid(pd->cpid, &wstat, 0) < 0)
  err(true, "_pipe_disconnect(%s): wait", dev->name);
  if (WIFEXITED(wstat)) {
- err(false, "_pipe_disconnect(%s): %s exited with status %d",
- dev->name, pd->argv[0], WEXITSTATUS(wstat));
+ if (WEXITSTATUS(wstat) == 0)
+ dbg(DBG_DEVICE, "_pipe_disconnect(%s): %s exited with status 0",
+ dev->name, pd->argv[0]);
+ else
+ err(false, "_pipe_disconnect(%s): %s exited with status %d",
+ dev->name, pd->argv[0], WEXITSTATUS(wstat));
  } else if (WIFSIGNALED(wstat)) {
- err(false, "_pipe_disconnect(%s): %s terminated with signal %d",
- dev->name, pd->argv[0], WTERMSIG(wstat));
+ if (WTERMSIG(wstat) == SIGTERM)
+ dbg(DBG_DEVICE, "_pipe_disconnect(%s): %s terminated",
+ dev->name, pd->argv[0]);
+ else
+ err(false, "_pipe_disconnect(%s): %s terminated with signal %d",
+ dev->name, pd->argv[0], WTERMSIG(wstat));
  } else {
  err(false, "_pipe_disconnect(%s): %s terminated",
  dev->name, pd->argv[0]);

src/powerman/device_serial.c

@@ -227,7 +227,7 @@ bool serial_connect(Device * dev)
  dev->connect_state = DEV_CONNECTED;
  dev->stat_successful_connects++;
 
- err(false, "_serial_connect(%s): opened", dev->name);
+ dbg(DBG_DEVICE, "_serial_connect(%s): opened", dev->name);
  return true;
 
 out:
@@ -255,7 +255,7 @@ void serial_disconnect(Device * dev)
  dev->fd = NO_FD;
  }
 
- err(false, "_serial_disconnect(%s): closed", dev->name);
+ dbg(DBG_DEVICE, "_serial_disconnect(%s): closed", dev->name);
 }
 
 /*

src/powerman/device_tcp.c

@@ -206,12 +206,10 @@ bool tcp_finish_connect(Device * dev)
  err(false, "tcp_finish_connect(%s): connection refused", dev->name);
  break;
  case DEV_CONNECTED:
- if (!tcp->quiet)
- err(false, "tcp_finish_connect(%s): connected", dev->name);
+ dbg(DBG_DEVICE, "tcp_finish_connect(%s): connected", dev->name);
  break;
  case DEV_CONNECTING:
- if (!tcp->quiet)
- err(false, "tcp_finish_connect(%s): connecting", dev->name);
+ dbg(DBG_DEVICE, "tcp_finish_connect(%s): connecting", dev->name);
  break;
  }
  return (dev->connect_state != DEV_NOT_CONNECTED);
@@ -242,12 +240,10 @@ bool tcp_connect(Device * dev)
  err(false, "tcp_connect(%s): connection refused", dev->name);
  break;
  case DEV_CONNECTED:
- if (!tcp->quiet)
- err(false, "tcp_connect(%s): connected", dev->name);
+ dbg(DBG_DEVICE, "tcp_connect(%s): connected", dev->name);
  break;
  case DEV_CONNECTING:
- if (!tcp->quiet)
- err(false, "tcp_connect(%s): connecting", dev->name);
+ dbg(DBG_DEVICE, "tcp_connect(%s): connecting", dev->name);
  break;
  }
 
@@ -259,11 +255,8 @@ bool tcp_connect(Device * dev)
  */
 void tcp_disconnect(Device * dev)
 {
- TcpDev *tcp;
-
  assert(dev->connect_state == DEV_CONNECTING
  || dev->connect_state == DEV_CONNECTED);
- tcp = (TcpDev *)dev->data;
 
  dbg(DBG_DEVICE, "tcp_disconnect: %s on fd %d", dev->name, dev->fd);
 
@@ -274,8 +267,7 @@ void tcp_disconnect(Device * dev)
  dev->fd = NO_FD;
  }
 
- if (!tcp->quiet)
- err(false, "tcp_disconnect(%s): disconnected", dev->name);
+ dbg(DBG_DEVICE, "tcp_disconnect(%s): disconnected", dev->name);
 }
 
 void tcp_preprocess(Device *dev)