[geary/wip/structured-logging: 4/4] Switch to using GLib structured logging

[Michael Gratton <mjog src gnome org>]

commit 21e0f6ee11a6a264ba6b9b1a6c98b69a85aad5b5
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.
    
    XXX WIP
    
    TODO:
    
     * Fix crash in formatting message string in Context
     * Switch/remove calls in Logging, use Loggables instead

 src/client/application/geary-application.vala |   1 +
 src/engine/api/geary-logging.vala             | 127 ++++++++++++++++++++++++++
 src/engine/util/util-loggable.vala            |  62 +++++++++++--
 3 files changed, 183 insertions(+), 7 deletions(-)
---
diff --git a/src/client/application/geary-application.vala b/src/client/application/geary-application.vala
index e7ecc762..4cca1fd0 100644
--- a/src/client/application/geary-application.vala
+++ b/src/client/application/geary-application.vala
@@ -187,6 +187,7 @@ public class GearyApplication : Gtk.Application {
         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);
 
         Date.init();
 
diff --git a/src/engine/api/geary-logging.vala b/src/engine/api/geary-logging.vala
index c6ec9a6a..1f8cc2b3 100644
--- a/src/engine/api/geary-logging.vala
+++ b/src/engine/api/geary-logging.vala
@@ -35,6 +35,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;
+    }
+
 }
 
 private int init_count = 0;
@@ -169,6 +214,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..0e39bd64 100644
--- a/src/engine/util/util-loggable.vala
+++ b/src/engine/util/util-loggable.vala
@@ -17,6 +17,54 @@
  */
 public interface Geary.Loggable : GLib.Object {
 
+    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;
+
+        Context(string domain,
+                Logging.Flag flags,
+                GLib.LogLevelFlags levels,
+                string message,
+                va_list args) {
+            this.fields = new GLib.LogField[FIELD_COUNT];
+            this.len = FIELD_COUNT;
+            this.count = 0;
+            append("PRIORITY", levels);
+            append("GLIB_DOMAIN", domain);
+            append("GEARY_FLAGS", flags);
+            append("MESSAGE", message.vprintf(args));
+
+            GLib.debug("XXX context: %s", message.vprintf(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() {
+            return this.fields[0:this.count];
+        }
+
+    }
+
 
     /**
      * Default flags to use for this loggable when logging messages.
@@ -92,15 +140,15 @@ 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;
+        GLib.debug("XXX log call: %s", fmt.vprintf(args));
+        Context context = Context(Logging.DOMAIN, flags, levels, fmt, va_list.copy(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());
     }
 
 }