[geary/wip/problem-report-logs: 4/22] Switch to using GLib structured logging

[Michael Gratton <mjog src gnome org>]

commit 4d31068de91fb399f53a729a500bbb733d1d22c9
Author: Michael Gratton <mike vee net>
Date:   Sat Dec 29 12:57:01 2018 +1100

    Switch to using GLib structured logging
    
    This converts the logging infrastructure to using structured logging
    calls, adds and sets a structured logging writer.

 src/client/application/geary-application.vala |   2 +-
 src/engine/api/geary-logging.vala             | 151 ++++++++++++++++++++++++--
 src/engine/util/util-loggable.vala            |  95 ++++++++++++++--
 src/mailer/main.vala                          |   2 +-
 src/meson.build                               |   2 +
 test/test-integration.vala                    |   2 +-
 6 files changed, 232 insertions(+), 22 deletions(-)
---
diff --git a/src/client/application/geary-application.vala b/src/client/application/geary-application.vala
index f74369ba..de894601 100644
--- a/src/client/application/geary-application.vala
+++ b/src/client/application/geary-application.vala
@@ -412,7 +412,7 @@ public class GearyApplication : Gtk.Application {
         Configuration.init(this.is_installed, GSETTINGS_DIR);
         Geary.Logging.init();
         Geary.Logging.log_to(stderr);
-        GLib.Log.set_default_handler(Geary.Logging.default_handler);
+        GLib.Log.set_writer_func(Geary.Logging.default_log_writer);
 
         Util.Date.init();
 
diff --git a/src/engine/api/geary-logging.vala b/src/engine/api/geary-logging.vala
index af435374..317a6d2b 100644
--- a/src/engine/api/geary-logging.vala
+++ b/src/engine/api/geary-logging.vala
@@ -47,6 +47,51 @@ public enum Flag {
     public inline bool is_any_set(Flag flags) {
         return (flags & this) != 0;
     }
+
+    public string to_string() {
+        GLib.StringBuilder buf = new GLib.StringBuilder();
+        if (this == ALL) {
+            buf.append("ALL");
+        } else if (this == NONE) {
+            buf.append("NONE");
+        } else {
+            if (this.is_any_set(NETWORK)) {
+                buf.append("NET");
+            }
+            if (this.is_any_set(SERIALIZER)) {
+                if (buf.len > 0) {
+                    buf.append_c('|');
+                }
+                buf.append("SER");
+            }
+            if (this.is_any_set(REPLAY)) {
+                if (buf.len > 0) {
+                    buf.append_c('|');
+                }
+                buf.append("REPLAY");
+            }
+            if (this.is_any_set(SQL)) {
+                if (buf.len > 0) {
+                    buf.append_c('|');
+                }
+                buf.append("SQL");
+            }
+            if (this.is_any_set(FOLDER_NORMALIZATION)) {
+                if (buf.len > 0) {
+                    buf.append_c('|');
+                }
+                buf.append("NORM");
+            }
+            if (this.is_any_set(DESERIALIZER)) {
+                if (buf.len > 0) {
+                    buf.append_c('|');
+                }
+                buf.append("DESER");
+            }
+        }
+        return buf.str;
+    }
+
 }
 
 /**
@@ -173,33 +218,27 @@ public inline bool are_all_flags_set(Flag flags) {
 
 [PrintfFormat]
 public inline void error(Flag flags, string fmt, ...) {
-    if (flags == ALL || logging_flags.is_any_set(flags))
-        GLib.logv(DOMAIN, LogLevelFlags.LEVEL_ERROR, fmt, va_list());
+    logv(flags, GLib.LogLevelFlags.LEVEL_ERROR, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void critical(Flag flags, string fmt, ...) {
-    if (flags == ALL || logging_flags.is_any_set(flags))
-        GLib.logv(DOMAIN, LogLevelFlags.LEVEL_CRITICAL, fmt, va_list());
+    logv(flags, GLib.LogLevelFlags.LEVEL_CRITICAL, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void warning(Flag flags, string fmt, ...) {
-    if (flags == ALL || logging_flags.is_any_set(flags))
-        GLib.logv(DOMAIN, LogLevelFlags.LEVEL_WARNING, fmt, va_list());
+    logv(flags, GLib.LogLevelFlags.LEVEL_WARNING, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void message(Flag flags, string fmt, ...) {
-    if (flags == ALL || logging_flags.is_any_set(flags))
-        GLib.logv(DOMAIN, LogLevelFlags.LEVEL_MESSAGE, fmt, va_list());
+    logv(flags, GLib.LogLevelFlags.LEVEL_MESSAGE, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void debug(Flag flags, string fmt, ...) {
-    if (flags == ALL || logging_flags.is_any_set(flags)) {
-        GLib.logv(DOMAIN, LogLevelFlags.LEVEL_DEBUG, fmt, va_list());
-    }
+    logv(flags, GLib.LogLevelFlags.LEVEL_DEBUG, fmt, va_list());
 }
 
 public inline void logv(Flag flags,
@@ -207,7 +246,13 @@ public inline void logv(Flag flags,
                         string fmt,
                         va_list args) {
     if (flags == ALL || logging_flags.is_any_set(flags)) {
-        GLib.logv(DOMAIN, level, fmt, args);
+        string formatted = fmt.vprintf(args);
+        GLib.LogField<string> message = GLib.LogField<string>();
+        message.key = "MESSAGE";
+        message.length = -1;
+        message.value = formatted;
+
+        GLib.log_structured_array(level, { message });
     }
 }
 
@@ -277,6 +322,88 @@ public void default_handler(string? domain,
     }
 }
 
+public GLib.LogWriterOutput default_log_writer(GLib.LogLevelFlags log_levels,
+                                               GLib.LogField[] fields) {
+    unowned FileStream? out = stream;
+    if (out != null ||
+        ((LogLevelFlags.LEVEL_WARNING & log_levels) > 0) ||
+        ((LogLevelFlags.LEVEL_CRITICAL & log_levels) > 0)  ||
+        ((LogLevelFlags.LEVEL_ERROR & log_levels) > 0)) {
+
+        if (out == null) {
+            out = GLib.stderr;
+        }
+
+        string domain = "default";
+        Flag flag = Flag.NONE;
+        string message = "[no message]";
+
+        string[] strings = new string[fields.length];
+        uint string_count = 0;
+
+        foreach (GLib.LogField field in fields) {
+            switch (field.key.ascii_up()) {
+            case "GLIB_DOMAIN":
+                if (field.length < 0) {
+                    domain = (string) field.value;
+                }
+                break;
+            case "MESSAGE":
+                if (field.length < 0) {
+                    message = (string) field.value;
+                }
+                break;
+            case "PRIORITY":
+                // noop, we get it from the args
+                break;
+            case "GEARY_FLAGS":
+                flag = (Flag) field.value;
+                break;
+            default:
+                string? string_value = null;
+                if (field.length < 0) {
+                    string_value = (string) field.value;
+                } else {
+                    Loggable? loggable = field.value as Loggable;
+                    if (loggable != null) {
+                        string_value = loggable.to_string();
+                    }
+                }
+                if (string_value != null) {
+                    strings[string_count++] = string_value;
+                }
+                break;
+            }
+        }
+
+        GLib.Time tm = GLib.Time.local(time_t());
+        out.printf(
+            "%s %02d:%02d:%02d %lf %s",
+            to_prefix(log_levels),
+            tm.hour, tm.minute, tm.second,
+            entry_timer.elapsed(),
+            domain
+        );
+
+        if (flag != ALL && flag != NONE) {
+            out.printf("[%s]: ", flag.to_string());
+        } else {
+            out.puts(": ");
+        }
+
+        for (int i = 0; i < string_count; i++) {
+            out.puts(strings[i]);
+            out.putc(' ');
+        }
+        out.puts(message);
+        out.putc('\n');
+        entry_timer.start();
+    }
+
+    return GLib.LogWriterOutput.HANDLED;
+}
+
+
 private inline string to_prefix(LogLevelFlags level) {
     switch (level) {
     case LogLevelFlags.LEVEL_ERROR:
diff --git a/src/engine/util/util-loggable.vala b/src/engine/util/util-loggable.vala
index d220d397..6fba32f9 100644
--- a/src/engine/util/util-loggable.vala
+++ b/src/engine/util/util-loggable.vala
@@ -18,6 +18,88 @@
 public interface Geary.Loggable : GLib.Object {
 
 
+    // Based on function from with the same name from GLib's
+    // gmessages.c. Return value must be 1 byte long (plus nul byte).
+    // Reference:
+    // http://man7.org/linux/man-pages/man3/syslog.3.html#DESCRIPTION
+    private static string log_level_to_priority(GLib.LogLevelFlags level) {
+        if (GLib.LogLevelFlags.LEVEL_ERROR in level) {
+            return "3";
+        }
+        if (GLib.LogLevelFlags.LEVEL_CRITICAL in level) {
+            return "4";
+        }
+        if (GLib.LogLevelFlags.LEVEL_WARNING in level) {
+            return "4";
+        }
+        if (GLib.LogLevelFlags.LEVEL_MESSAGE in level) {
+            return "5";
+        }
+        if (GLib.LogLevelFlags.LEVEL_INFO in level) {
+            return "6";
+        }
+        if (GLib.LogLevelFlags.LEVEL_DEBUG in level) {
+            return "7";
+        }
+
+        /* Default to LOG_NOTICE for custom log levels. */
+        return "5";
+    }
+
+
+    protected struct Context {
+
+        // 8 fields ought to be enough for anybody...
+        private const uint8 FIELD_COUNT = 8;
+
+        public GLib.LogField[] fields;
+        public uint8 len;
+        public uint8 count;
+
+        public string message;
+
+
+        Context(string domain,
+                Logging.Flag flags,
+                GLib.LogLevelFlags level,
+                string message,
+                va_list args) {
+            this.fields = new GLib.LogField[FIELD_COUNT];
+            this.len = FIELD_COUNT;
+            this.count = 0;
+            append("PRIORITY", log_level_to_priority(level));
+            append("GLIB_DOMAIN", domain);
+            append("GEARY_FLAGS", flags);
+
+            this.message = message.vprintf(va_list.copy(args));
+        }
+
+        public void append<T>(string key, T value) {
+            uint8 count = this.count;
+            if (count + 1 >= this.len) {
+                this.fields.resize(this.len + FIELD_COUNT);
+            }
+
+            this.fields[count].key = key;
+            this.fields[count].value = value;
+            this.fields[count].length = (typeof(T) == typeof(string)) ? -1 : 0;
+
+            this.count++;
+        }
+
+        public inline void append_instance<T>(T value) {
+            this.append(typeof(T).name(), value);
+        }
+
+        public GLib.LogField[] to_array() {
+            // MESSAGE must always be last, so append it here
+            append("MESSAGE", this.message);
+            return this.fields[0:this.count];
+        }
+
+    }
+
+
     /**
      * Default flags to use for this loggable when logging messages.
      */
@@ -92,15 +174,14 @@ public interface Geary.Loggable : GLib.Object {
                                        GLib.LogLevelFlags levels,
                                        string fmt,
                                        va_list args) {
-        GLib.StringBuilder message = new GLib.StringBuilder(fmt);
-        Loggable? decorator = this;
-        while (decorator != null) {
-            message.prepend_c(' ');
-            message.prepend(decorator.to_string());
-            decorator = decorator.loggable_parent;
+        Context context = Context(Logging.DOMAIN, flags, levels, fmt, args);
+        Loggable? decorated = this;
+        while (decorated != null) {
+            context.append_instance(decorated);
+            decorated = decorated.loggable_parent;
         }
 
-        Logging.logv(flags, levels, message.str, args);
+        GLib.log_structured_array(levels, context.to_array());
     }
 
 }
diff --git a/src/mailer/main.vala b/src/mailer/main.vala
index e91d20e2..72cddd82 100644
--- a/src/mailer/main.vala
+++ b/src/mailer/main.vala
@@ -161,7 +161,7 @@ int main(string[] args) {
         Geary.Logging.init();
         Geary.Logging.log_to(stdout);
         Geary.Logging.enable_flags(Geary.Logging.Flag.NETWORK);
-        GLib.Log.set_default_handler(Geary.Logging.default_handler);
+        GLib.Log.set_writer_func(Geary.Logging.default_log_writer);
     }
 
     Geary.RFC822.init();
diff --git a/src/meson.build b/src/meson.build
index efeb9407..5ef921fd 100644
--- a/src/meson.build
+++ b/src/meson.build
@@ -31,6 +31,8 @@ endif
 
 geary_c_options = [
   '-include', 'config.h',
+  # Enable GLib structured logging
+  '-DG_LOG_USE_STRUCTURED',
   # Select libunwind's optimised, local-only backtrace unwiding. See
   # libunwind(3).
   '-DUNW_LOCAL_ONLY',
diff --git a/test/test-integration.vala b/test/test-integration.vala
index 76a775bb..4a20af93 100644
--- a/test/test-integration.vala
+++ b/test/test-integration.vala
@@ -36,7 +36,7 @@ int main(string[] args) {
     Geary.HTML.init();
     Geary.Logging.init();
     Geary.Logging.log_to(stderr);
-    GLib.Log.set_default_handler(Geary.Logging.default_handler);
+    GLib.Log.set_writer_func(Geary.Logging.default_log_writer);
 
     Integration.Configuration config = load_config(args);