From 4670b62969b5eed2ccf972d14cf20f10aabff2b9 Mon Sep 17 00:00:00 2001 From: Martin Brennan Date: Fri, 14 Aug 2020 12:01:31 +1000 Subject: [PATCH] DEV: IMAP log to database (#10435) Convert all IMAP logging to write to a database table for easier inspection. These logs are cleaned up daily if they are > 5 days old. Logs can easily be watched in dev by setting DISCOURSE_DEV_LOG_LEVEL=\"debug\" and running tail -f development.log | grep IMAP --- app/jobs/scheduled/cleanup_imap_sync_log.rb | 11 +++ app/models/group.rb | 2 + app/models/imap_sync_log.rb | 60 +++++++++++++++ .../20200813044955_create_imap_sync_log.rb | 16 ++++ lib/demon/email_sync.rb | 74 ++++++++++--------- lib/imap/providers/gmail.rb | 6 +- lib/imap/sync.rb | 39 ++++------ spec/jobs/cleanup_imap_sync_log_spec.rb | 20 +++++ 8 files changed, 166 insertions(+), 62 deletions(-) create mode 100644 app/jobs/scheduled/cleanup_imap_sync_log.rb create mode 100644 app/models/imap_sync_log.rb create mode 100644 db/migrate/20200813044955_create_imap_sync_log.rb create mode 100644 spec/jobs/cleanup_imap_sync_log_spec.rb diff --git a/app/jobs/scheduled/cleanup_imap_sync_log.rb b/app/jobs/scheduled/cleanup_imap_sync_log.rb new file mode 100644 index 00000000000..ac17cdd325f --- /dev/null +++ b/app/jobs/scheduled/cleanup_imap_sync_log.rb @@ -0,0 +1,11 @@ +# frozen_string_literal: true + +module Jobs + class CleanupImapSyncLog < ::Jobs::Scheduled + every 1.day + + def execute(args) + ImapSyncLog.where("created_at < ?", ImapSyncLog::RETAIN_LOGS_DAYS.days.ago).delete_all + end + end +end diff --git a/app/models/group.rb b/app/models/group.rb index 61a986443f9..358b089cc53 100644 --- a/app/models/group.rb +++ b/app/models/group.rb @@ -111,6 +111,8 @@ class Group < ActiveRecord::Base validates :mentionable_level, inclusion: { in: ALIAS_LEVELS.values } validates :messageable_level, inclusion: { in: ALIAS_LEVELS.values } + scope :with_imap_configured, -> { where.not(imap_mailbox_name: '') } + scope :visible_groups, Proc.new { |user, order, opts| groups = self.order(order || "name ASC") diff --git a/app/models/imap_sync_log.rb b/app/models/imap_sync_log.rb new file mode 100644 index 00000000000..7abf098647d --- /dev/null +++ b/app/models/imap_sync_log.rb @@ -0,0 +1,60 @@ +# frozen_string_literal: true + +class ImapSyncLog < ActiveRecord::Base + RETAIN_LOGS_DAYS = 5 + + belongs_to :group + + def self.levels + @levels ||= Enum.new( + debug: 1, + info: 2, + warn: 3, + error: 4 + ) + end + + def self.log(message, level, group_id = nil) + now = Time.now.strftime("%Y-%m-%d %H:%M:%S.%L") + new_log = create(message: message, level: ImapSyncLog.levels[level], group_id: group_id) + Rails.logger.send(level, "#{level[0].upcase}, [#{now}] [IMAP] (group_id #{group_id}) #{message}") + new_log + end + + def self.debug(message, group_or_id) + group_id = group_or_id.is_a?(Integer) ? group_or_id : group_or_id.id + log(message, :debug, group_id) + end + + def self.info(message, group_or_id) + group_id = group_or_id.is_a?(Integer) ? group_or_id : group_or_id.id + log(message, :info, group_id) + end + + def self.warn(message, group_or_id) + group_id = group_or_id.is_a?(Integer) ? group_or_id : group_or_id.id + log(message, :warn, group_id) + end + + def self.error(message, group_or_id) + group_id = group_or_id.is_a?(Integer) ? group_or_id : group_or_id.id + log(message, :error, group_id) + end +end + +# == Schema Information +# +# Table name: imap_sync_logs +# +# id :bigint not null, primary key +# level :integer +# message :string +# group_id :bigint +# created_at :datetime not null +# updated_at :datetime not null +# +# Indexes +# +# index_imap_sync_logs_on_group_id (group_id) +# index_imap_sync_logs_on_level (level) +# diff --git a/db/migrate/20200813044955_create_imap_sync_log.rb b/db/migrate/20200813044955_create_imap_sync_log.rb new file mode 100644 index 00000000000..96d786947cd --- /dev/null +++ b/db/migrate/20200813044955_create_imap_sync_log.rb @@ -0,0 +1,16 @@ +# frozen_string_literal: true + +class CreateImapSyncLog < ActiveRecord::Migration[6.0] + def change + create_table :imap_sync_logs do |t| + t.integer :level + t.string :message + t.bigint :group_id, null: true + + t.timestamps + end + + add_index :imap_sync_logs, :group_id + add_index :imap_sync_logs, :level + end +end diff --git a/lib/demon/email_sync.rb b/lib/demon/email_sync.rb index dbf6d6f22dc..f548e987653 100644 --- a/lib/demon/email_sync.rb +++ b/lib/demon/email_sync.rb @@ -23,28 +23,28 @@ class Demon::EmailSync < ::Demon::Base def start_thread(db, group) Thread.new do RailsMultisite::ConnectionManagement.with_connection(db) do - puts "[EmailSync] Thread started for group #{group.name} (id = #{group.id}) in db #{db}" + ImapSyncLog.debug("Thread started for group #{group.name} in db #{db}", group) begin - obj = Imap::Sync.new(group) + syncer = Imap::Sync.new(group) rescue Net::IMAP::NoResponseError => e group.update(imap_last_error: e.message) Thread.exit end - @sync_lock.synchronize { @sync_data[db][group.id][:obj] = obj } + @sync_lock.synchronize { @sync_data[db][group.id][:syncer] = syncer } status = nil idle = false while @running && group.reload.imap_mailbox_name.present? do - puts "[EmailSync] Processing IMAP mailbox for group #{group.name} (id = #{group.id}) in db #{db}" - status = obj.process( - idle: obj.can_idle? && status && status[:remaining] == 0, + ImapSyncLog.debug("Processing mailbox for group #{group.name} in db #{db}", group) + status = syncer.process( + idle: syncer.can_idle? && status && status[:remaining] == 0, old_emails_limit: status && status[:remaining] > 0 ? 0 : nil, ) - if !obj.can_idle? && status[:remaining] == 0 - puts "[EmailSync] Going to sleep for group #{group.name} (id = #{group.id}) in db #{db} to wait for new emails." + if !syncer.can_idle? && status[:remaining] == 0 + ImapSyncLog.debug("Going to sleep for group #{group.name} in db #{db} to wait for new emails", group) # Thread goes into sleep for a bit so it is better to return any # connection back to the pool. @@ -54,7 +54,7 @@ class Demon::EmailSync < ::Demon::Base end end - obj.disconnect! + syncer.disconnect! end end end @@ -70,7 +70,7 @@ class Demon::EmailSync < ::Demon::Base sync_data.each do |_, data| data[:thread].kill data[:thread].join - data[:obj]&.disconnect! rescue nil + data[:syncer]&.disconnect! rescue nil end end @@ -106,44 +106,46 @@ class Demon::EmailSync < ::Demon::Base sync_data.each do |_, data| data[:thread].kill data[:thread].join - data[:obj]&.disconnect! + data[:syncer]&.disconnect! end false end RailsMultisite::ConnectionManagement.each_connection do |db| - if SiteSetting.enable_imap - groups = Group.where.not(imap_mailbox_name: '').map { |group| [group.id, group] }.to_h + next if !SiteSetting.enable_imap - @sync_lock.synchronize do - @sync_data[db] ||= {} + groups = Group.with_imap_configured.map { |group| [group.id, group] }.to_h - # Kill threads for group's mailbox that are no longer synchronized. - @sync_data[db].filter! do |group_id, data| - next true if groups[group_id] && data[:thread]&.alive? && !data[:obj]&.disconnected? + @sync_lock.synchronize do + @sync_data[db] ||= {} - if !groups[group_id] - puts("[EmailSync] Killing thread for group (id = #{group_id}) because mailbox is no longer synced") - else - puts("[EmailSync] Thread for group #{groups[group_id].name} (id = #{group_id}) is dead") - end + # Kill threads for group's mailbox that are no longer synchronized. + @sync_data[db].filter! do |group_id, data| + next true if groups[group_id] && data[:thread]&.alive? && !data[:syncer]&.disconnected? - data[:thread].kill - data[:thread].join - data[:obj]&.disconnect! - - false + if !groups[group_id] + ImapSyncLog.warn("Killing thread for group because mailbox is no longer synced", group_id) + else + ImapSyncLog.warn("Thread for group is dead", group_id) end - # Spawn new threads for groups that are now synchronized. - groups.each do |group_id, group| - if !@sync_data[db][group_id] - puts("[EmailSync] Starting thread for group #{group.name} (id = #{group.id}) and mailbox #{group.imap_mailbox_name}") - @sync_data[db][group_id] = { - thread: start_thread(db, group), obj: nil - } - end + data[:thread].kill + data[:thread].join + data[:syncer]&.disconnect! + + false + end + + # Spawn new threads for groups that are now synchronized. + groups.each do |group_id, group| + if !@sync_data[db][group_id] + ImapSyncLog.debug("Starting thread for group #{group.name} mailbox #{group.imap_mailbox_name}", group) + + @sync_data[db][group_id] = { + thread: start_thread(db, group), + syncer: nil + } end end end diff --git a/lib/imap/providers/gmail.rb b/lib/imap/providers/gmail.rb index da327552924..8400cc53960 100644 --- a/lib/imap/providers/gmail.rb +++ b/lib/imap/providers/gmail.rb @@ -77,7 +77,7 @@ module Imap new_labels = labels.reject { |l| l == "\\Inbox" } store(email["UID"], "LABELS", labels, new_labels) end - Imap::Sync::Logger.log("[IMAP] Thread ID #{thread_id} (UID #{uid}) archived in Gmail mailbox for #{@username}") + ImapSyncLog.log("Thread ID #{thread_id} (UID #{uid}) archived in Gmail mailbox for #{@username}", :debug) end # Though Gmail considers the email thread unarchived if the first email @@ -94,7 +94,7 @@ module Imap end store(email["UID"], "LABELS", labels, new_labels) end - Imap::Sync::Logger.log("[IMAP] Thread ID #{thread_id} (UID #{uid}) unarchived in Gmail mailbox for #{@username}") + ImapSyncLog.log("Thread ID #{thread_id} (UID #{uid}) unarchived in Gmail mailbox for #{@username}", :debug) end def thread_id_from_uid(uid) @@ -116,7 +116,7 @@ module Imap email_uids_to_trash = emails_in_thread(thread_id).map { |e| e['UID'] } imap.uid_move(email_uids_to_trash, trash_mailbox) - Imap::Sync::Logger.log("[IMAP] Thread ID #{thread_id} (UID #{uid}) trashed in Gmail mailbox for #{@username}") + ImapSyncLog.log("Thread ID #{thread_id} (UID #{uid}) trashed in Gmail mailbox for #{@username}", :debug) { trash_uid_validity: open_trash_mailbox, email_uids_to_trash: email_uids_to_trash } end diff --git a/lib/imap/sync.rb b/lib/imap/sync.rb index ecad53a0d50..99ae2b995c0 100644 --- a/lib/imap/sync.rb +++ b/lib/imap/sync.rb @@ -4,16 +4,6 @@ require 'net/imap' module Imap class Sync - class Logger - def self.log(msg, level = :debug) - if ENV['DISCOURSE_EMAIL_SYNC_LOG_OVERRIDE'] == 'warn' - Rails.logger.warn(msg) - else - Rails.logger.send(level, msg) - end - end - end - def initialize(group, opts = {}) @group = group @provider = Imap::Providers::Detector.init_with_detected_provider(@group.imap_config) @@ -53,12 +43,12 @@ module Imap # If UID validity changes, the whole mailbox must be synchronized (all # emails are considered new and will be associated to existent topics # in Email::Reciever by matching Message-Ids). - Logger.log("[IMAP] (#{@group.name}) UIDVALIDITY = #{@status[:uid_validity]} does not match expected #{@group.imap_uid_validity}, invalidating IMAP cache and resyncing emails for group #{@group.name} and mailbox #{@group.imap_mailbox_name}", :warn) + ImapSyncLog.warn("UIDVALIDITY = #{@status[:uid_validity]} does not match expected #{@group.imap_uid_validity}, invalidating IMAP cache and resyncing emails for mailbox #{@group.imap_mailbox_name}", @group) @group.imap_last_uid = 0 end if idle && !can_idle? - Logger.log("[IMAP] (#{@group.name}) IMAP server for group cannot IDLE", :warn) + ImapSyncLog.warn("IMAP server for group cannot IDLE or imap idle site setting is disabled", @group) idle = false end @@ -70,7 +60,7 @@ module Imap ActiveRecord::Base.connection_handler.clear_active_connections! idle_polling_mins = SiteSetting.imap_polling_period_mins.minutes.to_i - Logger.log("[IMAP] (#{@group.name}) Going IDLE for #{idle_polling_mins} seconds to wait for more work") + ImapSyncLog.debug("Going IDLE for #{idle_polling_mins} seconds to wait for more work", @group) @provider.imap.idle(idle_polling_mins) do |resp| if resp.kind_of?(Net::IMAP::UntaggedResponse) && resp.name == 'EXISTS' @@ -92,7 +82,7 @@ module Imap # Sometimes, new_uids contains elements from old_uids. new_uids = new_uids - old_uids - Logger.log("[IMAP] (#{@group.name}) Remote email server has #{old_uids.size} old emails and #{new_uids.size} new emails") + ImapSyncLog.debug("Remote email server has #{old_uids.size} old emails and #{new_uids.size} new emails", @group) all_old_uids_size = old_uids.size all_new_uids_size = new_uids.size @@ -134,7 +124,7 @@ module Imap private def process_old_uids(old_uids) - Logger.log("[IMAP] (#{@group.name}) Syncing #{old_uids.size} randomly-selected old emails") + ImapSyncLog.debug("Syncing #{old_uids.size} randomly-selected old emails", @group) emails = old_uids.empty? ? [] : @provider.emails(old_uids, ['UID', 'FLAGS', 'LABELS', 'ENVELOPE']) emails.each do |email| incoming_email = IncomingEmail.find_by( @@ -161,7 +151,7 @@ module Imap ) update_topic(email, incoming_email, mailbox_name: @group.imap_mailbox_name) else - Logger.log("[IMAP] (#{@group.name}) Could not find old email (UIDVALIDITY = #{@status[:uid_validity]}, UID = #{email['UID']})", :warn) + ImapSyncLog.warn("Could not find old email (UIDVALIDITY = #{@status[:uid_validity]}, UID = #{email['UID']})", @group) end end end @@ -204,18 +194,18 @@ module Imap # not exist, and this sync is just updating the old UIDs to the new ones # in the trash, and we don't need to re-destroy the post if incoming.post - Logger.log("[IMAP] (#{@group.name}) Deleting post ID #{incoming.post_id}; it has been deleted on the IMAP server.") + ImapSyncLog.debug("Deleting post ID #{incoming.post_id}, topic id #{incoming.topic_id}; email has been deleted on the IMAP server.", @group) PostDestroyer.new(Discourse.system_user, incoming.post).destroy end # the email has moved mailboxes, we don't want to try trashing again next time - Logger.log("[IMAP] (#{@group.name}) Updating incoming ID #{incoming.id} uid data FROM [UID #{incoming.imap_uid} | UIDVALIDITY #{incoming.imap_uid_validity}] TO [UID #{matching_trashed.uid} | UIDVALIDITY #{response.trash_uid_validity}] (TRASHED)") + ImapSyncLog.debug("Updating incoming ID #{incoming.id} uid data FROM [UID #{incoming.imap_uid} | UIDVALIDITY #{incoming.imap_uid_validity}] TO [UID #{matching_trashed.uid} | UIDVALIDITY #{response.trash_uid_validity}] (TRASHED)", @group) incoming.update(imap_uid_validity: response.trash_uid_validity, imap_uid: matching_trashed.uid) end end def process_new_uids(new_uids, import_mode, all_old_uids_size, all_new_uids_size) - Logger.log("[IMAP] (#{@group.name}) Syncing #{new_uids.size} new emails (oldest first)") + ImapSyncLog.debug("Syncing #{new_uids.size} new emails (oldest first)", @group) emails = @provider.emails(new_uids, ['UID', 'FLAGS', 'LABELS', 'RFC822']) processed = 0 @@ -242,7 +232,7 @@ module Imap update_topic(email, receiver.incoming_email, mailbox_name: @group.imap_mailbox_name) rescue Email::Receiver::ProcessingError => e - Logger.log("[IMAP] (#{@group.name}) Could not process (UIDVALIDITY = #{@status[:uid_validity]}, UID = #{email['UID']}): #{e.message}", :warn) + ImapSyncLog.warn("Could not process (UIDVALIDITY = #{@status[:uid_validity]}, UID = #{email['UID']}): #{e.message}", @group) end processed += 1 @@ -262,7 +252,7 @@ module Imap if to_sync.size > 0 @provider.open_mailbox(@group.imap_mailbox_name, write: true) to_sync.each do |incoming_email| - Logger.log("[IMAP] (#{@group.name}) Updating email and incoming email ID = #{incoming_email.id}") + ImapSyncLog.debug("Updating email on IMAP server for incoming email ID = #{incoming_email.id}, UID = #{incoming_email.imap_uid}", @group) update_email(incoming_email) incoming_email.update(imap_sync: false) end @@ -276,8 +266,10 @@ module Imap email_is_archived = !email['LABELS'].include?('\\Inbox') && !email['LABELS'].include?('INBOX') if topic_is_archived && !email_is_archived + ImapSyncLog.debug("Unarchiving topic ID #{topic.id}, email was unarchived", @group) GroupArchivedMessage.move_to_inbox!(@group.id, topic, skip_imap_sync: true) elsif !topic_is_archived && email_is_archived + ImapSyncLog.debug("Archiving topic ID #{topic.id}, email was archived", @group) GroupArchivedMessage.archive!(@group.id, topic, skip_imap_sync: true) end end @@ -346,6 +338,7 @@ module Imap if !topic # no need to do anything further here, we will recognize the UIDs in the # mail server email thread have been trashed on next sync + ImapSyncLog.debug("Trashing UID #{incoming_email.imap_uid} (incoming ID #{incoming_email.id})", @group) return @provider.trash(incoming_email.imap_uid) end @@ -358,12 +351,12 @@ module Imap # at the same time. new_labels << "\\Inbox" - Logger.log("[IMAP] (#{@group.name}) Unarchiving UID #{incoming_email.imap_uid}") + ImapSyncLog.debug("Unarchiving UID #{incoming_email.imap_uid} (incoming ID #{incoming_email.id})", @group) # some providers need special handling for unarchiving too @provider.unarchive(incoming_email.imap_uid) else - Logger.log("[IMAP] (#{@group.name}) Archiving UID #{incoming_email.imap_uid}") + ImapSyncLog.debug("Archiving UID #{incoming_email.imap_uid} (incoming ID #{incoming_email.id})", @group) # some providers need special handling for archiving. this way we preserve # any new tag-labels, and archive, even though it may cause extra requests diff --git a/spec/jobs/cleanup_imap_sync_log_spec.rb b/spec/jobs/cleanup_imap_sync_log_spec.rb new file mode 100644 index 00000000000..e2a8091b795 --- /dev/null +++ b/spec/jobs/cleanup_imap_sync_log_spec.rb @@ -0,0 +1,20 @@ +# frozen_string_literal: true + +require 'rails_helper' + +describe Jobs::CleanupImapSyncLog do + let(:job_class) { Jobs::CleanupImapSyncLog.new } + + it "deletes logs older than RETAIN_LOGS_DAYS" do + log1 = ImapSyncLog.log("Test log 1", :debug) + log2 = ImapSyncLog.log("Test log 2", :debug) + log3 = ImapSyncLog.log("Test log 3", :debug) + + log2.update(created_at: Time.now - 6.days) + log3.update(created_at: Time.now - 7.days) + + job_class.execute({}) + + expect(ImapSyncLog.count).to eq(1) + end +end