diff --git a/src/engine/imap-engine/imap-engine-generic-account.vala b/src/engine/imap-engine/imap-engine-generic-account.vala index ae9f0cb2..6f54c6a3 100644 --- a/src/engine/imap-engine/imap-engine-generic-account.vala +++ b/src/engine/imap-engine/imap-engine-generic-account.vala @@ -297,11 +297,10 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account { check_open(); debug("Acquiring account session"); yield this.remote_ready_lock.wait_async(cancellable); - Imap.ClientSession client = - yield this.imap.claim_authorized_session_async(cancellable); - return new Imap.AccountSession( - this.information.id, this.local.imap_folder_root, client - ); + var client = yield this.imap.claim_authorized_session_async(cancellable); + var session = new Imap.AccountSession(this.local.imap_folder_root, client); + session.set_logging_parent(this.imap); + return session; } /** @@ -351,8 +350,9 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account { Imap.ClientSession? client = yield this.imap.claim_authorized_session_async(cancellable); Imap.AccountSession account = new Imap.AccountSession( - this.information.id, this.local.imap_folder_root, client + this.local.imap_folder_root, client ); + account.set_logging_parent(this.imap); Imap.Folder? folder = null; GLib.Error? folder_err = null; @@ -368,8 +368,9 @@ private abstract class Geary.ImapEngine.GenericAccount : Geary.Account { if (folder_err == null) { try { folder_session = yield new Imap.FolderSession( - this.information.id, client, folder, cancellable + client, folder, cancellable ); + folder_session.set_logging_parent(this.imap); } catch (Error err) { folder_err = err; } diff --git a/src/engine/imap/api/imap-account-session.vala b/src/engine/imap/api/imap-account-session.vala index 63838b2f..ed713733 100644 --- a/src/engine/imap/api/imap-account-session.vala +++ b/src/engine/imap/api/imap-account-session.vala @@ -32,10 +32,8 @@ internal class Geary.Imap.AccountSession : Geary.Imap.SessionObject { private Gee.List? status_collector = null; - internal AccountSession(string account_id, - FolderRoot root, - ClientSession session) { - base("%s:account".printf(account_id), session); + internal AccountSession(FolderRoot root, ClientSession session) { + base(session); this.root = root; session.list.connect(on_list_data); @@ -228,8 +226,8 @@ internal class Geary.Imap.AccountSession : Geary.Imap.SessionObject { MailboxInformation mailbox_info = info_map.get(mailbox); if (response.status != Status.OK) { - message("Unable to get STATUS of %s: %s", mailbox.to_string(), response.to_string()); - message("STATUS command: %s", cmd.to_string()); + warning("Unable to get STATUS of %s: %s", mailbox.to_string(), response.to_string()); + warning("STATUS command: %s", cmd.to_string()); continue; } @@ -243,7 +241,7 @@ internal class Geary.Imap.AccountSession : Geary.Imap.SessionObject { } } if (status == null) { - message("Unable to get STATUS of %s: not returned from server", mailbox.to_string()); + warning("Unable to get STATUS of %s: not returned from server", mailbox.to_string()); continue; } status_results.remove(status); @@ -294,6 +292,16 @@ internal class Geary.Imap.AccountSession : Geary.Imap.SessionObject { return old_session; } + /** {@inheritDoc} */ + public override Logging.State to_logging_state() { + return new Logging.State( + this, + "%s, folder root: %s", + base.to_logging_state().format_message(), // XXX this is cruddy + this.root.to_string() + ); + } + // Performs a LIST against the server, returning the results private async Gee.List send_list_async(ClientSession session, FolderPath folder, diff --git a/src/engine/imap/api/imap-client-service.vala b/src/engine/imap/api/imap-client-service.vala index 724942f2..26d4aa6d 100644 --- a/src/engine/imap/api/imap-client-service.vala +++ b/src/engine/imap/api/imap-client-service.vala @@ -143,8 +143,7 @@ internal class Geary.Imap.ClientService : Geary.ClientService { } if (this.all_sessions.size > 0) { - debug("[%s] Cancelling remaining client sessions...", - this.account.id); + debug("Cancelling remaining client sessions..."); this.close_cancellable.cancel(); } } @@ -447,6 +446,7 @@ internal class Geary.Imap.ClientService : Geary.ClientService { } ClientSession new_session = new ClientSession(remote); + new_session.set_logging_parent(this); yield new_session.connect_async(cancellable); try { @@ -504,8 +504,7 @@ internal class Geary.Imap.ClientService : Geary.ClientService { } private async void disconnect_session(ClientSession session) { - debug("[%s] Logging out session %s", - this.account.id, session.to_string()); + debug("Logging out session: %s", session.to_string()); // Log out before removing the session since close() only // hangs around until all sessions have been removed before @@ -514,15 +513,14 @@ internal class Geary.Imap.ClientService : Geary.ClientService { yield session.logout_async(this.close_cancellable); yield remove_session_async(session); } catch (GLib.Error err) { - debug("[%s] Error logging out of session: %s", - this.account.id, err.message); + debug("Error logging out of session: %s", err.message); yield force_disconnect_session(session); } } private async void force_disconnect_session(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); @@ -552,6 +550,10 @@ internal class Geary.Imap.ClientService : Geary.ClientService { } private void on_disconnected(ClientSession session, ClientSession.DisconnectReason reason) { + debug( + "Session unexpected disconnect: %s: %s", + session.to_string(), reason.to_string() + ); this.remove_session_async.begin( session, (obj, res) => { diff --git a/src/engine/imap/api/imap-folder-session.vala b/src/engine/imap/api/imap-folder-session.vala index d07199b2..c94da4bc 100644 --- a/src/engine/imap/api/imap-folder-session.vala +++ b/src/engine/imap/api/imap-folder-session.vala @@ -32,11 +32,11 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { /** Determines if this folder immutable. */ public Trillian readonly { get; private set; default = Trillian.UNKNOWN; } - /** Determines if this folder accepts custom IMAP flags. */ - public Trillian accepts_user_flags { get; private set; default = Trillian.UNKNOWN; } + /** This folder's set of permanent IMAP flags. */ + public MessageFlags? permanent_flags { get; private set; default = null; } /** Determines if this folder accepts custom IMAP flags. */ - public MessageFlags? permanent_flags { get; private set; default = null; } + public Trillian accepts_user_flags { get; private set; default = Trillian.UNKNOWN; } /** * Set to true when it's detected that the server doesn't allow a @@ -87,12 +87,11 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { public signal void removed(SequenceNumber pos); - public async FolderSession(string account_id, - ClientSession session, + public async FolderSession(ClientSession session, Imap.Folder folder, Cancellable cancellable) throws Error { - base("%s:%s".printf(account_id, folder.path.to_string()), session); + base(session); this.folder = folder; if (folder.properties.attrs.is_no_select) { @@ -173,7 +172,7 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { } private void on_exists(int total) { - debug("%s EXISTS %d", to_string(), total); + debug("EXISTS %d", total); int old_total = this.folder.properties.select_examine_messages; this.folder.properties.set_select_examine_message_count(total); @@ -185,7 +184,7 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { } private void on_expunge(SequenceNumber pos) { - debug("%s EXPUNGE %s", to_string(), pos.to_string()); + debug("EXPUNGE %s", pos.to_string()); int old_total = this.folder.properties.select_examine_messages; if (old_total > 0) { @@ -206,15 +205,13 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { data.seq_num, (existing != null) ? data.combine(existing) : data ); } else { - debug("%s: FETCH (unsolicited): %s:", - to_string(), - data.to_string()); + debug("FETCH (unsolicited): %s:", data.to_string()); updated(data.seq_num, data); } } private void on_recent(int total) { - debug("%s RECENT %d", to_string(), total); + debug("RECENT %d", total); this.folder.properties.recent = total; recent(total); } @@ -227,11 +224,12 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { try { this.search_accumulator.add(new UID.checked(uid)); } catch (ImapError imaperr) { - debug("%s Unable to process SEARCH UID result: %s", to_string(), imaperr.message); + warning("Unable to process SEARCH UID result: %s", + imaperr.message); } } } else { - debug("%s Not handling unsolicited SEARCH response", to_string()); + debug("Not handling unsolicited SEARCH response"); } } @@ -280,8 +278,8 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { break; } } catch (ImapError ierr) { - debug("Unable to parse ResponseCode %s: %s", response_code.to_string(), - ierr.message); + warning("Unable to parse ResponseCode %s: %s", response_code.to_string(), + ierr.message); } } @@ -512,8 +510,7 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { if (retry_bad_header_fields_response(cmds)) { // The command failed, but it wasn't using the // header field hack, so retry it. - debug("Retryable server failure detected for %s: %s", - to_string(), err.message); + debug("Retryable server failure detected: %s", err.message); } else { throw err; } @@ -534,15 +531,14 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { // have come back with the response (if using UID addressing) UID? uid = fetched_data.data_map.get(FetchDataSpecifier.UID) as UID; if (uid == null) { - message("Unable to list message #%s on %s: No UID returned from server", - seq_num.to_string(), to_string()); + message("Unable to list message #%s: No UID returned from server", + seq_num.to_string()); continue; } try { Geary.Email email = fetched_data_to_email( - to_string(), uid, fetched_data, fields, @@ -552,9 +548,8 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { preview_charset_specifier ); if (!email.fields.fulfills(fields)) { - message( - "%s: %s missing=%s fetched=%s", - to_string(), + warning( + "%s missing=%s fetched=%s", email.id.to_string(), fields.clear(email.fields).to_string(), fetched_data.to_string() @@ -564,8 +559,10 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { email_list.add(email); } catch (Error err) { - debug("%s: Unable to convert email for %s %s: %s", to_string(), uid.to_string(), - fetched_data.to_string(), err.message); + warning("Unable to convert email for %s %s: %s", + uid.to_string(), + fetched_data.to_string(), + err.message); } } }, cancellable); @@ -685,7 +682,7 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { try { response.response_code.get_copyuid(null, out src_uids, out dst_uids); } catch (ImapError ierr) { - debug("Unable to retrieve COPYUID UIDs: %s", ierr.message); + warning("Unable to retrieve COPYUID UIDs: %s", ierr.message); } if (src_uids != null && !src_uids.is_empty && @@ -795,8 +792,7 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { } } - private static Geary.Email fetched_data_to_email( - string folder_name, + private Geary.Email fetched_data_to_email( UID uid, FetchedData fetched_data, Geary.Email.Field required_fields, @@ -890,12 +886,11 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { } } else { warning( - "[%s] No header specifier \"%s\" found in response:", - folder_name, + "No header specifier \"%s\" found in response:", header_specifier.to_string() ); foreach (FetchBodyDataSpecifier specifier in fetched_data.body_data_map.keys) { - message("[%s] - has %s", folder_name, specifier.to_string()); + warning(" - has %s", specifier.to_string()); } } } @@ -908,7 +903,7 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { try { date = new RFC822.Date(value); } catch (GLib.Error err) { - debug( + warning( "Error parsing date from FETCH response: %s", err.message ); @@ -1006,10 +1001,10 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { fetched_data.body_data_map.get(preview_charset_specifier), fetched_data.body_data_map.get(preview_specifier))); } else { - message("[%s] No preview specifiers \"%s\" and \"%s\" found", folder_name, + warning("No preview specifiers \"%s\" and \"%s\" found", preview_specifier.to_string(), preview_charset_specifier.to_string()); foreach (FetchBodyDataSpecifier specifier in fetched_data.body_data_map.keys) - message("[%s] has %s", folder_name, specifier.to_string()); + warning(" - has %s", specifier.to_string()); } } @@ -1042,10 +1037,10 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { ); } } else { - message("[%s] No body specifier \"%s\" found", folder_name, - body_specifier.to_string()); + warning("No body specifier \"%s\" found", + body_specifier.to_string()); foreach (FetchBodyDataSpecifier specifier in fetched_data.body_data_map.keys) - message("[%s] has %s", folder_name, specifier.to_string()); + warning(" - has %s", specifier.to_string()); } } @@ -1093,6 +1088,20 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { return null; } + /** {@inheritDoc} */ + public override Logging.State to_logging_state() { + return new Logging.State( + this, + "%s, %s, ro: %s, permanent_flags: %s, accepts_user_flags: %s", + base.to_logging_state().format_message(), // XXX this is cruddy + this.folder.to_string(), + this.readonly.to_string(), + this.permanent_flags != null + ? this.permanent_flags.to_string() : "(none)", + this.accepts_user_flags.to_string() + ); + } + // HACK: See https://bugzilla.gnome.org/show_bug.cgi?id=714902 // // Detect when a server has returned a BAD response to FETCH @@ -1130,14 +1139,13 @@ private class Geary.Imap.FolderSession : Geary.Imap.SessionObject { case Status.NO: throw new ImapError.NOT_SUPPORTED( - "Request %s failed on %s: %s", cmd.to_string(), - to_string(), response.to_string() + "Request %s failed: %s", cmd.to_string(), response.to_string() ); default: throw new ImapError.SERVER_ERROR( - "Unknown response status to %s on %s: %s", - cmd.to_string(), to_string(), response.to_string() + "Unknown response status to %s: %s", + cmd.to_string(), response.to_string() ); } } diff --git a/src/engine/imap/api/imap-folder.vala b/src/engine/imap/api/imap-folder.vala index 2144bab8..5e8028ce 100644 --- a/src/engine/imap/api/imap-folder.vala +++ b/src/engine/imap/api/imap-folder.vala @@ -31,4 +31,8 @@ internal class Geary.Imap.Folder : Geary.BaseObject { this.properties = properties; } + public string to_string() { + return "Imap.Folder(%s)".printf(path.to_string()); + } + } diff --git a/src/engine/imap/api/imap-session-object.vala b/src/engine/imap/api/imap-session-object.vala index 8391fde1..248f9b70 100644 --- a/src/engine/imap/api/imap-session-object.vala +++ b/src/engine/imap/api/imap-session-object.vala @@ -17,13 +17,21 @@ * * This class is ''not'' thread safe. */ -public abstract class Geary.Imap.SessionObject : BaseObject { +public abstract class Geary.Imap.SessionObject : BaseObject, Logging.Source { /** Determines if this object has a valid session or not. */ public bool is_valid { get { return this.session != null; } } - private string id; + /** {@inheritDoc} */ + public Logging.Flag logging_flags { + get; protected set; default = Logging.Flag.ALL; + } + + /** {@inheritDoc} */ + public Logging.Source? logging_parent { get { return _logging_parent; } } + private weak Logging.Source? _logging_parent = null; + private ClientSession? session; @@ -34,15 +42,14 @@ public abstract class Geary.Imap.SessionObject : BaseObject { /** * Constructs a new IMAP object with the given session. */ - protected SessionObject(string id, ClientSession session) { - this.id = id; + protected SessionObject(ClientSession session) { this.session = session; this.session.disconnected.connect(on_disconnected); } ~SessionObject() { if (close() != null) { - debug("%s: destroyed without releasing its session".printf(this.id)); + debug("Destroyed without releasing its session"); } } @@ -67,16 +74,19 @@ public abstract class Geary.Imap.SessionObject : BaseObject { return old_session; } - /** - * Returns a string representation of this object for debugging. - */ - public virtual string to_string() { - return "%s:%s".printf( - this.id, - this.session != null ? this.session.to_string() : "(session dropped)" + /** {@inheritDoc} */ + public virtual Logging.State to_logging_state() { + return new Logging.State( + this, + this.session != null ? this.session.to_string() : "no session" ); } + /** Sets the session's logging parent. */ + internal void set_logging_parent(Logging.Source parent) { + this._logging_parent = parent; + } + /** * Obtains IMAP session the server for use by this object. * @@ -93,7 +103,7 @@ public abstract class Geary.Imap.SessionObject : BaseObject { } private void on_disconnected(ClientSession.DisconnectReason reason) { - debug("%s: DISCONNECTED %s", to_string(), reason.to_string()); + debug("DISCONNECTED %s", reason.to_string()); close(); disconnected(reason); diff --git a/src/engine/imap/transport/imap-client-connection.vala b/src/engine/imap/transport/imap-client-connection.vala index fd9e2f1b..7513adb7 100644 --- a/src/engine/imap/transport/imap-client-connection.vala +++ b/src/engine/imap/transport/imap-client-connection.vala @@ -6,7 +6,7 @@ * (version 2.1 or later). See the COPYING file in this distribution. */ -public class Geary.Imap.ClientConnection : BaseObject { +public class Geary.Imap.ClientConnection : BaseObject, Logging.Source { /** * Default socket timeout duration. @@ -58,6 +58,16 @@ public class Geary.Imap.ClientConnection : BaseObject { */ public bool idle_when_quiet { get; private set; default = false; } + + /** {@inheritDoc} */ + public Logging.Flag logging_flags { + get; protected set; default = Logging.Flag.NETWORK; + } + + /** {@inheritDoc} */ + public Logging.Source? logging_parent { get { return _logging_parent; } } + private weak Logging.Source? _logging_parent = null; + private Geary.Endpoint endpoint; private SocketConnection? cx = null; private IOStream? ios = null; @@ -80,59 +90,56 @@ public class Geary.Imap.ClientConnection : BaseObject { public virtual signal void connected() { - Logging.debug(Logging.Flag.NETWORK, "[%s] connected to %s", to_string(), - endpoint.to_string()); + debug("Connected to %s", endpoint.to_string()); } public virtual signal void disconnected() { - Logging.debug(Logging.Flag.NETWORK, "[%s] disconnected from %s", to_string(), - endpoint.to_string()); + debug("Disconnected from %s", endpoint.to_string()); } public virtual signal void sent_command(Command cmd) { - Logging.debug(Logging.Flag.NETWORK, "[%s S] %s", to_string(), cmd.to_string()); + debug("SEND: %s", cmd.to_string()); } public virtual signal void received_status_response(StatusResponse status_response) { - Logging.debug(Logging.Flag.NETWORK, "[%s R] %s", to_string(), status_response.to_string()); + debug("RECV: %s", status_response.to_string()); } public virtual signal void received_server_data(ServerData server_data) { - Logging.debug(Logging.Flag.NETWORK, "[%s R] %s", to_string(), server_data.to_string()); + debug("RECV: %s", server_data.to_string()); } public virtual signal void received_continuation_response(ContinuationResponse continuation_response) { - Logging.debug(Logging.Flag.NETWORK, "[%s R] %s", to_string(), continuation_response.to_string()); + debug("RECV: %s", continuation_response.to_string()); } public virtual signal void received_bytes(size_t bytes) { // this generates a *lot* of debug logging if one was placed here, so it's not } - public virtual signal void received_bad_response(RootParameters root, ImapError err) { - Logging.debug(Logging.Flag.NETWORK, "[%s] recv bad response %s: %s", to_string(), - root.to_string(), err.message); + public virtual signal void received_bad_response(RootParameters root, + ImapError err) { + warning("Received bad response: %s", err.message); } public virtual signal void received_eos() { - Logging.debug(Logging.Flag.NETWORK, "[%s] recv eos", to_string()); + debug("Received eos"); } public virtual signal void send_failure(Error err) { - Logging.debug(Logging.Flag.NETWORK, "[%s] send failure: %s", to_string(), err.message); + warning("Send failure: %s", err.message); } public virtual signal void receive_failure(Error err) { - Logging.debug(Logging.Flag.NETWORK, "[%s] recv failure: %s", to_string(), err.message); + warning("Receive failure: %s", err.message); } public virtual signal void deserialize_failure(Error err) { - Logging.debug(Logging.Flag.NETWORK, "[%s] deserialize failure: %s", to_string(), - err.message); + warning("Deserialize failure: %s", err.message); } public virtual signal void close_error(Error err) { - Logging.debug(Logging.Flag.NETWORK, "[%s] close error: %s", to_string(), err.message); + warning("Close error: %s", err.message); } @@ -148,30 +155,22 @@ public class Geary.Imap.ClientConnection : BaseObject { ); } - public SocketAddress? get_remote_address() { - if (cx == null) - return null; - - try { - return cx.get_remote_address(); - } catch (Error err) { - debug("Unable to retrieve remote address: %s", err.message); + /** Returns the remote address of this connection, if any. */ + public GLib.SocketAddress? get_remote_address() throws GLib.Error { + GLib.SocketAddress? addr = null; + if (cx != null) { + addr = cx.get_remote_address(); } - - return null; + return addr; } - public SocketAddress? get_local_address() { - if (cx == null) - return null; - - try { - return cx.get_local_address(); - } catch (Error err) { - debug("Unable to retrieve local address: %s", err.message); + /** Returns the local address of this connection, if any. */ + public SocketAddress? get_local_address() throws GLib.Error { + GLib.SocketAddress? addr = null; + if (cx != null) { + addr = cx.get_local_address(); } - - return null; + return addr; } /** @@ -203,12 +202,12 @@ public class Geary.Imap.ClientConnection : BaseObject { } /** - * Returns silently if a connection is already established. + * Establishes a connection to the connection's endpoint. */ - public async void connect_async(Cancellable? cancellable = null) throws Error { + public async void connect_async(Cancellable? cancellable = null) + throws GLib.Error { if (this.cx != null) { - debug("Already connected/connecting to %s", to_string()); - return; + throw new ImapError.ALREADY_CONNECTED("Client already connected"); } this.cx = yield endpoint.connect_async(cancellable); @@ -258,10 +257,7 @@ public class Geary.Imap.ClientConnection : BaseObject { // Cancel any pending commands foreach (Command pending in this.pending_queue.get_all()) { - debug( - "[%s] Cancelling pending command: %s", - to_string(), pending.to_brief_string() - ); + debug("Cancelling pending command: %s", pending.to_brief_string()); pending.disconnected("Disconnected"); } this.pending_queue.clear(); @@ -269,36 +265,38 @@ public class Geary.Imap.ClientConnection : BaseObject { // close the actual streams and the connection itself Error? close_err = null; try { - debug("[%s] Disconnecting...", to_string()); yield ios.close_async(Priority.DEFAULT, cancellable); yield close_cx.close_async(Priority.DEFAULT, cancellable); - debug("[%s] Disconnected", to_string()); } catch (Error err) { - debug("[%s] Error disconnecting: %s", to_string(), err.message); close_err = err; } finally { ios = null; - if (close_err != null) + if (close_err != null) { close_error(close_err); + } disconnected(); } } - public async void starttls_async(Cancellable? cancellable = null) throws Error { - if (cx == null) - throw new ImapError.NOT_SUPPORTED("[%s] Unable to enable TLS: no connection", to_string()); + public async void starttls_async(Cancellable? cancellable = null) + throws GLib.Error { + if (cx == null) { + throw new ImapError.NOT_CONNECTED( + "Cannot start TLS when not connected" + ); + } // (mostly) silent fail in this case if (cx is TlsClientConnection) { - debug("[%s] Already TLS connection", to_string()); - - return; + throw new ImapError.NOT_SUPPORTED( + "Cannot start TLS when already established" + ); } // Close the Serializer/Deserializer, as need to use the TLS streams - debug("[%s] Closing serializer to switch to TLS", to_string()); + debug("Closing serializer to switch to TLS"); yield close_channels_async(cancellable); // wrap connection with TLS connection @@ -319,11 +317,14 @@ public class Geary.Imap.ClientConnection : BaseObject { cancel_idle(); } - public string to_string() { - return "%04X/%s/%s".printf( + /** {@inheritDoc} */ + public Logging.State to_logging_state() { + return new Logging.State( + this, + "%04X/%s/%s", cx_id, endpoint.to_string(), - this.cx != null ? "Connected" : "Disconnected" + this.cx != null ? "up" : "down" ); } @@ -346,6 +347,11 @@ public class Geary.Imap.ClientConnection : BaseObject { return sent; } + /** Sets the connection's logging parent. */ + internal void set_logging_parent(Logging.Source parent) { + this._logging_parent = parent; + } + private async void open_channels_async() throws Error { assert(ios != null); assert(ser == null); @@ -381,10 +387,7 @@ public class Geary.Imap.ClientConnection : BaseObject { // underlying streams are going away. this.open_cancellable.cancel(); foreach (Command sent in this.sent_queue) { - debug( - "[%s] Cancelling sent command: %s", - to_string(), sent.to_brief_string() - ); + debug("Cancelling sent command: %s", sent.to_brief_string()); sent.disconnected("Connection channels closed"); } this.sent_queue.clear(); @@ -517,8 +520,8 @@ public class Geary.Imap.ClientConnection : BaseObject { on_continuation_response((ContinuationResponse) response); } else { warning( - "[%s] Unknown ServerResponse of type %s received: %s:", - to_string(), response.get_type().name(), + "Unknown ServerResponse of type %s received: %s:", + response.get_type().name(), response.to_string() ); } @@ -619,11 +622,11 @@ public class Geary.Imap.ClientConnection : BaseObject { } private void on_idle_timeout() { - Logging.debug(Logging.Flag.NETWORK, "[%s] Initiating IDLE", to_string()); + debug("Initiating IDLE"); try { this.send_command(new IdleCommand()); } catch (ImapError err) { - debug("[%s] Error sending IDLE: %s", to_string(), err.message); + warning("Error sending IDLE: %s", err.message); } } diff --git a/src/engine/imap/transport/imap-client-session.vala b/src/engine/imap/transport/imap-client-session.vala index c368ab32..a40c5986 100644 --- a/src/engine/imap/transport/imap-client-session.vala +++ b/src/engine/imap/transport/imap-client-session.vala @@ -24,7 +24,7 @@ * sending a {@link LoginCommand}. Other commands can be sent via * {@link send_command_async} and {@link send_multiple_commands_async}. */ -public class Geary.Imap.ClientSession : BaseObject { +public class Geary.Imap.ClientSession : BaseObject, Logging.Source { /** * Maximum keep-alive interval required to maintain a session. @@ -187,7 +187,7 @@ public class Geary.Imap.ClientSession : BaseObject { } private static string state_to_string(uint state) { - return ((State) state).to_string(); + return ObjectUtils.to_enum_nick(typeof(State), state); } private enum Event { @@ -245,6 +245,14 @@ public class Geary.Imap.ClientSession : BaseObject { */ public int64 last_seen = 0; + /** {@inheritDoc} */ + public Logging.Flag logging_flags { + get; protected set; default = Logging.Flag.ALL; + } + + /** {@inheritDoc} */ + public Logging.Source? logging_parent { get { return _logging_parent; } } + private weak Logging.Source? _logging_parent = null; // While the following inbox and namespace data should be server // specific, there is a small chance they will differ between @@ -483,10 +491,8 @@ public class Geary.Imap.ClientSession : BaseObject { break; default: - warning("[%s] ClientSession ref dropped while still active", to_string()); + warning("ClientSession ref dropped while still active"); } - - debug("DTOR: ClientSession %s", to_string()); } public MailboxSpecifier? get_current_mailbox() { @@ -709,8 +715,10 @@ public class Geary.Imap.ClientSession : BaseObject { try { yield disconnect_async(cancellable); } catch (Error err) { - debug("[%s] Error disconnecting after a failed connect attempt: %s", to_string(), - err.message); + warning( + "Error disconnecting after a failed connect attempt: %s", + err.message + ); } throw connect_err; @@ -730,6 +738,7 @@ public class Geary.Imap.ClientSession : BaseObject { assert(cx == null); cx = new ClientConnection(imap_endpoint); + cx.set_logging_parent(this); cx.connected.connect(on_network_connected); cx.disconnected.connect(on_network_disconnected); cx.sent_command.connect(on_network_sent_command); @@ -775,9 +784,7 @@ public class Geary.Imap.ClientSession : BaseObject { } private uint on_connected(uint state, uint event) { - debug("[%s] Connected to %s", - to_string(), - imap_endpoint.to_string()); + debug("Connected to %s", imap_endpoint.to_string()); // stay in current state -- wait for initial status response // to move into NOAUTH or LOGOUT @@ -789,9 +796,7 @@ public class Geary.Imap.ClientSession : BaseObject { void *user = null, GLib.Object? obj = null, GLib.Error? err = null) { - debug("[%s] Disconnected from %s", - to_string(), - this.imap_endpoint.to_string()); + debug("Disconnected from %s", this.imap_endpoint.to_string()); return State.CLOSED; } @@ -802,8 +807,10 @@ public class Geary.Imap.ClientSession : BaseObject { try { connect_waiter.notify(); } catch (Error err) { - message("[%s] Unable to notify connect_waiter of connection: %s", to_string(), - err.message); + warning( + "Unable to notify connect_waiter of connection: %s", + err.message + ); } if (status_response.status == Status.OK) { @@ -812,8 +819,6 @@ public class Geary.Imap.ClientSession : BaseObject { return State.NOAUTH; } - debug("[%s] Connect denied: %s", to_string(), status_response.to_string()); - fsm.do_post_transition(() => { session_denied(status_response.get_text()); }); // Don't need to manually disconnect here, by setting @@ -830,12 +835,11 @@ public class Geary.Imap.ClientSession : BaseObject { try { connect_waiter.notify(); } catch (Error err) { - message("[%s] Unable to notify connect_waiter of timeout: %s", to_string(), - err.message); + warning( + "Unable to notify connect_waiter of timeout: %s", err.message + ); } - debug("[%s] Connect timed-out", to_string()); - // Don't need to manually disconnect here, by setting // connect_err here that will be done in connect_async this.connect_err = new IOError.TIMED_OUT( @@ -957,28 +961,15 @@ public class Geary.Imap.ClientSession : BaseObject { "STARTTLS unavailable for %s", to_string()); } - debug("[%s] Attempting STARTTLS...", to_string()); - StatusResponse resp; - try { - resp = yield send_command_async( - new StarttlsCommand(), cancellable - ); - } catch (Error err) { - debug( - "Error attempting STARTTLS command on %s: %s", - to_string(), err.message - ); - throw err; - } + debug("Attempting STARTTLS..."); + StatusResponse resp = yield send_command_async( + new StarttlsCommand(), cancellable + ); if (resp.status == Status.OK) { yield cx.starttls_async(cancellable); - debug("[%s] STARTTLS completed", to_string()); + debug("STARTTLS completed"); } else { - debug( - "[%s} STARTTLS refused: %s", - to_string(), resp.status.to_string() - ); // Throw an exception and fail rather than send // credentials under suspect conditions throw new ImapError.NOT_SUPPORTED( @@ -1009,7 +1000,7 @@ public class Geary.Imap.ClientSession : BaseObject { ); if (response.status == Status.OK && !server_data.is_empty) { this.inbox = server_data[0].get_list(); - debug("[%s] Using as INBOX: %s", to_string(), this.inbox.to_string()); + debug("Using INBOX: %s", this.inbox.to_string()); } else { throw new ImapError.INVALID("Unable to find INBOX"); } @@ -1027,14 +1018,16 @@ public class Geary.Imap.ClientSession : BaseObject { update_namespaces(ns.user, this.user_namespaces); update_namespaces(ns.shared, this.shared_namespaces); } else { - debug("[%s] NAMESPACE command failed", to_string()); + warning("NAMESPACE command failed"); } } server_data.clear(); if (!this.personal_namespaces.is_empty) { - debug("[%s] Default personal namespace: %s", to_string(), this.personal_namespaces[0].to_string()); + debug( + "Default personal namespace: %s", + this.personal_namespaces[0].to_string() + ); } else { - debug("[%s] Personal namespace not found, guessing it", to_string()); string? prefix = ""; string? delim = this.inbox.delim; if (!this.inbox.attrs.contains(MailboxAttribute.NO_INFERIORS) && @@ -1061,8 +1054,8 @@ public class Geary.Imap.ClientSession : BaseObject { } this.personal_namespaces.add(new Namespace(prefix, delim)); - debug("[%s] Personal namespace guessed as: %s", - to_string(), this.personal_namespaces[0].to_string()); + debug("Personal namespace not specified, guessed as: %s", + this.personal_namespaces[0].to_string()); } } finally { disconnect(data_id); @@ -1114,7 +1107,7 @@ public class Geary.Imap.ClientSession : BaseObject { return State.AUTHORIZED; default: - debug("[%s] Unable to LOGIN: %s", to_string(), completion_response.to_string()); + debug("LOGIN failed: %s", completion_response.to_string()); fsm.do_post_transition((resp) => { login_failed((StatusResponse)resp); }, completion_response); return State.NOAUTH; @@ -1226,7 +1219,7 @@ public class Geary.Imap.ClientSession : BaseObject { keepalive_id = 0; send_command_async.begin(new NoopCommand(), null, on_keepalive_completed); - Logging.debug(Logging.Flag.PERIODIC, "[%s] Sending keepalive...", to_string()); + log(PERIODIC, LEVEL_DEBUG, "Sending keepalive..."); // No need to reschedule keepalive, as the notification that the command was sent should // do that automatically @@ -1236,11 +1229,9 @@ public class Geary.Imap.ClientSession : BaseObject { private void on_keepalive_completed(Object? source, AsyncResult result) { try { - StatusResponse response = send_command_async.end(result); - Logging.debug(Logging.Flag.PERIODIC, "[%s] Keepalive result: %s", to_string(), - response.to_string()); - } catch (Error err) { - debug("[%s] Keepalive error: %s", to_string(), err.message); + send_command_async.end(result); + } catch (GLib.Error err) { + log(PERIODIC, LEVEL_WARNING, "Keepalive error: %s", err.message); } } @@ -1346,8 +1337,8 @@ public class Geary.Imap.ClientSession : BaseObject { break; case Status.BYE: - debug("[%s] Received unilateral BYE from server: %s", - to_string(), status_response.to_string()); + debug("Received unilateral BYE from server: %s", + status_response.to_string()); // nothing more we can do; drop connection and report disconnect to user cx.disconnect_async.begin(null, on_bye_disconnect_completed); @@ -1356,7 +1347,8 @@ public class Geary.Imap.ClientSession : BaseObject { break; default: - debug("[%s] Received error from server: %s", to_string(), status_response.to_string()); + debug("Received error from server: %s", + status_response.to_string()); break; } @@ -1454,7 +1446,8 @@ public class Geary.Imap.ClientSession : BaseObject { return State.SELECTED; default: - debug("[%s]: Unable to SELECT/EXAMINE: %s", to_string(), completion_response.to_string()); + warning("SELECT/EXAMINE failed: %s", + completion_response.to_string()); return State.AUTHORIZED; } } @@ -1510,7 +1503,7 @@ public class Geary.Imap.ClientSession : BaseObject { return State.AUTHORIZED; default: - debug("[%s] Unable to CLOSE: %s", to_string(), completion_response.to_string()); + warning("CLOSE failed: %s", completion_response.to_string()); return State.SELECTED; } @@ -1572,13 +1565,13 @@ public class Geary.Imap.ClientSession : BaseObject { case Status.BYE: // We're expecting this bye, but don't disconnect yet // since we'll do that when the command is complete - debug("[%s] Received bye from server on logout: %s", - to_string(), status_response.to_string()); + debug("Received bye from server on logout: %s", + status_response.to_string()); break; default: - debug("[%s] Received error from server on logout: %s", - to_string(), status_response.to_string()); + warning("Received error from server on logout: %s", + status_response.to_string()); break; } @@ -1623,6 +1616,35 @@ public class Geary.Imap.ClientSession : BaseObject { throw disconnect_err; } + /** {@inheritDoc} */ + public string to_string() { + string cx = ", " + ( + (this.cx != null) ? this.cx.to_string() : "not connected" + ); + return Logging.Source.default_to_string(this, cx); + } + + /** {@inheritDoc} */ + public Logging.State to_logging_state() { + return (this.current_mailbox == null) + ? new Logging.State( + this, + this.fsm.get_state_string(fsm.get_state()) + ) + : new Logging.State( + this, + "%s:%s %s", + this.fsm.get_state_string(fsm.get_state()), + this.current_mailbox.to_string(), + this.current_mailbox_readonly ? "RO" : "RW" + ); + } + + /** Sets the connection's logging parent. */ + internal void set_logging_parent(Logging.Source parent) { + this._logging_parent = parent; + } + private uint on_disconnect(uint state, uint event, void *user, Object? object) { MachineParams params = (MachineParams) object; @@ -1645,8 +1667,7 @@ public class Geary.Imap.ClientSession : BaseObject { void *user, GLib.Object? object, GLib.Error? err) { - debug("[%s] Connecting send/recv error, dropping client connection: %s", - to_string(), + debug("Connecting send/recv error, dropping client connection: %s", err != null ? err.message : "EOS"); fsm.do_post_transition(() => { drop_connection(); }); return State.CLOSED; @@ -1658,7 +1679,7 @@ public class Geary.Imap.ClientSession : BaseObject { if (err is IOError.CANCELLED) return state; - debug("[%s] Send error, disconnecting: %s", to_string(), err.message); + debug("Send error, disconnecting: %s", err.message); cx.disconnect_async.begin(null, on_fire_send_error_signal); @@ -1674,8 +1695,7 @@ public class Geary.Imap.ClientSession : BaseObject { void *user, GLib.Object? object, GLib.Error? err) { - debug("[%s] Receive error, disconnecting: %s", - to_string(), + debug("Receive error, disconnecting: %s", (err != null) ? err.message : "EOS" ); cx.disconnect_async.begin(null, on_fire_recv_error_signal); @@ -1687,16 +1707,13 @@ public class Geary.Imap.ClientSession : BaseObject { } private void dispatch_disconnect_results(DisconnectReason reason, AsyncResult result) { - debug("[%s] Disconnected due to %s", to_string(), reason.to_string()); - try { cx.disconnect_async.end(result); } catch (Error err) { - debug("[%s] Send/recv disconnect failed: %s", to_string(), err.message); + debug("Send/recv disconnect failed: %s", err.message); } drop_connection(); - disconnected(reason); } @@ -1745,8 +1762,9 @@ public class Geary.Imap.ClientSession : BaseObject { private uint on_dropped_response(uint state, uint event, void *user, Object? object) { ServerResponse server_response = (ServerResponse) object; - debug("[%s] Dropped server response at %s: %s", to_string(), fsm.get_event_issued_string(state, event), - server_response.to_string()); + debug("Dropped server response at %s: %s", + fsm.get_event_issued_string(state, event), + server_response.to_string()); return state; } @@ -1762,7 +1780,8 @@ public class Geary.Imap.ClientSession : BaseObject { } private uint on_ignored_transition(uint state, uint event) { - debug("[%s] Ignored transition: %s", to_string(), fsm.get_event_issued_string(state, event)); + debug("Ignored transition: %s", + fsm.get_event_issued_string(state, event)); return state; } @@ -1826,14 +1845,17 @@ public class Geary.Imap.ClientSession : BaseObject { try { if (response_code.get_response_code_type().is_value(ResponseCodeType.CAPABILITY)) { capabilities = response_code.get_capabilities(ref next_capabilities_revision); - debug("[%s] %s %s", to_string(), status_response.status.to_string(), + debug("%s %s", + status_response.status.to_string(), capabilities.to_string()); capability(capabilities); } - } catch (Error err) { - debug("[%s] Unable to convert response code to capabilities: %s", to_string(), - err.message); + } catch (GLib.Error err) { + warning( + "Unable to convert response code to capabilities: %s", + err.message + ); } } @@ -1855,8 +1877,9 @@ public class Geary.Imap.ClientSession : BaseObject { // update ClientSession capabilities before firing signal, so external signal // handlers that refer back to property aren't surprised capabilities = server_data.get_capabilities(ref next_capabilities_revision); - debug("[%s] %s %s", to_string(), server_data.server_data_type.to_string(), - capabilities.to_string()); + debug("%s %s", + server_data.server_data_type.to_string(), + capabilities.to_string()); capability(capabilities); break; @@ -1902,8 +1925,8 @@ public class Geary.Imap.ClientSession : BaseObject { case ServerDataType.LSUB: default: // do nothing - debug("[%s] Not notifying of unhandled server data: %s", to_string(), - server_data.to_string()); + debug("Not notifying of unhandled server data: %s", + server_data.to_string()); break; } @@ -1920,8 +1943,9 @@ public class Geary.Imap.ClientSession : BaseObject { try { notify_received_data(server_data); } catch (ImapError ierr) { - debug("[%s] Failure notifying of server data: %s %s", to_string(), server_data.to_string(), - ierr.message); + debug("Failure notifying of server data: %s %s", + server_data.to_string(), + ierr.message); } } @@ -1940,7 +1964,7 @@ public class Geary.Imap.ClientSession : BaseObject { } private void on_received_bad_response(RootParameters root, ImapError err) { - debug("[%s] Received bad response %s: %s", to_string(), root.to_string(), err.message); + debug("Received bad response %s: %s", root.to_string(), err.message); fsm.issue(Event.RECV_ERROR, null, null, err); } @@ -1952,12 +1976,4 @@ public class Geary.Imap.ClientSession : BaseObject { fsm.issue(Event.RECV_ERROR, null, null, err); } - public string to_string() { - if (cx == null) { - return "%s %s".printf(imap_endpoint.to_string(), fsm.get_state_string(fsm.get_state())); - } else { - return "%04X/%s %s".printf(cx.cx_id, imap_endpoint.to_string(), - fsm.get_state_string(fsm.get_state())); - } - } }