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 message = GLib.LogField(); + 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(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 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);