Add logging tests, add "log" command

Refactor log.c ready for log file rotation

commandline.c

@@ -34,6 +34,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
 #ifdef HAVE_JNI_H
 #include <jni.h>
 #endif
+#include <assert.h>
 #include "serval.h"
 #include "conf.h"
 #include "rhizome.h"
@@ -497,6 +498,20 @@ int app_echo(const struct cli_parsed *parsed, void *context)
   return 0;
 }
 
+int app_log(const struct cli_parsed *parsed, void *context)
+{
+  if (config.debug.verbose)
+    DEBUG_cli_parsed(parsed);
+  assert(parsed->argc == 3);
+  const char *lvl = parsed->args[1];
+  const char *msg = parsed->args[2];
+  int level = string_to_log_level(lvl);
+  if (level == LOG_LEVEL_INVALID)
+    return WHYF("invalid log level: %s", lvl);
+  logMessage(level, __NOWHERE__, "%s", msg);
+  return 0;
+}
+
 void lookup_send_request(const sid_t *srcsid, int srcport, const sid_t *dstsid, const char *did)
 {
   int i;
@@ -2355,12 +2370,18 @@ int app_network_scan(const struct cli_parsed *parsed, void *context)
 */
 #define KEYRING_PIN_OPTIONS ,"[--keyring-pin=<pin>]","[--entry-pin=<pin>]..."
 struct cli_schema command_line_options[]={
-  {app_dna_lookup,{"dna","lookup","<did>","[<timeout>]",NULL},0,
-   "Lookup the SIP/MDP address of the supplied telephone number (DID)."},
   {commandline_usage,{"help","...",NULL},CLIFLAG_PERMISSIVE_CONFIG,
    "Display command usage."},
-  {app_echo,{"echo","[-e]","[--]","...",NULL},CLIFLAG_STANDALONE,
+  {app_echo,{"echo","[-e]","[--]","...",NULL},CLIFLAG_PERMISSIVE_CONFIG,
    "Output the supplied string."},
+  {app_log,{"log","debug","<message>",NULL},CLIFLAG_PERMISSIVE_CONFIG,
+   "Log the supplied message at DEBUG level."},
+  {app_log,{"log","info","<message>",NULL},CLIFLAG_PERMISSIVE_CONFIG,
+   "Log the supplied message at INFO level."},
+  {app_log,{"log","warn","<message>",NULL},CLIFLAG_PERMISSIVE_CONFIG,
+   "Log the supplied message at WARN level."},
+  {app_log,{"log","error","<message>",NULL},CLIFLAG_PERMISSIVE_CONFIG,
+   "Log the supplied message at ERROR level."},
   {app_server_start,{"start",NULL},CLIFLAG_STANDALONE,
    "Start Serval Mesh node process with instance path taken from SERVALINSTANCE_PATH environment variable."},
   {app_server_start,{"start","in","<instance path>",NULL},CLIFLAG_STANDALONE,
@@ -2462,8 +2483,10 @@ struct cli_schema command_line_options[]={
    "Return routing information about a SID"},
   {app_count_peers,{"peer","count",NULL},0,
     "Return a count of routable peers on the network"},
+  {app_dna_lookup,{"dna","lookup","<did>","[<timeout>]",NULL},0,
+   "Lookup the subscribers (SID) with the supplied telephone number (DID)."},
   {app_reverse_lookup, {"reverse", "lookup", "<sid>", "[<timeout>]", NULL}, 0,
-    "Lookup the phone number and name of a given subscriber"},
+    "Lookup the phone number (DID) and name of a given subscriber (SID)"},
   {app_monitor_cli,{"monitor",NULL},0,
    "Interactive servald monitor interface."},
   {app_crypt_test,{"test","crypt",NULL},0,

conf_schema.c

@@ -935,44 +935,16 @@ int cf_cmp_interface_list(const struct config_interface_list *a, const struct co
 
 int cf_opt_log_level(int *levelp, const char *text)
 {
-  if (strcmp(text, "none") == 0) {
+  int level = string_to_log_level(text);
-    *levelp = LOG_LEVEL_NONE;
+  if (level == LOG_LEVEL_INVALID)
-    return CFOK;
+    return CFINVALID;
-  }
+  *levelp = level;
-  if (strcmp(text, "fatal") == 0) {
+  return CFOK;
-    *levelp = LOG_LEVEL_FATAL;
-    return CFOK;
-  }
-  if (strcmp(text, "error") == 0) {
-    *levelp = LOG_LEVEL_ERROR;
-    return CFOK;
-  }
-  if (strcmp(text, "warn") == 0) {
-    *levelp = LOG_LEVEL_WARN;
-    return CFOK;
-  }
-  if (strcmp(text, "info") == 0) {
-    *levelp = LOG_LEVEL_INFO;
-    return CFOK;
-  }
-  if (strcmp(text, "debug") == 0) {
-    *levelp = LOG_LEVEL_DEBUG;
-    return CFOK;
-  }
-  return CFINVALID;
 }
 
 int cf_fmt_log_level(const char **textp, const int *levelp)
 {
-  const char *t = NULL;
+  const char *t = log_level_as_string(*levelp);
-  switch (*levelp) {
-    case LOG_LEVEL_NONE:   t = "none"; break;
-    case LOG_LEVEL_FATAL:  t = "fatal"; break;
-    case LOG_LEVEL_ERROR:  t = "error"; break;
-    case LOG_LEVEL_WARN:   t = "warn"; break;
-    case LOG_LEVEL_INFO:   t = "info"; break;
-    case LOG_LEVEL_DEBUG:  t = "debug"; break;
-  }
   if (!t)
     return CFINVALID;
   *textp = str_edup(t);

log.c

@@ -46,114 +46,8 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
 int serverMode = 0;
 const struct __sourceloc __whence = __NOWHERE__;
 
-static FILE *logfile_file = NULL;
-static FILE *logfile_stderr = NULL;
 #define NO_FILE ((FILE *)1)
 
-/* The file logbuf is used to accumulate log messages before the log file is open and ready for
- * writing.
- */
-static char _log_buf[8192];
-static struct strbuf logbuf = STRUCT_STRBUF_EMPTY;
-
-#ifdef ANDROID
-
-#include <android/log.h>
-
-/* The Android logbuf is used to accumulate a single log line before printing to Android's
- * logging API.
- */
-static char _log_buf_android[1024];
-static struct strbuf logbuf_android;
-
-#endif // ANDROID
-
-static void _open_log_file()
-{
-  if (!logfile_file) {
-    const char *logpath = getenv("SERVALD_LOG_FILE");
-    if (!logpath) {
-      if (cf_limbo)
-	return;
-      logpath = config.log.file_path;
-    }
-    if (!logpath || !logpath[0]) {
-      logfile_file = NO_FILE;
-      if (serverMode)
-	logMessage(LOG_LEVEL_INFO, __NOWHERE__, "No logfile_file configured");
-    } else {
-      char path[1024];
-      if (!FORM_SERVAL_INSTANCE_PATH(path, logpath)) {
-	logfile_file = NO_FILE;
-	logMessage(LOG_LEVEL_WARN, __NOWHERE__, "Logfile path overrun");
-      } else if ((logfile_file = fopen(path, "a"))) {
-	setlinebuf(logfile_file);
-	if (serverMode)
-	  logMessage(LOG_LEVEL_INFO, __NOWHERE__, "Logging to %s (fd %d)", path, fileno(logfile_file));
-      } else {
-	logfile_file = NO_FILE;
-	WARNF_perror("fopen(%s)", path);
-	logMessage(LOG_LEVEL_WARN, __NOWHERE__, "Cannot append to %s", path);
-      }
-    }
-  }
-}
-
-static void _flush_log_file()
-{
-  if (logfile_file && logfile_file != NO_FILE) {
-    fprintf(logfile_file, "%s%s%s",
-	strbuf_len(&logbuf) ? strbuf_str(&logbuf) : "",
-	strbuf_len(&logbuf) ? "\n" : "",
-	strbuf_overrun(&logbuf) ? "LOG OVERRUN\n" : ""
-      );
-    strbuf_reset(&logbuf);
-  }
-}
-
-void close_log_file()
-{
-  if (logfile_file && logfile_file != NO_FILE)
-    fclose(logfile_file);
-  logfile_file = NULL;
-}
-
-static void _open_log_stderr()
-{
-  if (!logfile_stderr) {
-    logfile_stderr = stderr;
-    setlinebuf(logfile_stderr);
-  }
-}
-
-static void _flush_log_stderr()
-{
-  if (logfile_stderr && logfile_stderr != NO_FILE)
-    fflush(logfile_stderr);
-}
-
-void disable_log_stderr()
-{
-  if (logfile_stderr && logfile_stderr != NO_FILE) {
-    fflush(logfile_stderr);
-    logfile_stderr = NO_FILE;
-  }
-}
-
-static const char *_trimbuildpath(const char *path)
-{
-  /* Remove common path prefix */
-  int lastsep = 0;
-  int i;
-  for (i = 0; __FILE__[i] && path[i]; ++i) {
-    if (i && path[i - 1] == '/')
-      lastsep = i;
-    if (__FILE__[i] != path[i])
-      break;
-  }
-  return &path[lastsep];
-}
-
 struct _log_state {
 
   /* This structure is initially zerofilled. */
@@ -173,11 +67,36 @@ struct _log_state {
 
 };
 
+/* Static variables for sending log output to a file.
+ *
+ * The logbuf is used to accumulate log messages before the log file is open and ready for
+ * writing.
+ */
+static FILE *logfile_file = NULL;
+static void _open_log_file();
+static void _rotate_log_file();
+static void _flush_log_file();
 struct _log_state state_file;
+static char _log_buf[8192];
+static struct strbuf logbuf = STRUCT_STRBUF_EMPTY;
+
 #ifdef ANDROID
+/* Static variables for sending log output to the Android log.
+ *
+ * The logbuf is used to accumulate a single log line before printing to Android's logging API.
+ */
+#include <android/log.h>
 struct _log_state state_android;
-#endif
+static char _log_buf_android[1024];
+static struct strbuf logbuf_android;
+#endif // ANDROID
+
+/* Static variables for sending log output to standard error.
+ */
+static FILE *logfile_stderr = NULL;
 struct _log_state state_stderr;
+static void _open_log_stderr();
+static void _flush_log_stderr();
 
 typedef struct _log_iterator {
   const struct config_log_format *config;
@@ -194,23 +113,40 @@ static void _log_iterator_start(_log_iterator *it)
   localtime_r(&it->tv.tv_sec, &it->tm);
 }
 
+static void _log_iterator_advance_to_file(_log_iterator *it)
+{
+  it->config = &config.log.file;
+  it->state = &state_file;
+}
+
+#ifdef ANDROID
+static void _log_iterator_advance_to_android(_log_iterator *it)
+{
+  it->config = &config.log.android;
+  it->state = &state_android;
+}
+#endif // ANDROID
+
+static void _log_iterator_advance_to_stderr(_log_iterator *it)
+{
+  it->config = &config.log.stderr;
+  it->state = &state_stderr;
+}
+
 static int _log_iterator_advance(_log_iterator *it)
 {
   if (it->config == NULL) {
-    it->config = &config.log.file;
+    _log_iterator_advance_to_file(it);
-    it->state = &state_file;
     return 1;
   }
   if (it->config == &config.log.file) {
 #ifdef ANDROID
-    it->config = &config.log.android;
+    _log_iterator_advance_to_android(it);
-    it->state = &state_android;
     return 1;
   }
   if (it->config == &config.log.android) {
 #endif // ANDROID
-    it->config = &config.log.stderr;
+    _log_iterator_advance_to_stderr(it);
-    it->state = &state_stderr;
     return 1;
   }
   return 0;
@@ -219,7 +155,7 @@ static int _log_iterator_advance(_log_iterator *it)
 static int _log_enabled(_log_iterator *it)
 {
   if (it->config == &config.log.file) {
-    _open_log_file(); // puts initial INFO message at start of log file
+    _open_log_file(); // puts initial INFO message(s) at head of log file
     if (logfile_file == NO_FILE)
       return 0;
   }
@@ -281,6 +217,20 @@ static void _log_prefix(_log_iterator *it, int level)
   }
 }
 
+static const char *_trimbuildpath(const char *path)
+{
+  /* Remove common path prefix */
+  int lastsep = 0;
+  int i;
+  for (i = 0; __FILE__[i] && path[i]; ++i) {
+    if (i && path[i - 1] == '/')
+      lastsep = i;
+    if (__FILE__[i] != path[i])
+      break;
+  }
+  return &path[lastsep];
+}
+
 static void _log_prefix_whence(_log_iterator *it, struct __sourceloc whence)
 {
   if (whence.file) {
@@ -342,6 +292,21 @@ static void _log_printf_nl(_log_iterator *it, int level, const char *fmt, ...)
   va_end(ap);
 }
 
+static void _log_current_datetime(_log_iterator *it, int level)
+{
+  char buf[50];
+  if (strftime(buf, sizeof buf, "%F %T %z", &it->tm)) {
+    _log_printf_nl(it, level, "Local date/time: %s", buf);
+    it->state->last_tm = it->tm;
+  }
+}
+
+static void _log_software_version(_log_iterator *it, int level)
+{
+  _log_printf_nl(it, level, "Serval DNA version: %s", version_servald);
+  it->state->version_logged = 1;
+}
+
 static int _log_current_config(_log_iterator *it, int level)
 {
   if (!cf_limbo) {
@@ -373,20 +338,12 @@ static void _log_update(_log_iterator *it)
   if ( it->tm.tm_mday != it->state->last_tm.tm_mday
     || it->tm.tm_mon != it->state->last_tm.tm_mon
     || it->tm.tm_year != it->state->last_tm.tm_year
-  ) {
+  )
-    char buf[50];
+    _log_current_datetime(it, LOG_LEVEL_INFO);
-    if (strftime(buf, sizeof buf, "%F %T %z", &it->tm)) {
+  if (!it->state->version_logged)
-      _log_printf_nl(it, LOG_LEVEL_INFO, "Local date/time: %s", buf);
+    _log_software_version(it, LOG_LEVEL_INFO);
-      it->state->last_tm = it->tm;
+  if (it->config->dump_config && !it->state->config_logged)
-    }
-  }
-  if (!it->state->version_logged) {
-    _log_printf_nl(it, LOG_LEVEL_INFO, "Serval DNA version: %s", version_servald);
-    it->state->version_logged = 1;
-  }
-  if (it->config->dump_config && !it->state->config_logged) {
     _log_current_config(it, LOG_LEVEL_INFO);
-  }
 }
 
 static int _log_iterator_next(_log_iterator *it, int level)
@@ -397,8 +354,8 @@ static int _log_iterator_next(_log_iterator *it, int level)
   _log_flush(it);
   while (_log_iterator_advance(it)) {
     if (_log_enabled(it)) {
-      _log_update(it);
       if (level >= it->config->level) {
+	_log_update(it);
 	_log_prefix(it, level);
 	return 1;
       }
@@ -408,6 +365,106 @@ static int _log_iterator_next(_log_iterator *it, int level)
   return 0;
 }
 
+static void _logs_vprintf_nl(int level, struct __sourceloc whence, const char *fmt, va_list ap)
+{
+  _log_iterator it;
+  _log_iterator_start(&it);
+  while (_log_iterator_next(&it, level)) {
+    _log_prefix_whence(&it, whence);
+    _log_vprintf_nl(&it, level, fmt, ap);
+  }
+}
+
+static void _logs_printf_nl(int level, struct __sourceloc whence, const char *fmt, ...)
+{
+  va_list ap;
+  va_start(ap, fmt);
+  _logs_vprintf_nl(level, whence, fmt, ap);
+  va_end(ap);
+}
+
+static void _open_log_file()
+{
+  if (!logfile_file) {
+    const char *logpath = getenv("SERVALD_LOG_FILE");
+    if (!logpath) {
+      if (cf_limbo)
+	return;
+      logpath = config.log.file_path;
+    }
+    if (!logpath || !logpath[0]) {
+      logfile_file = NO_FILE;
+      if (serverMode)
+	_logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "No logfile_file configured");
+    } else {
+      char path[1024];
+      if (!FORM_SERVAL_INSTANCE_PATH(path, logpath)) {
+	logfile_file = NO_FILE;
+	_logs_printf_nl(LOG_LEVEL_WARN, __NOWHERE__, "Logfile path overrun");
+      } else if ((logfile_file = fopen(path, "a"))) {
+	setlinebuf(logfile_file);
+	memset(&state_file, 0, sizeof state_file);
+	// The first line in every log file must be the starting time stamp.  (After that, it is up
+	// to _log_update() to insert other mandatory messages in any suitable order.)
+	_log_iterator it;
+	_log_iterator_start(&it);
+	_log_iterator_advance_to_file(&it);
+	_log_current_datetime(&it, LOG_LEVEL_INFO);
+	if (serverMode)
+	  _logs_printf_nl(LOG_LEVEL_INFO, __NOWHERE__, "Logging to %s (fd %d)", path, fileno(logfile_file));
+      } else {
+	logfile_file = NO_FILE;
+	_logs_printf_nl(LOG_LEVEL_WARN, __NOWHERE__, "Cannot append to %s - %s [errno=%d]", path, strerror(errno), errno);
+      }
+    }
+  }
+}
+
+static void _rotate_log_file()
+{
+}
+
+static void _flush_log_file()
+{
+  if (logfile_file && logfile_file != NO_FILE) {
+    fprintf(logfile_file, "%s%s%s",
+	strbuf_len(&logbuf) ? strbuf_str(&logbuf) : "",
+	strbuf_len(&logbuf) ? "\n" : "",
+	strbuf_overrun(&logbuf) ? "LOG OVERRUN\n" : ""
+      );
+    strbuf_reset(&logbuf);
+  }
+}
+
+void close_log_file()
+{
+  if (logfile_file && logfile_file != NO_FILE)
+    fclose(logfile_file);
+  logfile_file = NULL;
+}
+
+static void _open_log_stderr()
+{
+  if (!logfile_stderr) {
+    logfile_stderr = stderr;
+    setlinebuf(logfile_stderr);
+  }
+}
+
+static void _flush_log_stderr()
+{
+  if (logfile_stderr && logfile_stderr != NO_FILE)
+    fflush(logfile_stderr);
+}
+
+void disable_log_stderr()
+{
+  if (logfile_stderr && logfile_stderr != NO_FILE) {
+    fflush(logfile_stderr);
+    logfile_stderr = NO_FILE;
+  }
+}
+
 void logFlush()
 {
   _log_iterator it;
@@ -425,6 +482,7 @@ void logArgv(int level, struct __sourceloc whence, const char *label, int argc,
     size_t len = strbuf_count(&b);
     strbuf_init(&b, alloca(len + 1), len + 1);
     strbuf_append_argv(&b, argc, argv);
+    _rotate_log_file();
     _log_iterator it;
     _log_iterator_start(&it);
     while (_log_iterator_next(&it, level)) {
@@ -441,6 +499,7 @@ void logArgv(int level, struct __sourceloc whence, const char *label, int argc,
 void logString(int level, struct __sourceloc whence, const char *str)
 {
   if (level != LOG_LEVEL_SILENT) {
+    _rotate_log_file();
     _log_iterator it;
     const char *s = str;
     const char *p;
@@ -477,6 +536,7 @@ void logMessage(int level, struct __sourceloc whence, const char *fmt, ...)
 void vlogMessage(int level, struct __sourceloc whence, const char *fmt, va_list ap)
 {
   if (level != LOG_LEVEL_SILENT) {
+    _rotate_log_file();
     _log_iterator it;
     _log_iterator_start(&it);
     while (_log_iterator_next(&it, level)) {
@@ -488,11 +548,10 @@ void vlogMessage(int level, struct __sourceloc whence, const char *fmt, va_list
 
 void logConfigChanged()
 {
-  state_file.config_logged = 0;
+  _log_iterator it;
-#ifdef ANDROID
+  _log_iterator_start(&it);
-  state_android.config_logged = 0;
+  while (_log_iterator_advance(&it))
-#endif
+    it.state->config_logged = 0;
-  state_stderr.config_logged = 0;
   logFlush();
 }
 
@@ -537,7 +596,7 @@ ssize_t get_self_executable_path(char *buf, size_t len)
 int log_backtrace(struct __sourceloc whence)
 {
 #ifndef NO_BACKTRACE
-  _open_log_file();
+  _rotate_log_file();
   char execpath[MAXPATHLEN];
   if (get_self_executable_path(execpath, sizeof execpath) == -1)
     return WHY("cannot log backtrace: own executable path unknown");
@@ -589,7 +648,7 @@ int log_backtrace(struct __sourceloc whence)
   }
   // parent
   close(stdout_fds[1]);
-  logMessage(LOG_LEVEL_DEBUG, whence, "GDB BACKTRACE");
+  _logs_printf_nl(LOG_LEVEL_DEBUG, whence, "GDB BACKTRACE");
   char buf[1024];
   char *const bufe = buf + sizeof buf;
   char *linep = buf;
@@ -601,14 +660,14 @@ int log_backtrace(struct __sourceloc whence)
     for (; p < readp; ++p)
       if (*p == '\n' || *p == '\0') {
 	*p = '\0';
-	logMessage(LOG_LEVEL_DEBUG, __NOWHERE__, "%s", linep);
+	_logs_printf_nl(LOG_LEVEL_DEBUG, __NOWHERE__, "%s", linep);
 	linep = p + 1;
       }
     if (readp >= bufe && linep == buf) {
       // Line does not fit into buffer.
       char t = bufe[-1];
       bufe[-1] = '\0';
-      logMessage(LOG_LEVEL_DEBUG, __NOWHERE__, "%s", buf);
+      _logs_printf_nl(LOG_LEVEL_DEBUG, __NOWHERE__, "%s", buf);
       buf[0] = t;
       readp = buf + 1;
     } else if (readp + 120 >= bufe && linep != buf) {
@@ -624,7 +683,7 @@ int log_backtrace(struct __sourceloc whence)
     WHY_perror("read");
   if (readp > linep) {
     *readp = '\0';
-    logMessage(LOG_LEVEL_DEBUG, __NOWHERE__, "%s", linep);
+    _logs_printf_nl(LOG_LEVEL_DEBUG, __NOWHERE__, "%s", linep);
   }
   close(stdout_fds[0]);
   int status = 0;
@@ -632,8 +691,34 @@ int log_backtrace(struct __sourceloc whence)
     WHY_perror("waitpid");
   strbuf b = strbuf_local(buf, sizeof buf);
   strbuf_append_exit_status(b, status);
-  logMessage(LOG_LEVEL_DEBUG, __NOWHERE__, "gdb %s", buf);
+  _logs_printf_nl(LOG_LEVEL_DEBUG, __NOWHERE__, "gdb %s", buf);
   unlink(tempfile);
 #endif
   return 0;
 }
+
+const char *log_level_as_string(int level)
+{
+  switch (level) {
+    case LOG_LEVEL_SILENT: return "silent";
+    case LOG_LEVEL_DEBUG:  return "debug";
+    case LOG_LEVEL_INFO:   return "info";
+    case LOG_LEVEL_WARN:   return "warn";
+    case LOG_LEVEL_ERROR:  return "error";
+    case LOG_LEVEL_FATAL:  return "fatal";
+    case LOG_LEVEL_NONE:   return "none";
+  }
+  return NULL;
+}
+
+int string_to_log_level(const char *text)
+{
+  if (strcasecmp(text, "none") == 0)   return LOG_LEVEL_NONE;
+  if (strcasecmp(text, "fatal") == 0)  return LOG_LEVEL_FATAL;
+  if (strcasecmp(text, "error") == 0)  return LOG_LEVEL_ERROR;
+  if (strcasecmp(text, "warn") == 0)   return LOG_LEVEL_WARN;
+  if (strcasecmp(text, "info") == 0)   return LOG_LEVEL_INFO;
+  if (strcasecmp(text, "debug") == 0)  return LOG_LEVEL_DEBUG;
+  if (strcasecmp(text, "silent") == 0) return LOG_LEVEL_SILENT;
+  return LOG_LEVEL_INVALID;
+}

log.h

@@ -25,14 +25,18 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
 #include <sys/types.h>
 #include <errno.h>
 
-#define LOG_LEVEL_SILENT    (-1)
+#define LOG_LEVEL_INVALID   (-1)
-#define LOG_LEVEL_DEBUG     (0)
+#define LOG_LEVEL_SILENT    (0)
-#define LOG_LEVEL_INFO      (1)
+#define LOG_LEVEL_DEBUG     (1)
-#define LOG_LEVEL_WARN      (2)
+#define LOG_LEVEL_INFO      (2)
-#define LOG_LEVEL_ERROR     (3)
+#define LOG_LEVEL_WARN      (3)
-#define LOG_LEVEL_FATAL     (4)
+#define LOG_LEVEL_ERROR     (4)
+#define LOG_LEVEL_FATAL     (5)
 #define LOG_LEVEL_NONE      (127)
 
+const char *log_level_as_string(int level);
+int string_to_log_level(const char *text);
+
 /*
  * Every log message identifies the location in the source code at which the
  * message was produced.  This location is represented by a struct __sourceloc,

tests/config

@@ -210,7 +210,7 @@ test_InterfacesLegacyInvalidType() {
       config set interfaces '+eth=foo:4111:9M'
    assert_stderr_log \
       --warn-pattern='"interfaces".*invalid' \
-      --error-pattern='config file.*not loaded.*invalid'
+      --error-pattern='config file.*loaded despite defects.*invalid'
 }
 
 doc_InterfacesLegacyInvalidPort="Legacy 'interfaces' config option invalid port"
@@ -219,7 +219,7 @@ test_InterfacesLegacyInvalidPort() {
       config set interfaces '+eth=ethernet:-1000:9M'
    assert_stderr_log \
       --warn-pattern='"interfaces".*invalid' \
-      --error-pattern='config file.*not loaded.*invalid'
+      --error-pattern='config file.*loaded despite defects.*invalid'
 }
 
 doc_InterfacesLegacyInvalidSpeed="Legacy 'interfaces' config option invalid speed is ignored"
@@ -229,7 +229,7 @@ test_InterfacesLegacyInvalidSpeed() {
       config set interfaces '+eth=ethernet:4111:9Moose'
    #assert_stderr_log \
    #   --warn-pattern='"interfaces".*invalid' \
-   #   --error-pattern='config file.*not loaded.*invalid'
+   #   --error-pattern='config file.*loaded despite defects.*invalid'
 }
 
 doc_InterfacesLegacyIncompatible="Legacy 'interfaces' config option incompatible with modern form"
@@ -241,7 +241,7 @@ test_InterfacesLegacyIncompatible() {
    assertExitStatus '==' 2
    assert_stderr_log \
       --warn-pattern='"interfaces.*incompatible' \
-      --error-pattern='config file.*not loaded.*incompatible'
+      --error-pattern='config file.*loaded despite defects.*incompatible'
    tfw_cat --stderr
 }
 
@@ -267,7 +267,7 @@ test_InterfacesModernIncompatible() {
    assertExitStatus '==' 2
    assert_stderr_log \
       --warn-pattern='"interfaces\.0\..*incompatible' \
-      --error-pattern='config file.*not loaded.*incompatible'
+      --error-pattern='config file.*loaded despite defects.*incompatible'
 }
 
 doc_LogFileAbsolute="Absolute log file"

tests/logging

@@ -0,0 +1,133 @@
+#!/bin/bash
+
+# Tests for Serval DNA logging.
+#
+# Copyright 2013 Serval Project, Inc.
+#
+# This program is free software; you can redistribute it and/or
+# modify it under the terms of the GNU General Public License
+# as published by the Free Software Foundation; either version 2
+# of the License, or (at your option) any later version.
+# 
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+# 
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, write to the Free Software
+# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+
+source "${0%/*}/../testframework.sh"
+source "${0%/*}/../testdefs.sh"
+
+setup() {
+   setup_servald
+}
+
+doc_LogStderrDefault="By default, only errors and warnings are logged to stderr"
+test_LogStderrDefault() {
+   execute $servald log error 'hoopla'
+   assertExitStatus '==' 0
+   assertStderrGrep --matches=1 '^ERROR:.*hoopla$'
+   executeOk_servald log warn 'buckle'
+   assertStderrGrep --matches=1 '^WARN:.*buckle$'
+   executeOk_servald log info 'lymph'
+   assertStderrGrep --matches=0 'lymph'
+   executeOk_servald log debug 'eccles'
+   assertStderrGrep --matches=0 'eccles'
+}
+
+doc_LogStderrConfigAll="Configure all messages logged to stderr"
+test_LogStderrConfigAll() {
+   executeOk_servald config set log.stderr.level debug
+   execute $servald log error 'hoopla'
+   assertExitStatus '==' 0
+   assertStderrGrep --matches=1 '^ERROR:.*hoopla$'
+   executeOk_servald log warn 'buckle'
+   assertStderrGrep --matches=1 '^WARN:.*buckle$'
+   executeOk_servald log info 'lymph'
+   assertStderrGrep --matches=1 'INFO:.*lymph$'
+   executeOk_servald log debug 'eccles'
+   assertStderrGrep --matches=1 'DEBUG:.*eccles$'
+}
+
+doc_LogStderrConfigNone="Configure no messages logged to stderr"
+test_LogStderrConfigNone() {
+   executeOk_servald config set log.stderr.level none
+   executeOk_servald log error 'hoopla'
+   assertStderrIs ''
+   executeOk_servald log warn 'buckle'
+   assertStderrIs ''
+   executeOk_servald log info 'lymph'
+   assertStderrIs ''
+   executeOk_servald log debug 'eccles'
+   assertStderrIs ''
+}
+
+doc_LogFileDefault="By Default, all messages are appended to a configured file"
+test_LogFileDefault() {
+   executeOk_servald config set log.stderr.level none
+   executeOk_servald config set log.file_path "$PWD/log.txt"
+   executeOk_servald log error 'hoopla'
+   assertGrep --matches=1 log.txt '^ERROR:.*hoopla$'
+   executeOk_servald log warn 'buckle'
+   assertGrep --matches=1 log.txt '^ERROR:.*hoopla$'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   executeOk_servald log info 'lymph'
+   assertGrep --matches=1 log.txt '^ERROR:.*hoopla$'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertGrep --matches=1 log.txt 'INFO:.*lymph$'
+   executeOk_servald log debug 'eccles'
+   assertGrep --matches=1 log.txt '^ERROR:.*hoopla$'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertGrep --matches=1 log.txt 'INFO:.*lymph$'
+   assertGrep --matches=1 log.txt 'DEBUG:.*eccles$'
+}
+
+doc_LogFileConfigLevel="Configure level of messages appended to a configured file"
+test_LogFileConfigLevel() {
+   executeOk_servald config set log.stderr.level none
+   executeOk_servald config set log.file.level info
+   executeOk_servald config set log.file_path "$PWD/log.txt"
+   executeOk_servald log warn 'buckle'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   executeOk_servald log debug 'eccles'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertGrep --matches=0 log.txt 'DEBUG:.*eccles$'
+   executeOk_servald log error 'hoopla'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertGrep --matches=0 log.txt 'DEBUG:.*eccles$'
+   assertGrep --matches=1 log.txt '^ERROR:.*hoopla$'
+   executeOk_servald log info 'lymph'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertGrep --matches=0 log.txt 'DEBUG:.*eccles$'
+   assertGrep --matches=1 log.txt '^ERROR:.*hoopla$'
+   assertGrep --matches=1 log.txt 'INFO:.*lymph$'
+}
+
+doc_LogFileStderrFile="Log messages to stderr and a configured file"
+test_LogFileStderrFile() {
+   executeOk_servald config set log.file_path "$PWD/log.txt"
+   executeOk_servald log info 'lymph'
+   assertGrep --matches=1 log.txt 'INFO:.*lymph$'
+   assertStderrIs ''
+   executeOk_servald log warn 'buckle'
+   assertGrep --matches=1 log.txt 'INFO:.*lymph$'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertStderrGrep --matches=1 '^WARN:.*buckle$'
+   executeOk_servald log debug 'eccles'
+   assertStderrIs ''
+   assertGrep --matches=1 log.txt 'INFO:.*lymph$'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertGrep --matches=1 log.txt 'DEBUG:.*eccles$'
+   execute $servald log error 'hoopla'
+   assertExitStatus '==' 0
+   assertStderrGrep --matches=1 '^ERROR:.*hoopla$'
+   assertGrep --matches=1 log.txt 'INFO:.*lymph$'
+   assertGrep --matches=1 log.txt '^WARN:.*buckle$'
+   assertGrep --matches=1 log.txt 'DEBUG:.*eccles$'
+   assertGrep --matches=1 log.txt '^ERROR:.*hoopla$'
+}
+
+runTests "$@"