Refactor our logging and extend the wslog API

Experience has shown that:

  1. The current logging methods are not very reliable or practical.
A logging bitmask makes little sense as the user-facing interface (who
would want debug but not crtical messages for example?); it's
computer-friendly and user-unfriendly. More importantly the console
log level preference is initialized too late in the startup process
to be used for the logging subsystem and that fact raises a number
of annoying and hard-to-fix usability issues.

  2. Coding around G_MESSAGES_DEBUG to comply with our log level mask
and not clobber the user's settings or not create unexpected log misses
is unworkable and generally follows the principle of most surprise.
The fact that G_MESSAGES_DEBUG="all" can leak to other programs using
GLib is also annoying.

  3. The non-structured GLib logging API is very opinionated and lacks
configurability beyond replacing the log handler.

  4. Windows GUI has some special code to attach to a console,
but it would be nice to abstract away the rest under a single
interface.

  5. Using this logger seems to be noticeably faster.

Deprecate the console log level preference and extend our API to
implement a log handler in wsutil/wslog.h to provide easy-to-use,
flexible and dependable logging during all execution phases.

Log levels have a hierarchy, from most verbose to least verbose
(debug to error). When a given level is set everything above that
is also enabled.

The log level can be set with an environment variable or a command
line option (parsed as soon as possible but still later than the
environment). The default log level is "message".

Dissector logging is not included because it is not clear what log
domain they should use. An explosion to thousands of domains is
not desirable and putting everything in a single domain is probably
too coarse and noisy. For now I think it makes sense to let them do
their own thing using g_log_default_handler() and continue using the
G_MESSAGES_DEBUG mechanism with specific domains for each individual
dissector.

In the future a mechanism may be added to selectively enable these
domains at runtime while trying to avoid the problems introduced
by G_MESSAGES_DEBUG.

1 files changed, 18 insertions, 68 deletions

diff --git a/tshark.c b/tshark.c
index fddb346c65..a224c5eaf2 100644
--- a/tshark.c
+++ b/tshark.c
@@ -12,7 +12,7 @@
 
 #include <config.h>
 
-#define G_LOG_DOMAIN "tshark"
+#define WS_LOG_DOMAIN  LOG_DOMAIN_MAIN
 
 #include <stdlib.h>
 #include <stdio.h>
@@ -117,12 +117,12 @@
 #include <capture/capture_sync.h>
 #include <ui/capture_info.h>
 #endif /* HAVE_LIBPCAP */
-#include "log.h"
 #include <epan/funnel.h>
 
 #include <wsutil/str_util.h>
 #include <wsutil/utf8_entities.h>
 #include <wsutil/json_dumper.h>
+#include <wsutil/wslog.h>
 #ifdef _WIN32
 #include <wsutil/win32-utils.h>
 #endif
@@ -531,31 +531,6 @@ glossary_option_help(void)
 }
 
 static void
-tshark_log_handler (const gchar *log_domain, GLogLevelFlags log_level,
-    const gchar *message, gpointer user_data)
-{
-  /* ignore log message, if log_level isn't interesting based
-     upon the console log preferences.
-     If the preferences haven't been loaded yet, display the
-     message anyway.
-
-     The default console_log_level preference value is such that only
-       ERROR, CRITICAL and WARNING level messages are processed;
-       MESSAGE, INFO and DEBUG level messages are ignored.
-
-     XXX: Aug 07, 2009: Prior tshark g_log code was hardwired to process only
-           ERROR and CRITICAL level messages so the current code is a behavioral
-           change.  The current behavior is the same as in Wireshark.
-  */
-  if (prefs_loaded && (log_level & G_LOG_LEVEL_MASK & prefs.console_log_level) == 0) {
-    return;
-  }
-
-  g_log_default_handler(log_domain, log_level, message, user_data);
-
-}
-
-static void
 print_current_user(void) {
   gchar *cur_user, *cur_group;
 
@@ -757,7 +732,6 @@ main(int argc, char *argv[])
   dfilter_t           *rfcode = NULL;
   dfilter_t           *dfcode = NULL;
   e_prefs             *prefs_p;
-  int                  log_flags;
   gchar               *output_only = NULL;
   gchar               *volatile pdu_export_arg = NULL;
   char                *volatile exp_pdu_filename = NULL;
@@ -798,10 +772,21 @@ main(int argc, char *argv[])
   setlocale(LC_ALL, "");
 #endif
 
-  ws_debug("tshark started with %d args", argc);
+  /* Initialize log handler early so we can have proper logging during startup. */
+  ws_log_init(NULL);
 
   cmdarg_err_init(tshark_cmdarg_err, tshark_cmdarg_err_cont);
 
+  /* Command line options are parsed too late to configure logging, do it
+      manually. */
+  const char *opt_err_val;
+  if ((opt_err_val = ws_log_set_level_args(&argc, argv)) != NULL) {
+    cmdarg_err("Invalid log level \"%s\"", opt_err_val);
+    return INVALID_OPTION;
+  }
+
+  ws_debug("tshark started with %d args", argc);
+
 #ifdef _WIN32
   create_app_running_mutex();
 #endif /* _WIN32 */
@@ -922,33 +907,6 @@ main(int argc, char *argv[])
     }
   }
 
-/** Send All g_log messages to our own handler **/
-
-  log_flags =
-                    G_LOG_LEVEL_ERROR|
-                    G_LOG_LEVEL_CRITICAL|
-                    G_LOG_LEVEL_WARNING|
-                    G_LOG_LEVEL_MESSAGE|
-                    G_LOG_LEVEL_INFO|
-                    G_LOG_LEVEL_DEBUG|
-                    G_LOG_FLAG_FATAL|G_LOG_FLAG_RECURSION;
-
-  g_log_set_handler(NULL,
-                    (GLogLevelFlags)log_flags,
-                    tshark_log_handler, NULL /* user_data */);
-  g_log_set_handler(LOG_DOMAIN_MAIN,
-                    (GLogLevelFlags)log_flags,
-                    tshark_log_handler, NULL /* user_data */);
-
-#ifdef HAVE_LIBPCAP
-  g_log_set_handler(LOG_DOMAIN_CAPTURE,
-                    (GLogLevelFlags)log_flags,
-                    tshark_log_handler, NULL /* user_data */);
-  g_log_set_handler(LOG_DOMAIN_CAPTURE_CHILD,
-                    (GLogLevelFlags)log_flags,
-                    tshark_log_handler, NULL /* user_data */);
-#endif
-
   init_report_message("TShark", &tshark_report_routines);
 
 #ifdef HAVE_LIBPCAP
@@ -2403,8 +2361,6 @@ pipe_timer_cb(gpointer data)
 
   /* try to read data from the pipe only 5 times, to avoid blocking */
   while(iterations < 5) {
-    /*g_log(NULL, G_LOG_LEVEL_DEBUG, "pipe_timer_cb: new iteration");*/
-
     /* Oddly enough although Named pipes don't work on win9x,
        PeekNamedPipe does !!! */
     handle = (HANDLE) _get_osfhandle (pipe_input_p->source);
@@ -2419,18 +2375,15 @@ pipe_timer_cb(gpointer data)
        callback */
     if (!result || avail > 0 || childstatus != STILL_ACTIVE) {
 
-      /*g_log(NULL, G_LOG_LEVEL_DEBUG, "pipe_timer_cb: data avail");*/
-
       /* And call the real handler */
       if (!pipe_input_p->input_cb(pipe_input_p->source, pipe_input_p->user_data)) {
-        g_log(NULL, G_LOG_LEVEL_DEBUG, "pipe_timer_cb: input pipe closed, iterations: %u", iterations);
+        ws_debug("input pipe closed, iterations: %u", iterations);
         /* pipe closed, return false so that the timer is stopped */
         g_mutex_unlock (pipe_input_p->callback_running);
         return FALSE;
       }
     }
     else {
-      /*g_log(NULL, G_LOG_LEVEL_DEBUG, "pipe_timer_cb: no data avail");*/
       /* No data, stop now */
       break;
     }
@@ -2438,8 +2391,6 @@ pipe_timer_cb(gpointer data)
     iterations++;
   }
 
-  /*g_log(NULL, G_LOG_LEVEL_DEBUG, "pipe_timer_cb: finished with iterations: %u, new timer", iterations);*/
-
   g_mutex_unlock (pipe_input_p->callback_running);
 
   /* we didn't stopped the timer, so let it run */
@@ -2465,7 +2416,6 @@ pipe_input_set_handler(gint source, gpointer user_data, ws_process_id *child_pro
      this but doesn't seem to work over processes.  Attempt to do
      something similar here, start a timer and check for data on every
      timeout. */
-  /*g_log(NULL, G_LOG_LEVEL_DEBUG, "pipe_input_set_handler: new");*/
   pipe_input.pipe_input_id = g_timeout_add(200, pipe_timer_cb, &pipe_input);
 #endif
 }
@@ -2627,7 +2577,7 @@ capture(void)
 #endif
         /* Call the real handler */
         if (!pipe_input.input_cb(pipe_input.source, pipe_input.user_data)) {
-          g_log(NULL, G_LOG_LEVEL_DEBUG, "input pipe closed");
+          ws_debug("input pipe closed");
           ret = FALSE;
           loop_running = FALSE;
         }
@@ -2704,9 +2654,9 @@ capture_input_new_file(capture_session *cap_session, gchar *new_file)
   int      err;
 
   if (cap_session->state == CAPTURE_PREPARING) {
-    g_log(LOG_DOMAIN_CAPTURE, G_LOG_LEVEL_MESSAGE, "Capture started.");
+    ws_message("Capture started.");
   }
-  g_log(LOG_DOMAIN_CAPTURE, G_LOG_LEVEL_MESSAGE, "File: \"%s\"", new_file);
+  ws_message("File: \"%s\"", new_file);
 
   g_assert(cap_session->state == CAPTURE_PREPARING || cap_session->state == CAPTURE_RUNNING);