diff --git a/po/POTFILES.in b/po/POTFILES.in index cc42fb14..b73f99bf 100644 --- a/po/POTFILES.in +++ b/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 diff --git a/src/client/application/geary-application.vala b/src/client/application/geary-application.vala index f74369ba..e6e078f4 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(); @@ -661,6 +661,8 @@ public class GearyApplication : Gtk.Application { } quit(); + + Geary.Logging.clear(); Util.Date.terminate(); } diff --git a/src/engine/api/geary-account.vala b/src/engine/api/geary-account.vala index b0edd857..ad368170 100644 --- a/src/engine/api/geary-account.vala +++ b/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 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? get_containing_folders_async( Gee.Collection ids, Cancellable? cancellable) throws Error; - /** - * Used only for debugging. Should not be used for user-visible strings. - */ + /** {@inheritDoc} */ public virtual string to_string() { - return this.id; + return "%s(%s)".printf( + this.get_type().name(), + this.information.id + ); } /** Fires a {@link opened} signal. */ diff --git a/src/engine/api/geary-client-service.vala b/src/engine/api/geary-client-service.vala index 4fbae488..6f6da006 100644 --- a/src/engine/api/geary-client-service.vala +++ b/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( - "%s:%s %s", - this.account.id, - this.configuration.protocol.to_value(), - this.is_running ? "started" : "stopped" - ); + debug(this.is_running ? "Started" : "Stopped"); } private void on_current_status_notify() { - debug( - "%s:%s: status changed to: %s", - this.account.id, - this.configuration.protocol.to_value(), - this.current_status.to_value() - ); + debug("Status changed to: %s", this.current_status.to_value()); } private void on_connectivity_change() { diff --git a/src/engine/api/geary-folder.vala b/src/engine/api/geary-folder.vala index b6f57fc8..948b925f 100644 --- a/src/engine/api/geary-folder.vala +++ b/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; - /** - * Used for debugging. Should not be used for user-visible labels. - */ + /** {@inheritDoc} */ 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() + ); } + } diff --git a/src/engine/api/geary-logging.vala b/src/engine/api/geary-logging.vala index 652b7005..95a1cd7f 100644 --- a/src/engine/api/geary-logging.vala +++ b/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. */ - public string domain { get; private set; } + /** The GLib domain of the log message, if any. */ + 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 int64 timestamp; - private double elapsed; - private string message; + private Loggable[] loggables; + private bool filled = false; + private bool old_log_api = false; - internal Record(string domain, - LogLevelFlags flags, - int64 timestamp, - double elapsed, - string message) { - this.domain = domain; - this.flags = flags; + internal Record(GLib.LogField[] fields, + GLib.LogLevelFlags levels, + int64 timestamp) { + this.levels = levels; this.timestamp = timestamp; - this.elapsed = elapsed; - this.message = message; + this.old_log_api = ( + 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( - to_prefix(this.flags), - time.get_hour(), time.get_minute(), time.get_second(), - this.elapsed, - this.domain ?? "default", - this.message + GLib.StringBuilder str = new GLib.StringBuilder.sized(128); + str.printf( + "%s %02d:%02d:%02d.%04d %s", + to_prefix(levels), + time.get_hour(), + 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(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 (logging_flags.is_any_set(flags)) - 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 (logging_flags.is_any_set(flags)) - 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 (logging_flags.is_any_set(flags)) - 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 (logging_flags.is_any_set(flags)) { - logv(DOMAIN, LogLevelFlags.LEVEL_DEBUG, fmt, va_list()); + logv(flags, GLib.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 message = GLib.LogField(); + 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, - string message) { - Record record = new Record( - domain, - log_levels, - GLib.get_real_time(), - entry_timer.elapsed(), - message - ); - entry_timer.start(); + +public GLib.LogWriterOutput default_log_writer(GLib.LogLevelFlags levels, + GLib.LogField[] fields) { + // Obtain a lock since multiple threads can be calling this + // function at the same time + record_lock.lock(); // 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_CRITICAL & log_levels) > 0) || - ((LogLevelFlags.LEVEL_ERROR & log_levels) > 0)) { + LogLevelFlags.LEVEL_WARNING in levels || + LogLevelFlags.LEVEL_CRITICAL in levels || + 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; +} + } diff --git a/src/engine/imap-engine/gmail/imap-engine-gmail-folder.vala b/src/engine/imap-engine/gmail/imap-engine-gmail-folder.vala index bddcb9d9..4744f67c 100644 --- a/src/engine/imap-engine/gmail/imap-engine-gmail-folder.vala +++ b/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? 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); } } diff --git a/src/engine/imap-engine/imap-engine-account-operation.vala b/src/engine/imap-engine/imap-engine-account-operation.vala index ea9641b0..99a7fdb3 100644 --- a/src/engine/imap-engine/imap-engine-account-operation.vala +++ b/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())); } - /** - * Provides a representation of this operation for debugging. - * - * By default simply returns the name of the class. - */ + /** {@inheritDoc} */ public virtual string to_string() { - return this.get_type().name(); + return get_type().name(); } } diff --git a/src/engine/imap-engine/imap-engine-generic-account.vala b/src/engine/imap-engine/imap-engine-generic-account.vala index 719142f4..e734868f 100644 --- a/src/engine/imap-engine/imap-engine-generic-account.vala +++ b/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( - "%s: Error stopping SMTP service: %s", to_string(), err.message - ); + debug("Error stopping SMTP service: %s", 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( - "%s: Error stopping IMAP service: %s", to_string(), err.message - ); + debug("Error stopping IMAP service: %s", 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", - to_string(), - err.message); + debug( + "Error releasing account session: %s", 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", - to_string(), + debug("Error releasing %s session: %s", session.folder.path.to_string(), err.message); } @@ -623,7 +620,7 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account { Gee.Collection folders = new Gee.LinkedList(); 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", - to_string(), minimal.to_string(), special.to_string()); + debug("Promoting %s to %s", + 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", - to_string(), err.message); + debug("Error getting special folder: %s", 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", - to_string(), + "Ignoring bad special folder path '%s' for type %s", 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", - to_string(), path.to_string(), type.to_string() + debug("Guessed folder \'%s\' for special_path %s", + 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", - to_string(), path.to_string(), type.to_string()); + debug("Creating \"%s\" to use as special folder %s", + 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", - generic.information.id, + "Previously used special folder %s not loaded: %s", 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; } diff --git a/src/engine/imap-engine/imap-engine-minimal-folder.vala b/src/engine/imap-engine/imap-engine-minimal-folder.vala index f1c2c80b..b450f4ec 100644 --- a/src/engine/imap-engine/imap-engine-minimal-folder.vala +++ b/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", - to_string(), local_earliest_id.uid.to_string(), local_latest_id.uid.to_string(), - last_uid.to_string()); + debug("Local UID(s) higher than remote UIDNEXT, detaching all email: %s/%s remote=%s", + local_earliest_id.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", - to_string(), local_properties.uid_next.to_string(), remote_properties.uid_next.to_string(), + debug("Messages only appended (local/remote UIDNEXT=%s/%s total=%d/%d diff=%s), gathering mail UIDs %s:%s", + 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", - to_string(), local_properties.uid_next.to_string(), remote_properties.uid_next.to_string(), + debug("Messages appended/removed (local/remote UIDNEXT=%s/%s total=%d/%d diff=%s), gathering mail UIDs %s:%s", + 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(), - local_uids.size, remote_uids.size); + debug("Loaded local (%d) and remote (%d) UIDs, normalizing...", + local_uids.size, remote_uids.size); Gee.HashSet removed_uids = new Gee.HashSet(); Gee.HashSet appended_uids = new Gee.HashSet(); @@ -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(), - removed_uids.size, appended_uids.size, inserted_uids.size); + debug("Changes since last seen: removed=%d appended=%d inserted=%d", + 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(), - locally_inserted_ids.size); + debug("Notifying of %d locally inserted emails since last opened", + 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 - // opened) + // notify locally appended (new email never seen before added + // 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(), - locally_appended_ids.size); + debug("Notifying of %d locally appended emails since last opened", + 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(), - count_change_reason, remote_message_count); + debug("Notifying of %Xh count change reason (%d remote messages)", + 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", - to_string(), flush_pending.to_string(), this.replay_queue.to_string()); + debug("Closing replay queue for (flush_pending=%s): %s", + 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", - to_string(), this.replay_queue.to_string()); + debug("Closed replay queue: %s", this.replay_queue.to_string()); } catch (Error err) { - debug("Error closing %s replay queue: %s", - to_string(), err.message); + warning("Error closing replay queue: %s", 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", - to_string(), remote_count, appended); + debug("on_remote_appended: remote_count=%d appended=%d", + 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", - to_string(), remote_count, position.to_string()); + debug("on_remote_removed: remote_count=%d position=%s", + 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? list_remote = yield list_email_by_sparse_id_async( local_map.keys, Email.Field.FLAGS, diff --git a/src/engine/imap/api/imap-client-service.vala b/src/engine/imap/api/imap-client-service.vala index 24a1d0d2..f07a2379 100644 --- a/src/engine/imap/api/imap-client-service.vala +++ b/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...", - this.account.id); + debug("Waiting for client sessions to disconnect..."); 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", - this.account.id, this.free_queue.size, this.all_sessions.size); + debug("Returning session with %d of %d free", + 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", - this.account.id, session.to_string(), imap_error.message); + debug("Error attempting to close released session %s: %s", + 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", - this.account.id, session.to_string()); + debug("Unreserving session %s", 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", - this.account.id, err.message); + debug("Auth error adding new session to the pool: %s", 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", - this.account.id, err.message); + debug("TLS validation error adding new session to the pool: %s", + 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", - this.account.id, context.format_full_error()); + debug("Error creating new session for the pool: %s", + 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", - this.account.id, context.format_full_error()); + debug("Error adding new session to the pool: %s", + 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", - this.account.id, err.message); + debug("Error removing unconnected session: %s", 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", - new_session.to_string(), disconnect_err.message); + debug("Error disconnecting due to session initiation failure, ignored: %s", + 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", - this.account.id, err.message); + debug("Error removing session: %s", 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", - this.account.id, err.message); + debug("Error removing disconnected session: %s", + err.message); } } ); diff --git a/src/engine/imap/transport/imap-deserializer.vala b/src/engine/imap/transport/imap-deserializer.vala index 8ca8ec25..6959b09d 100644 --- a/src/engine/imap/transport/imap-deserializer.vala +++ b/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); } diff --git a/src/engine/meson.build b/src/engine/meson.build index d413e509..71815983 100644 --- a/src/engine/meson.build +++ b/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', diff --git a/src/engine/util/util-loggable.vala b/src/engine/util/util-loggable.vala new file mode 100644 index 00000000..d559f41b --- /dev/null +++ b/src/engine/util/util-loggable.vala @@ -0,0 +1,187 @@ +/* + * Copyright 2018-2019 Michael Gratton + * + * 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(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()); + } + +} 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);