Merge branch 'wip/structured-logging' into 'mainline'

Convert Geary to use GLib structured logging

See merge request GNOME/geary!249

po/POTFILES.in

@@ -389,6 +389,7 @@ src/engine/util/util-imap-utf7.vala
 src/engine/util/util-inet.vala
 src/engine/util/util-iterable.vala
 src/engine/util/util-js.vala
+src/engine/util/util-loggable.vala
 src/engine/util/util-numeric.vala
 src/engine/util/util-object.vala
 src/engine/util/util-reference-semantics.vala

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();
 
@@ -661,6 +661,8 @@ public class GearyApplication : Gtk.Application {
         }
 
         quit();
+
+        Geary.Logging.clear();
         Util.Date.terminate();
     }
 

src/engine/api/geary-account.vala

@@ -22,7 +22,7 @@
  * A list of all Accounts may be retrieved from the {@link Engine} singleton.
  */
 
-public abstract class Geary.Account : BaseObject {
+public abstract class Geary.Account : BaseObject, Loggable {
 
 
     /** Number of times to attempt re-authentication. */
@@ -137,8 +137,6 @@ public abstract class Geary.Account : BaseObject {
     public Geary.ProgressMonitor opening_monitor { get; protected set; }
     public Geary.ProgressMonitor sending_monitor { get; protected set; }
 
-    protected string id { get; private set; }
-
 
     public signal void opened();
 
@@ -250,6 +248,14 @@ public abstract class Geary.Account : BaseObject {
     public signal void email_flags_changed(Geary.Folder folder,
         Gee.Map<Geary.EmailIdentifier, Geary.EmailFlags> map);
 
+    /** {@inheritDoc} */
+    public Logging.Flag loggable_flags {
+        get; protected set; default = Logging.Flag.ALL;
+    }
+
+    /** {@inheritDoc} */
+    public Loggable? loggable_parent { get { return null; } }
+
 
     protected Account(AccountInformation information,
                       ClientService incoming,
@@ -257,9 +263,6 @@ public abstract class Geary.Account : BaseObject {
         this.information = information;
         this.incoming = incoming;
         this.outgoing = outgoing;
-        this.id = "%s[%s]".printf(
-            information.id, information.service_provider.to_value()
-        );
 
         incoming.notify["current-status"].connect(
             on_service_status_notify
@@ -484,11 +487,12 @@ public abstract class Geary.Account : BaseObject {
     public abstract async Gee.MultiMap<Geary.EmailIdentifier, Geary.FolderPath>? get_containing_folders_async(
         Gee.Collection<Geary.EmailIdentifier> ids, Cancellable? cancellable) throws Error;
 
-    /**
+    /** {@inheritDoc} */
-     * Used only for debugging.  Should not be used for user-visible strings.
-     */
     public virtual string to_string() {
-        return this.id;
+        return "%s(%s)".printf(
+            this.get_type().name(),
+            this.information.id
+        );
     }
 
     /** Fires a {@link opened} signal. */

src/engine/api/geary-client-service.vala

@@ -14,7 +14,7 @@
  * itself, rather manages the configuration, status tracking, and
  * life-cycle of concrete implementations.
  */
-public abstract class Geary.ClientService : BaseObject {
+public abstract class Geary.ClientService : BaseObject, Loggable {
 
 
     private const int BECAME_REACHABLE_TIMEOUT_SEC = 1;
@@ -197,6 +197,15 @@ public abstract class Geary.ClientService : BaseObject {
     /** The last reported error, if any. */
     public ErrorContext? last_error { get; private set; default = null; }
 
+    /** {@inheritDoc} */
+    public Logging.Flag loggable_flags {
+        get; protected set; default = Logging.Flag.ALL;
+    }
+
+    /** {@inheritDoc} */
+    public Loggable? loggable_parent { get { return _loggable_parent; } }
+    private weak Loggable? _loggable_parent = null;
+
 
     protected ClientService(AccountInformation account,
                             ServiceInformation configuration,
@@ -283,6 +292,19 @@ public abstract class Geary.ClientService : BaseObject {
         yield start(cancellable);
     }
 
+    /** {@inheritDoc} */
+    public virtual string to_string() {
+        return "%s(%s)".printf(
+            this.get_type().name(),
+            this.configuration.protocol.to_value()
+        );
+    }
+
+    /** Sets the service's logging parent. */
+    internal void set_loggable_parent(Loggable parent) {
+        this._loggable_parent = parent;
+    }
+
     /**
      * Called when the network service has become reachable.
      *
@@ -407,21 +429,11 @@ public abstract class Geary.ClientService : BaseObject {
     }
 
     private void on_running_notify() {
-        debug(
+        debug(this.is_running ? "Started" : "Stopped");
-            "%s:%s %s",
-            this.account.id,
-            this.configuration.protocol.to_value(),
-            this.is_running ? "started" : "stopped"
-        );
     }
 
     private void on_current_status_notify() {
-        debug(
+        debug("Status changed to: %s", this.current_status.to_value());
-            "%s:%s: status changed to: %s",
-            this.account.id,
-            this.configuration.protocol.to_value(),
-            this.current_status.to_value()
-        );
     }
 
     private void on_connectivity_change() {

src/engine/api/geary-folder.vala

@@ -61,7 +61,7 @@
  *
  * @see Geary.SpecialFolderType
  */
-public abstract class Geary.Folder : BaseObject {
+public abstract class Geary.Folder : BaseObject, Loggable {
 
     /**
      * Indicates if a folder has been opened, and if so in which way.
@@ -238,6 +238,15 @@ public abstract class Geary.Folder : BaseObject {
     /** Monitor for notifying of progress when opening the folder. */
     public abstract Geary.ProgressMonitor opening_monitor { get; }
 
+    /** {@inheritDoc} */
+    public Logging.Flag loggable_flags {
+        get; protected set; default = Logging.Flag.ALL;
+    }
+
+    /** {@inheritDoc} */
+    public Loggable? loggable_parent {
+        get { return this.account; }
+    }
 
     /**
      * Fired when the folder moves through stages of being opened.
@@ -673,10 +682,13 @@ public abstract class Geary.Folder : BaseObject {
     public abstract async Geary.Email fetch_email_async(Geary.EmailIdentifier email_id,
         Geary.Email.Field required_fields, ListFlags flags, Cancellable? cancellable = null) throws Error;
 
-    /**
+    /** {@inheritDoc} */
-     * Used for debugging.  Should not be used for user-visible labels.
-     */
     public virtual string to_string() {
-        return "%s:%s".printf(this.account.information.id, this.path.to_string());
+        return "%s(%s:%s)".printf(
+            this.get_type().name(),
+            this.account.information.id,
+            this.path.to_string()
+        );
     }
+
 }

src/engine/api/geary-logging.vala

@@ -14,11 +14,12 @@
 namespace Geary.Logging {
 
 
+/** The logging domain for the engine. */
+public const string DOMAIN = "Geary";
+
 /** Specifies the default number of log records retained. */
 public const uint DEFAULT_MAX_LOG_BUFFER_LENGTH = 4096;
 
-private const string DOMAIN = "Geary";
-
 /**
  * Denotes a type of log message.
  *
@@ -36,7 +37,8 @@ public enum Flag {
     PERIODIC,
     SQL,
     FOLDER_NORMALIZATION,
-    DESERIALIZER;
+    DESERIALIZER,
+    ALL = int.MAX;
 
     public inline bool is_all_set(Flag flags) {
         return (flags & this) == flags;
@@ -45,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;
+    }
+
 }
 
 /**
@@ -58,42 +105,214 @@ public enum Flag {
 public class Record {
 
 
-    /** Returns the GLib domain of the log message. */
+    /** The GLib domain of the log message, if any. */
-    public string domain { get; private set; }
+    public string? domain { get; private set; default = null; }
 
-    /** Returns the next log record in the buffer, if any. */
+    /** Account from which the record originated, if any. */
+    public Account? account { get; private set; default = null; }
+
+    /** Client service from which the record originated, if any. */
+    public ClientService? service { get; private set; default = null; }
+
+    /** Folder from which the record originated, if any. */
+    public Folder? folder { get; private set; default = null; }
+
+    /** The logged flags, if any. */
+    public Flag? flags = null;
+
+    /** The logged message, if any. */
+    public string? message = null;
+
+    /** The source filename, if any. */
+    public string? source_filename = null;
+
+    /** The source filename, if any. */
+    public string? source_line_number = null;
+
+    /** The source function, if any. */
+    public string? source_function = null;
+
+    /** The logged level, if any. */
+    public GLib.LogLevelFlags levels;
+
+    /** Time at which the log message was generated. */
+    public int64 timestamp;
+
+    /** The next log record in the buffer, if any. */
     public Record? next { get; internal set; default = null; }
 
-    private LogLevelFlags flags;
+    private Loggable[] loggables;
-    private int64 timestamp;
+    private bool filled = false;
-    private double elapsed;
+    private bool old_log_api = false;
-    private string message;
 
 
-    internal Record(string domain,
+    internal Record(GLib.LogField[] fields,
-                    LogLevelFlags flags,
+                    GLib.LogLevelFlags levels,
-                    int64 timestamp,
+                    int64 timestamp) {
-                    double elapsed,
+        this.levels = levels;
-                    string message) {
-        this.domain = domain;
-        this.flags = flags;
         this.timestamp = timestamp;
-        this.elapsed = elapsed;
+        this.old_log_api = (
-        this.message = message;
+            fields.length > 0 &&
+            fields[0].key == "GLIB_OLD_LOG_API"
+        );
+
+        // Since GLib.LogField only retains a weak ref to its value,
+        // find and ref any values we wish to keep around.
+        this.loggables = new Loggable[fields.length];
+        int loggable_count = 0;
+        foreach (GLib.LogField field in fields) {
+            switch (field.key) {
+            case "GEARY_LOGGABLE":
+                this.loggables[loggable_count++] = (Loggable) field.value;
+                break;
+
+            case "GEARY_FLAGS":
+                this.flags = (Flag) field.value;
+                break;
+
+            case "GLIB_DOMAIN":
+                this.domain = field_to_string(field);
+                break;
+
+            case "MESSAGE":
+                this.message = field_to_string(field);
+                break;
+
+            case "CODE_FILE":
+                this.source_filename = field_to_string(field);
+                break;
+
+            case "CODE_LINE":
+                this.source_line_number = field_to_string(field);
+                break;
+
+            case "CODE_FUNC":
+                this.source_function = field_to_string(field);
+                break;
+            }
+        }
+
+        this.loggables.length = loggable_count;
+    }
+
+    /** Returns the record's loggables that aren't well-known. */
+    public Loggable[] get_other_loggables() {
+        fill_well_known_loggables();
+
+        Loggable[] copy = new Loggable[this.loggables.length];
+        int count = 0;
+        foreach (Loggable loggable in this.loggables) {
+            if (loggable != this.account &&
+                loggable != this.service &&
+                loggable != this.folder) {
+                copy[count++] = loggable;
+            }
+        }
+        copy.length = count;
+        return copy;
+    }
+
+    /**
+     * Sets the well-known loggable properties.
+     *
+     * Call this before trying to access {@link account}, {@link
+     * folder} and {@link service}. Determining these can be
+     * computationally complex and hence is not done by default.
+     */
+    public void fill_well_known_loggables() {
+        if (!this.filled) {
+            foreach (Loggable loggable in this.loggables) {
+                GLib.Type type = loggable.get_type();
+                if (type.is_a(typeof(Account))) {
+                    this.account = (Account) loggable;
+                } else if (type.is_a(typeof(ClientService))) {
+                    this.service = (ClientService) loggable;
+                } else if (type.is_a(typeof(Folder))) {
+                    this.folder = (Folder) loggable;
+                }
+            }
+            this.filled = true;
+        }
     }
 
     /** Returns a formatted string representation of this record. */
     public string format() {
+        fill_well_known_loggables();
+
+        string domain = this.domain ?? "[no domain]";
+        Flag flags = this.flags ?? Flag.NONE;
+        string message = this.message ?? "[no message]";
+        double float_secs = this.timestamp / 1000.0 / 1000.0;
+        double floor_secs = GLib.Math.floor(float_secs);
+        int ms = (int) GLib.Math.round((float_secs - floor_secs) * 1000.0);
         GLib.DateTime time = new GLib.DateTime.from_unix_utc(
-            this.timestamp / 1000 / 1000
+            (int64) float_secs
         ).to_local();
-        return "%s %02d:%02d:%02d %lf %s: %s".printf(
+        GLib.StringBuilder str = new GLib.StringBuilder.sized(128);
-            to_prefix(this.flags),
+        str.printf(
-            time.get_hour(), time.get_minute(), time.get_second(),
+            "%s %02d:%02d:%02d.%04d %s",
-            this.elapsed,
+            to_prefix(levels),
-            this.domain ?? "default",
+            time.get_hour(),
-            this.message
+            time.get_minute(),
+            time.get_second(),
+            ms,
+            domain
         );
+
+        if (flags != NONE && flags != ALL) {
+            str.printf("[%s]: ", flags.to_string());
+        } else {
+            str.append(": ");
+        }
+
+        // Use a compact format for well known ojects
+        if (this.account != null) {
+            str.append(this.account.information.id);
+            str.append_c('[');
+            str.append(this.account.information.service_provider.to_value());
+            if (this.service != null) {
+                str.append_c(':');
+                str.append(this.service.configuration.protocol.to_value());
+            }
+            str.append_c(']');
+            if (this.folder == null) {
+                str.append(": ");
+            }
+        } else if (this.service != null) {
+            str.append(this.service.configuration.protocol.to_value());
+            str.append(": ");
+        }
+        if (this.folder != null) {
+            str.append(this.folder.path.to_string());
+            str.append(": ");
+        }
+
+        foreach (Loggable loggable in get_other_loggables()) {
+            str.append(loggable.to_string());
+            str.append_c(' ');
+        }
+
+        str.append(message);
+
+
+        // XXX Don't append source details for the moment because of
+        // https://gitlab.gnome.org/GNOME/vala/issues/815
+        bool disabled = true;
+        if (!disabled && !this.old_log_api && this.source_filename != null) {
+            str.append(" [");
+            str.append(GLib.Path.get_basename(this.source_filename));
+            if (this.source_line_number != null) {
+                str.append_c(':');
+                str.append(this.source_line_number);
+            }
+            if (this.source_function != null) {
+                str.append_c(':');
+                str.append(this.source_function.to_string());
+            }
+            str.append("]");
+        }
+
+        return str.str;
     }
 
 }
@@ -104,8 +323,9 @@ public delegate void LogRecord(Record record);
 private int init_count = 0;
 private Flag logging_flags = Flag.NONE;
 private unowned FileStream? stream = null;
-private Timer? entry_timer = null;
 
+// Can't be nullable. See https://gitlab.gnome.org/GNOME/vala/issues/812
+private GLib.Mutex record_lock;
 private Record? first_record = null;
 private Record? last_record = null;
 private uint log_length = 0;
@@ -123,10 +343,27 @@ private unowned LogRecord? listener = null;
 public void init() {
     if (init_count++ != 0)
         return;
-    entry_timer = new Timer();
+    record_lock = GLib.Mutex();
     max_log_length = DEFAULT_MAX_LOG_BUFFER_LENGTH;
 }
 
+/**
+ * Clears all log records.
+ *
+ * Since log records hold references to Geary engine objects, it may
+ * be desirable to clear the records prior to shutdown so that the
+ * objects can be destroyed.
+ */
+public void clear() {
+    record_lock.lock();
+
+    first_record = null;
+    last_record = null;
+    log_length = 0;
+    
+    record_lock.unlock();
+}
+
 /**
  * Replaces the current logging flags with flags.  Use Geary.Logging.Flag.NONE to clear all
  * logging flags.
@@ -171,32 +408,41 @@ public inline bool are_all_flags_set(Flag flags) {
 
 [PrintfFormat]
 public inline void error(Flag flags, string fmt, ...) {
-    if (logging_flags.is_any_set(flags))
+    logv(flags, GLib.LogLevelFlags.LEVEL_ERROR, fmt, va_list());
-        logv(DOMAIN, LogLevelFlags.LEVEL_ERROR, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void critical(Flag flags, string fmt, ...) {
-    if (logging_flags.is_any_set(flags))
+    logv(flags, GLib.LogLevelFlags.LEVEL_CRITICAL, fmt, va_list());
-        logv(DOMAIN, LogLevelFlags.LEVEL_CRITICAL, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void warning(Flag flags, string fmt, ...) {
-    if (logging_flags.is_any_set(flags))
+    logv(flags, GLib.LogLevelFlags.LEVEL_WARNING, fmt, va_list());
-        logv(DOMAIN, LogLevelFlags.LEVEL_WARNING, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void message(Flag flags, string fmt, ...) {
-    if (logging_flags.is_any_set(flags))
+    logv(flags, GLib.LogLevelFlags.LEVEL_MESSAGE, fmt, va_list());
-        logv(DOMAIN, LogLevelFlags.LEVEL_MESSAGE, fmt, va_list());
 }
 
 [PrintfFormat]
 public inline void debug(Flag flags, string fmt, ...) {
-    if (logging_flags.is_any_set(flags)) {
+    logv(flags, GLib.LogLevelFlags.LEVEL_DEBUG, fmt, va_list());
-        logv(DOMAIN, LogLevelFlags.LEVEL_DEBUG, fmt, va_list());
+}
+
+public inline void logv(Flag flags,
+                        GLib.LogLevelFlags level,
+                        string fmt,
+                        va_list args) {
+    if (flags == ALL || logging_flags.is_any_set(flags)) {
+        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 });
     }
 }
 
@@ -217,19 +463,15 @@ public void log_to(FileStream? stream) {
     Logging.stream = stream;
 }
 
-public void default_handler(string? domain,
+
-                            LogLevelFlags log_levels,
+public GLib.LogWriterOutput default_log_writer(GLib.LogLevelFlags levels,
-                            string message) {
+                                               GLib.LogField[] fields) {
-    Record record = new Record(
+    // Obtain a lock since multiple threads can be calling this
-        domain,
+    // function at the same time
-        log_levels,
+    record_lock.lock();
-        GLib.get_real_time(),
-        entry_timer.elapsed(),
-        message
-    );
-    entry_timer.start();
 
     // Update the record linked list
+    Record record = new Record(fields, levels, GLib.get_real_time());
     if (first_record == null) {
         first_record = record;
         last_record = record;
@@ -247,15 +489,18 @@ public void default_handler(string? domain,
     }
 
     if (listener != null) {
-        listener(record);
+        GLib.MainContext.default().invoke(() => {
+                listener(record);
+                return GLib.Source.REMOVE;
+            });
     }
 
-    // Print to the output stream if needed
+    // Print a log message to the stream
     unowned FileStream? out = stream;
     if (out != null ||
-        ((LogLevelFlags.LEVEL_WARNING & log_levels) > 0) ||
+        LogLevelFlags.LEVEL_WARNING in levels ||
-        ((LogLevelFlags.LEVEL_CRITICAL & log_levels) > 0)  ||
+        LogLevelFlags.LEVEL_CRITICAL in levels  ||
-        ((LogLevelFlags.LEVEL_ERROR & log_levels) > 0)) {
+        LogLevelFlags.LEVEL_ERROR in levels) {
 
         if (out == null) {
             out = GLib.stderr;
@@ -264,8 +509,13 @@ public void default_handler(string? domain,
         out.puts(record.format());
         out.putc('\n');
     }
+
+    record_lock.unlock();
+
+    return GLib.LogWriterOutput.HANDLED;
 }
 
+
 private inline string to_prefix(LogLevelFlags level) {
     switch (level) {
     case LogLevelFlags.LEVEL_ERROR:
@@ -295,4 +545,14 @@ private inline string to_prefix(LogLevelFlags level) {
     }
 }
 
+private inline string? field_to_string(GLib.LogField field) {
+    string? value = null;
+    if (field.length < 0) {
+        value = (string) field.value;
+    } else if (field.length > 0) {
+        value = ((string) field.value).substring(0, field.length);
+    }
+    return value;
+}
+
 }

src/engine/imap-engine/gmail/imap-engine-gmail-folder.vala

@@ -68,7 +68,7 @@ private class Geary.ImapEngine.GmailFolder : MinimalFolder, FolderSupport.Archiv
         // messages are removed from all labels)
         Gee.Set<Imap.UID>? uids = yield folder.copy_email_uids_async(email_ids, trash.path, cancellable);
         if (uids == null || uids.size == 0) {
-            debug("%s: Can't true-remove %d emails, no COPYUIDs returned", folder.to_string(),
+            GLib.debug("%s: Can't true-remove %d emails, no COPYUIDs returned", folder.to_string(),
                 email_ids.size);
 
             return;
@@ -87,7 +87,7 @@ private class Geary.ImapEngine.GmailFolder : MinimalFolder, FolderSupport.Archiv
             yield account.release_folder_session(imap_trash);
         }
 
-        debug("%s: Successfully true-removed %d/%d emails", folder.to_string(), uids.size,
+        GLib.debug("%s: Successfully true-removed %d/%d emails", folder.to_string(), uids.size,
             email_ids.size);
     }
 }

src/engine/imap-engine/imap-engine-account-operation.vala

@@ -33,9 +33,17 @@
  * equal_to} method to specify which instances are considered to be
  * duplicates.
  */
-public abstract class Geary.ImapEngine.AccountOperation : Geary.BaseObject {
+public abstract class Geary.ImapEngine.AccountOperation : BaseObject, Loggable {
 
 
+    /** {@inheritDoc} */
+    public Logging.Flag loggable_flags {
+        get; protected set; default = Logging.Flag.ALL;
+    }
+
+    /** {@inheritDoc} */
+    public Loggable? loggable_parent { get { return account; } }
+
     /** The account this operation applies to. */
     protected weak Geary.Account account { get; private set; }
 
@@ -103,13 +111,9 @@ public abstract class Geary.ImapEngine.AccountOperation : Geary.BaseObject {
         return (op != null && (this == op || this.get_type() == op.get_type()));
     }
 
-    /**
+    /** {@inheritDoc} */
-     * Provides a representation of this operation for debugging.
-     *
-     * By default simply returns the name of the class.
-     */
     public virtual string to_string() {
-        return this.get_type().name();
+        return get_type().name();
     }
 
 }

src/engine/imap-engine/imap-engine-generic-account.vala

@@ -89,11 +89,13 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
         imap.notify["current-status"].connect(
             on_imap_status_notify
         );
+        imap.set_loggable_parent(this);
         this.imap = imap;
 
         smtp.outbox = new Outbox.Folder(this, local_folder_root, local);
         smtp.email_sent.connect(on_email_sent);
         smtp.report_problem.connect(notify_report_problem);
+        smtp.set_loggable_parent(this);
         this.smtp = smtp;
 
         this.sync = new AccountSynchronizer(this);
@@ -192,9 +194,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
         try {
             yield this.smtp.stop();
         } catch (Error err) {
-            debug(
+            debug("Error stopping SMTP service: %s", err.message);
-                "%s: Error stopping SMTP service: %s", to_string(), err.message
-            );
         }
 
         // Halt internal tasks early so they stop using local and
@@ -221,11 +221,11 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
         notify_folders_available_unavailable(null, remotes);
 
         foreach (Geary.Folder folder in locals) {
-            debug("%s: Waiting for local to close: %s", to_string(), folder.to_string());
+            debug("Waiting for local to close: %s", folder.to_string());
             yield folder.wait_for_close_async();
         }
         foreach (Geary.Folder folder in remotes) {
-            debug("%s: Waiting for remote to close: %s", to_string(), folder.to_string());
+            debug("Waiting for remote to close: %s", folder.to_string());
             yield folder.wait_for_close_async();
         }
 
@@ -234,9 +234,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
         try {
             yield this.imap.stop();
         } catch (Error err) {
-            debug(
+            debug("Error stopping IMAP service: %s", err.message);
-                "%s: Error stopping IMAP service: %s", to_string(), err.message
-            );
         }
         this.remote_ready_lock = null;
 
@@ -264,9 +262,9 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
             );
         }
 
-        message("%s: Rebuilding account local data", to_string());
+        message("Rebuilding account local data");
         yield this.local.delete_all_data(cancellable);
-        message("%s: Rebuild complete", to_string());
+        message("Rebuild complete");
     }
 
     /**
@@ -279,7 +277,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
     public void queue_operation(AccountOperation op)
         throws EngineError {
         check_open();
-        debug("%s: Enqueuing operation: %s", this.to_string(), op.to_string());
+        debug("Enqueuing operation: %s", op.to_string());
         this.processor.enqueue(op);
     }
 
@@ -297,7 +295,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
     public async Imap.AccountSession claim_account_session(Cancellable? cancellable = null)
         throws Error {
         check_open();
-        debug("%s: Acquiring account session", this.to_string());
+        debug("Acquiring account session");
         yield this.remote_ready_lock.wait_async(cancellable);
         Imap.ClientSession client =
             yield this.imap.claim_authorized_session_async(cancellable);
@@ -310,7 +308,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
      * Returns an IMAP account session to the pool for re-use.
      */
     public void release_account_session(Imap.AccountSession session) {
-        debug("%s: Releasing account session", this.to_string());
+        debug("Releasing account session");
         Imap.ClientSession? old_session = session.close();
         if (old_session != null) {
             this.imap.release_session_async.begin(
@@ -319,9 +317,9 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
                     try {
                         this.imap.release_session_async.end(res);
                     } catch (Error err) {
-                        debug("%s: Error releasing account session: %s",
+                        debug(
-                              to_string(),
+                            "Error releasing account session: %s", err.message
-                              err.message);
+                        );
                     }
                 }
             );
@@ -343,7 +341,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
                                                          Cancellable cancellable)
         throws Error {
         check_open();
-        debug("%s: Acquiring folder session", this.to_string());
+        debug("Acquiring folder session for: %s", path.to_string());
         yield this.remote_ready_lock.wait_async(cancellable);
 
         // We manually construct an account session here and then
@@ -394,14 +392,13 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
      * Returns an IMAP folder session to the pool for cleanup and re-use.
      */
     public async void release_folder_session(Imap.FolderSession session) {
-        debug("%s: Releasing folder session", this.to_string());
+        debug("Releasing folder session");
         Imap.ClientSession? old_session = session.close();
         if (old_session != null) {
             try {
                 yield this.imap.release_session_async(old_session);
             } catch (Error err) {
-                debug("%s: Error releasing %s session: %s",
+                debug("Error releasing %s session: %s",
-                      to_string(),
                       session.folder.path.to_string(),
                       err.message);
             }
@@ -623,7 +620,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
         Gee.Collection<Geary.Folder> folders =
             new Gee.LinkedList<Geary.Folder>();
         folders.add(folder);
-        debug("Contents altered!");
+        debug("Folder updated: %s", folder.path.to_string());
         notify_folders_contents_altered(folders);
     }
 
@@ -646,8 +643,8 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
         foreach (Geary.SpecialFolderType special in specials.keys) {
             MinimalFolder? minimal = specials.get(special) as MinimalFolder;
             if (minimal.special_folder_type != special) {
-                debug("%s: Promoting %s to %s",
+                debug("Promoting %s to %s",
-                      to_string(), minimal.to_string(), special.to_string());
+                      minimal.to_string(), special.to_string());
                 minimal.set_special_folder_type(special);
                 changed.add(minimal);
 
@@ -655,8 +652,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
                 try {
                     existing = get_special_folder(special) as MinimalFolder;
                 } catch (Error err) {
-                    debug("%s: Error getting special folder: %s",
+                    debug("Error getting special folder: %s", err.message);
-                          to_string(), err.message);
                 }
 
                 if (existing != null && existing != minimal) {
@@ -716,8 +712,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
             if (path != null) {
                 if (!remote.is_folder_path_valid(path)) {
                     warning(
-                        "%s: Ignoring bad special folder path '%s' for type %s",
+                        "Ignoring bad special folder path '%s' for type %s",
-                        to_string(),
                         path.to_string(),
                         type.to_string()
                     );
@@ -747,15 +742,15 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account {
                     path = root.get_child(search_names[0]);
                 }
 
-                debug("%s: Guessed folder \'%s\' for special_path %s",
+                debug("Guessed folder \'%s\' for special_path %s",
-                      to_string(), path.to_string(), type.to_string()
+                      path.to_string(), type.to_string()
                 );
                 information.set_special_folder_path(type, path);
             }
 
             if (!this.folder_map.has_key(path)) {
-                debug("%s: Creating \"%s\" to use as special folder %s",
+                debug("Creating \"%s\" to use as special folder %s",
-                      to_string(), path.to_string(), type.to_string());
+                      path.to_string(), type.to_string());
 
                 GLib.Error? created_err = null;
                 try {
@@ -1117,8 +1112,7 @@ internal class Geary.ImapEngine.LoadFolders : AccountOperation {
                         added_specials.set(type, target);
                     } catch (Error err) {
                         debug(
-                            "%s: Previously used special folder %s not loaded: %s",
+                            "Previously used special folder %s not loaded: %s",
-                            generic.information.id,
                             type.to_string(),
                             err.message
                         );
@@ -1224,7 +1218,7 @@ internal class Geary.ImapEngine.UpdateRemoteFolders : AccountOperation {
             if (err is IOError || err is ImapError)
                 throw err;
             debug("Ignoring error listing child folders of %s: %s",
-                (parent != null ? parent.to_string() : "root"), err.message);
+                  (parent != null ? parent.to_string() : "root"), err.message);
             results_suspect = true;
         }
 

src/engine/imap-engine/imap-engine-minimal-folder.vala

@@ -239,7 +239,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
     public async Imap.FolderSession claim_remote_session(Cancellable? cancellable = null)
         throws Error {
         check_open("claim_remote_session");
-        debug("%s: Claiming folder session", this.to_string());
+        debug("Claiming folder session");
 
 
         // If remote has not yet been opened and we are not in the
@@ -258,7 +258,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
     public override async bool close_async(Cancellable? cancellable = null)
         throws Error {
         check_open("close_async");
-        debug("%s: Scheduling folder close", this.to_string());
+        debug("Scheduling folder close");
         // Although it's inefficient in the case of just decrementing
         // the open count, pass all requests to close via the replay
         // queue so that other operations queued are interleaved in an
@@ -302,7 +302,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
     private async void normalize_folders(Geary.Imap.FolderSession session,
                                          Cancellable cancellable)
         throws Error {
-        debug("%s: Begin normalizing remote and local folders", to_string());
+        debug("Begin normalizing remote and local folders");
 
         Geary.Imap.FolderProperties local_properties = this.local_folder.get_properties();
         Geary.Imap.FolderProperties remote_properties = session.folder.properties;
@@ -341,7 +341,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         //
         // see http://tools.ietf.org/html/rfc3501#section-2.3.1.1
         if (local_properties.uid_validity.value != remote_properties.uid_validity.value) {
-            debug("%s: UID validity changed, detaching all email: %s -> %s", to_string(),
+            debug("UID validity changed, detaching all email: %s -> %s",
                 local_properties.uid_validity.value.to_string(),
                 remote_properties.uid_validity.value.to_string());
             yield detach_all_emails_async(cancellable);
@@ -366,7 +366,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
 
         // if no earliest UID, that means no messages in local store, so nothing to update
         if (local_earliest_id == null || local_latest_id == null) {
-            debug("%s: local store empty, nothing to normalize", to_string());
+            debug("local store empty, nothing to normalize");
             return;
         }
 
@@ -387,7 +387,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
 
         bool is_dirty = (already_marked_ids != null && already_marked_ids.size > 0);
         if (is_dirty)
-            debug("%s: %d remove markers found, folder is dirty", to_string(), already_marked_ids.size);
+            debug("%d remove markers found, folder is dirty",
+                  already_marked_ids.size);
 
         // a full normalize works from the highest possible UID on the remote and work down to the lowest UID on
         // the local; this covers all messages appended since last seen as well as any removed
@@ -396,9 +397,10 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // if either local UID is out of range of the current highest UID, then something very wrong
         // has occurred; the only recourse is to wipe all associations and start over
         if (local_earliest_id.uid.compare_to(last_uid) > 0 || local_latest_id.uid.compare_to(last_uid) > 0) {
-            debug("%s: Local UID(s) higher than remote UIDNEXT, detaching all email: %s/%s remote=%s",
+            debug("Local UID(s) higher than remote UIDNEXT, detaching all email: %s/%s remote=%s",
-                to_string(), local_earliest_id.uid.to_string(), local_latest_id.uid.to_string(),
+                  local_earliest_id.uid.to_string(),
-                last_uid.to_string());
+                  local_latest_id.uid.to_string(),
+                  last_uid.to_string());
             yield detach_all_emails_async(cancellable);
             return;
         }
@@ -419,7 +421,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // email is the same, then nothing has been added or removed,
         // and we're done.
         if (!is_dirty && uidnext_diff == 0 && local_message_count == remote_message_count) {
-            debug("%s: No messages added/removed since last opened, normalization completed", to_string());
+            debug("No messages added/removed since last opened, normalization completed");
             return;
         }
 
@@ -434,15 +436,15 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         if (!is_dirty && uidnext_diff == (remote_message_count - local_message_count)) {
             first_uid = local_latest_id.uid.next(true);
 
-            debug("%s: Messages only appended (local/remote UIDNEXT=%s/%s total=%d/%d diff=%s), gathering mail UIDs %s:%s",
+            debug("Messages only appended (local/remote UIDNEXT=%s/%s total=%d/%d diff=%s), gathering mail UIDs %s:%s",
-                to_string(), local_properties.uid_next.to_string(), remote_properties.uid_next.to_string(),
+                local_properties.uid_next.to_string(), remote_properties.uid_next.to_string(),
                 local_properties.select_examine_messages, remote_properties.select_examine_messages, uidnext_diff.to_string(),
                 first_uid.to_string(), last_uid.to_string());
         } else {
             first_uid = local_earliest_id.uid;
 
-            debug("%s: Messages appended/removed (local/remote UIDNEXT=%s/%s total=%d/%d diff=%s), gathering mail UIDs %s:%s",
+            debug("Messages appended/removed (local/remote UIDNEXT=%s/%s total=%d/%d diff=%s), gathering mail UIDs %s:%s",
-                to_string(), local_properties.uid_next.to_string(), remote_properties.uid_next.to_string(),
+                local_properties.uid_next.to_string(), remote_properties.uid_next.to_string(),
                 local_properties.select_examine_messages, remote_properties.select_examine_messages, uidnext_diff.to_string(),
                 first_uid.to_string(), last_uid.to_string());
         }
@@ -464,8 +466,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
 
         check_open("normalize_folders (list remote)");
 
-        debug("%s: Loaded local (%d) and remote (%d) UIDs, normalizing...", to_string(),
+        debug("Loaded local (%d) and remote (%d) UIDs, normalizing...",
-            local_uids.size, remote_uids.size);
+              local_uids.size, remote_uids.size);
 
         Gee.HashSet<Imap.UID> removed_uids = new Gee.HashSet<Imap.UID>();
         Gee.HashSet<Imap.UID> appended_uids = new Gee.HashSet<Imap.UID>();
@@ -503,8 +505,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
             }
         }, cancellable);
 
-        debug("%s: changes since last seen: removed=%d appended=%d inserted=%d", to_string(),
+        debug("Changes since last seen: removed=%d appended=%d inserted=%d",
-            removed_uids.size, appended_uids.size, inserted_uids.size);
+              removed_uids.size, appended_uids.size, inserted_uids.size);
 
         /*
          * Step 4: Synchronise local folder with remote
@@ -565,7 +567,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
                 }
             }, cancellable);
 
-            debug("%s: Finished creating/merging %d emails", to_string(), created_or_merged.size);
+            debug("Finished creating/merging %d emails", created_or_merged.size);
         }
 
         check_open("normalize_folders (created/merged appended/inserted emails)");
@@ -603,7 +605,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
             replay_queue.notify_remote_removed_ids(removed_ids);
 
             // notify subscribers about emails that have been removed
-            debug("%s: Notifying of %d removed emails since last opened", to_string(), removed_ids.size);
+            debug("Notifying of %d removed emails since last opened",
+                  removed_ids.size);
             notify_email_removed(removed_ids);
 
             count_change_reason |= Folder.CountChangeReason.REMOVED;
@@ -611,7 +614,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
 
         // notify inserted (new email located somewhere inside the local vector)
         if (inserted_ids.size > 0) {
-            debug("%s: Notifying of %d inserted emails since last opened", to_string(), inserted_ids.size);
+            debug("Notifying of %d inserted emails since last opened",
+                  inserted_ids.size);
             notify_email_inserted(inserted_ids);
 
             count_change_reason |= Folder.CountChangeReason.INSERTED;
@@ -620,8 +624,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // notify inserted (new email located somewhere inside the local vector that had to be
         // created, i.e. no portion was stored locally)
         if (locally_inserted_ids.size > 0) {
-            debug("%s: Notifying of %d locally inserted emails since last opened", to_string(),
+            debug("Notifying of %d locally inserted emails since last opened",
-                locally_inserted_ids.size);
+                  locally_inserted_ids.size);
             notify_email_locally_inserted(locally_inserted_ids);
 
             count_change_reason |= Folder.CountChangeReason.INSERTED;
@@ -629,29 +633,30 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
 
         // notify appended (new email added since the folder was last opened)
         if (appended_ids.size > 0) {
-            debug("%s: Notifying of %d appended emails since last opened", to_string(), appended_ids.size);
+            debug("Notifying of %d appended emails since last opened",
+                  appended_ids.size);
             notify_email_appended(appended_ids);
 
             count_change_reason |= Folder.CountChangeReason.APPENDED;
         }
 
-        // notify locally appended (new email never seen before added since the folder was last
+        // notify locally appended (new email never seen before added
-        // opened)
+        // since the folder was last opened)
         if (locally_appended_ids.size > 0) {
-            debug("%s: Notifying of %d locally appended emails since last opened", to_string(),
+            debug("Notifying of %d locally appended emails since last opened",
-                locally_appended_ids.size);
+                  locally_appended_ids.size);
             notify_email_locally_appended(locally_appended_ids);
 
             count_change_reason |= Folder.CountChangeReason.APPENDED;
         }
 
         if (count_change_reason != Folder.CountChangeReason.NONE) {
-            debug("%s: Notifying of %Xh count change reason (%d remote messages)", to_string(),
+            debug("Notifying of %Xh count change reason (%d remote messages)",
-                count_change_reason, remote_message_count);
+                  count_change_reason, remote_message_count);
             notify_email_count_changed(remote_message_count, count_change_reason);
         }
 
-        debug("%s: Completed normalize_folder", to_string());
+        debug("Completed normalize_folder");
     }
 
     /**
@@ -798,7 +803,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
             this.remote_open_timer.start();
         }
 
-        debug("%s: Folder opened", to_string());
+        debug("Folder opened");
         return true;
     }
 
@@ -828,7 +833,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
     private async void close_internal_locked(Folder.CloseReason local_reason,
                                              Folder.CloseReason remote_reason,
                                              Cancellable? cancellable) {
-        debug("%s: Folder closing", to_string());
+        debug("Folder closing");
 
         // Ensure we don't attempt to start opening a remote while
         // closing
@@ -872,15 +877,13 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // Close the replay queues; if a "clean" close, flush pending
         // operations so everything gets a chance to run; if forced
         // close, drop everything outstanding
-        debug("Closing replay queue for %s (flush_pending=%s): %s",
+        debug("Closing replay queue for (flush_pending=%s): %s",
-              to_string(), flush_pending.to_string(), this.replay_queue.to_string());
+              flush_pending.to_string(), this.replay_queue.to_string());
         try {
             yield this.replay_queue.close_async(flush_pending);
-            debug("Closed replay queue for %s: %s",
+            debug("Closed replay queue: %s", this.replay_queue.to_string());
-                  to_string(), this.replay_queue.to_string());
         } catch (Error err) {
-            debug("Error closing %s replay queue: %s",
+            warning("Error closing replay queue: %s", err.message);
-                  to_string(), err.message);
         }
 
         // Actually close the remote folder
@@ -905,7 +908,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // Notify waiting tasks
         this.closed_semaphore.blind_notify();
 
-        debug("%s: Folder closed", to_string());
+        debug("Folder closed");
     }
 
     /**
@@ -934,7 +937,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
 
     // Should only be called when remote_mutex is locked, i.e. use open_remote_session()
     private async void open_remote_session_locked(Cancellable? cancellable) {
-        debug("%s: Opening remote session", to_string());
+        debug("Opening remote session");
 
         // Note that any IOError.CANCELLED errors caught below do not
         // cause any error signals to be fired and do not force
@@ -1080,8 +1083,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // Use the session param rather than remote_session attr since
         // it may not be available yet
         int remote_count = session.folder.properties.email_total;
-        debug("%s on_remote_appended: remote_count=%d appended=%d",
+        debug("on_remote_appended: remote_count=%d appended=%d",
-              to_string(), remote_count, appended);
+              remote_count, appended);
 
         // from the new remote total and the old remote total, glean the SequenceNumbers of the
         // new email(s)
@@ -1106,7 +1109,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // Use the session param rather than remote_session attr since
         // it may not be available yet
         int remote_count = session.folder.properties.email_total;
-        debug("%s on_remote_updated: remote_count=%d position=%s", to_string(),
+        debug("on_remote_updated: remote_count=%d position=%s",
               remote_count, position.to_string());
 
         this.replay_queue.schedule_server_notification(
@@ -1119,8 +1122,8 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
         // Use the session param rather than remote_session attr since
         // it may not be available yet
         int remote_count = session.folder.properties.email_total;
-        debug("%s on_remote_removed: remote_count=%d position=%s",
+        debug("on_remote_removed: remote_count=%d position=%s",
-              to_string(), remote_count, position.to_string());
+              remote_count, position.to_string());
 
         // notify of removal to all pending replay operations
         replay_queue.notify_remote_removed_position(position);
@@ -1490,7 +1493,7 @@ private class Geary.ImapEngine.MinimalFolder : Geary.Folder, Geary.FolderSupport
 
             // Fetch e-mail from folder using force update, which will cause the cache to be bypassed
             // and the latest to be gotten from the server (updating the cache in the process)
-            debug("%s: fetching %d flags", this.to_string(), local_map.keys.size);
+            debug("Fetching %d flags", local_map.keys.size);
             Gee.List<Geary.Email>? list_remote = yield list_email_by_sparse_id_async(
                 local_map.keys,
                 Email.Field.FLAGS,

src/engine/imap/api/imap-client-service.vala

@@ -131,8 +131,7 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
         // this, but it's easy and works for now
         int attempts = 0;
         while (this.all_sessions.size > 0) {
-            debug("[%s] Waiting for client sessions to disconnect...",
+            debug("Waiting for client sessions to disconnect...");
-                  this.account.id);
             Timeout.add(250, this.stop.callback);
             yield;
 
@@ -208,8 +207,8 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
         // Don't check_open(), it's valid for this to be called when
         // is_running is false, that happens during mop-up
 
-        debug("[%s] Returning session with %d of %d free",
+        debug("Returning session with %d of %d free",
-              this.account.id, this.free_queue.size, this.all_sessions.size);
+              this.free_queue.size, this.all_sessions.size);
 
         bool too_many_free = (
             this.free_queue.size >= this.max_free_size &&
@@ -230,8 +229,8 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
                 try {
                     yield session.close_mailbox_async(pool_cancellable);
                 } catch (ImapError imap_error) {
-                    debug("[%s] Error attempting to close released session %s: %s",
+                    debug("Error attempting to close released session %s: %s",
-                          this.account.id, session.to_string(), imap_error.message);
+                          session.to_string(), imap_error.message);
                     free = false;
                 }
 
@@ -244,8 +243,7 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
             }
 
             if (free) {
-                debug("[%s] Unreserving session %s",
+                debug("Unreserving session %s", session.to_string());
-                      this.account.id, session.to_string());
                 this.free_queue.send(session);
             }
         }
@@ -302,20 +300,19 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
                 this.pool_cancellable
             );
         } catch (ImapError.UNAUTHENTICATED err) {
-            debug("[%s] Auth error adding new session to the pool: %s",
+            debug("Auth error adding new session to the pool: %s", err.message);
-                  this.account.id, err.message);
             notify_authentication_failed();
         } catch (GLib.TlsError.BAD_CERTIFICATE err) {
             // Don't notify of an error here, since the untrusted host
             // handler will be dealing with it already.
-            debug("[%s] TLS validation error adding new session to the pool: %s",
+            debug("TLS validation error adding new session to the pool: %s",
-                  this.account.id, err.message);
+                  err.message);
         } catch (GLib.IOError.CANCELLED err) {
             // Nothing to do here
         } catch (GLib.Error err) {
             Geary.ErrorContext context = new Geary.ErrorContext(err);
-            debug("[%s] Error creating new session for the pool: %s",
+            debug("Error creating new session for the pool: %s",
-                  this.account.id, context.format_full_error());
+                  context.format_full_error());
             notify_connection_failed(context);
         }
 
@@ -331,8 +328,8 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
                 notify_connected();
             } catch (GLib.Error err) {
                 Geary.ErrorContext context = new Geary.ErrorContext(err);
-                debug("[%s] Error adding new session to the pool: %s",
+                debug("Error adding new session to the pool: %s",
-                      this.account.id, context.format_full_error());
+                      context.format_full_error());
                 notify_connection_failed(context);
                 new_session.disconnect_async.begin(null);
                 this.close_pool.begin();
@@ -363,8 +360,7 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
             try {
                 yield remove_session_async(target);
             } catch (Error err) {
-                debug("[%s] Error removing unconnected session: %s",
+                debug("Error removing unconnected session: %s", err.message);
-                      this.account.id, err.message);
             }
             break;
 
@@ -402,7 +398,7 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
     }
 
     private async ClientSession create_new_authorized_session(Cancellable? cancellable) throws Error {
-        debug("[%s] Opening new session", this.account.id);
+        debug("Opening new session");
         Credentials? login = this.configuration.credentials;
         if (login != null && !login.is_complete()) {
             throw new ImapError.UNAUTHENTICATED("Token not loaded");
@@ -420,8 +416,8 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
             try {
                 yield new_session.disconnect_async(null);
             } catch (Error disconnect_err) {
-                debug("[%s] Error disconnecting due to session initiation failure, ignored: %s",
+                debug("Error disconnecting due to session initiation failure, ignored: %s",
-                    new_session.to_string(), disconnect_err.message);
+                      disconnect_err.message);
             }
 
             throw err;
@@ -462,13 +458,12 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
     }
 
     private async void force_disconnect(ClientSession session) {
-        debug("[%s] Dropping session %s", this.account.id, session.to_string());
+        debug("Dropping session %s", session.to_string());
 
         try {
             yield remove_session_async(session);
         } catch (Error err) {
-            debug("[%s] Error removing session: %s",
+            debug("Error removing session: %s", err.message);
-                  this.account.id, err.message);
         }
 
         // Don't wait for this to finish because we don't want to
@@ -499,8 +494,8 @@ internal class Geary.Imap.ClientService : Geary.ClientService {
                 try {
                     this.remove_session_async.end(res);
                 } catch (Error err) {
-                    debug("[%s] Error removing disconnected session: %s",
+                    debug("Error removing disconnected session: %s",
-                          this.account.id, err.message);
+                          err.message);
                 }
             }
         );

src/engine/imap/transport/imap-deserializer.vala

@@ -252,7 +252,7 @@ public class Geary.Imap.Deserializer : BaseObject {
 
         // wait for outstanding I/O to exit
         yield closed_semaphore.wait_async();
-        debug("[%s] Deserializer closed", to_string());
+        Logging.debug(Logging.Flag.DESERIALIZER, "[%s] Deserializer closed", to_string());
     }
 
     /**
@@ -808,7 +808,7 @@ public class Geary.Imap.Deserializer : BaseObject {
     }
 
     private uint on_eos() {
-        debug("[%s] EOS", to_string());
+        Logging.debug(Logging.Flag.DESERIALIZER, "[%s] EOS", to_string());
 
         // Per RFC 3501 7.1.5, we may get a EOS immediately after a
         // BYE, so flush any message being processed.
@@ -828,7 +828,7 @@ public class Geary.Imap.Deserializer : BaseObject {
         // only Cancellable allowed is internal used to notify when closed; all other errors should
         // be reported
         if (!(err is IOError.CANCELLED)) {
-            debug("[%s] input error: %s", to_string(), err.message);
+            Logging.debug(Logging.Flag.DESERIALIZER, "[%s] input error: %s", to_string(), err.message);
             receive_failure(err);
         }
 

src/engine/meson.build

@@ -307,6 +307,7 @@ geary_engine_vala_sources = files(
   'util/util-inet.vala',
   'util/util-iterable.vala',
   'util/util-js.vala',
+  'util/util-loggable.vala',
   'util/util-numeric.vala',
   'util/util-object.vala',
   'util/util-reference-semantics.vala',

src/engine/util/util-loggable.vala

@@ -0,0 +1,187 @@
+/*
+ * Copyright 2018-2019 Michael Gratton <mike@vee.net>
+ *
+ * This software is licensed under the GNU Lesser General Public License
+ * (version 2.1 or later). See the COPYING file in this distribution.
+ */
+
+/**
+ * Mixin interface for objects that support structured logging.
+ *
+ * Loggable objects provide both a standard means to obtain a string
+ * representation of the object for display to humans, and keep a weak
+ * reference to some parent loggable, enabling this context to be
+ * automatically added to logging calls. For example, if a Foo object
+ * is the loggable parent of a Bar object, log calls made by Bar will
+ * automatically be decorated with Foo.
+ */
+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_loggable(Loggable value) {
+            this.append("GEARY_LOGGABLE", 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.
+     */
+    public abstract Logging.Flag loggable_flags { get; protected set; }
+
+    /**
+     * The parent of this loggable.
+     *
+     * If not null, the parent and its ancestors recursively will be
+     * added to to log message context.
+     */
+    public abstract Loggable? loggable_parent { get; }
+
+    /**
+     * Returns a string representation of the service, for debugging.
+     */
+    public abstract string to_string();
+
+
+    /**
+     * Logs a debug-level log message with this object as context.
+     */
+    [PrintfFormat]
+    public inline void debug(string fmt, ...) {
+        log_structured(
+            this.loggable_flags, LogLevelFlags.LEVEL_DEBUG, fmt, va_list()
+        );
+    }
+
+    /**
+     * Logs a message-level log message with this object as context.
+     */
+    [PrintfFormat]
+    public inline void message(string fmt, ...) {
+        log_structured(
+            this.loggable_flags, LogLevelFlags.LEVEL_MESSAGE, fmt, va_list()
+        );
+    }
+
+    /**
+     * Logs a warning-level log message with this object as context.
+     */
+    [PrintfFormat]
+    public inline void warning(string fmt, ...) {
+        log_structured(
+            this.loggable_flags, LogLevelFlags.LEVEL_WARNING, fmt, va_list()
+        );
+    }
+
+    /**
+     * Logs a error-level log message with this object as context.
+     */
+    [PrintfFormat]
+    [NoReturn]
+    public inline void error(string fmt, ...) {
+        log_structured(
+            this.loggable_flags, LogLevelFlags.LEVEL_ERROR, fmt, va_list()
+        );
+    }
+
+    /**
+     * Logs a critical-level log message with this object as context.
+     */
+    [PrintfFormat]
+    public inline void critical(string fmt, ...) {
+        log_structured(
+            this.loggable_flags, LogLevelFlags.LEVEL_CRITICAL, fmt, va_list()
+        );
+    }
+
+    private inline void log_structured(Logging.Flag flags,
+                                       GLib.LogLevelFlags levels,
+                                       string fmt,
+                                       va_list args) {
+        Context context = Context(Logging.DOMAIN, flags, levels, fmt, args);
+        Loggable? decorated = this;
+        while (decorated != null) {
+            context.append_loggable(decorated);
+            decorated = decorated.loggable_parent;
+        }
+
+        GLib.log_structured_array(levels, context.to_array());
+    }
+
+}

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();

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',

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);