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

@@ -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

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

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)
+#

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

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}"
+          ImapSyncLog.debug("Processing mailbox for group #{group.name} in db #{db}", group)
-          status = obj.process(
+          status = syncer.process(
-            idle: obj.can_idle? && status && status[:remaining] == 0,
+            idle: syncer.can_idle? && status && status[:remaining] == 0,
             old_emails_limit: status && status[:remaining] > 0 ? 0 : nil,
           )
 
-          if !obj.can_idle? && status[:remaining] == 0
+          if !syncer.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."
+            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
+        next if !SiteSetting.enable_imap
-          groups = Group.where.not(imap_mailbox_name: '').map { |group| [group.id, group] }.to_h
 
-          @sync_lock.synchronize do
+        groups = Group.with_imap_configured.map { |group| [group.id, group] }.to_h
-            @sync_data[db] ||= {}
 
-            # Kill threads for group's mailbox that are no longer synchronized.
+        @sync_lock.synchronize do
-            @sync_data[db].filter! do |group_id, data|
+          @sync_data[db] ||= {}
-              next true if groups[group_id] && data[:thread]&.alive? && !data[:obj]&.disconnected?
 
-              if !groups[group_id]
+          # Kill threads for group's mailbox that are no longer synchronized.
-                puts("[EmailSync] Killing thread for group (id = #{group_id}) because mailbox is no longer synced")
+          @sync_data[db].filter! do |group_id, data|
-              else
+            next true if groups[group_id] && data[:thread]&.alive? && !data[:syncer]&.disconnected?
-                puts("[EmailSync] Thread for group #{groups[group_id].name} (id = #{group_id}) is dead")
-              end
 
-              data[:thread].kill
+            if !groups[group_id]
-              data[:thread].join
+              ImapSyncLog.warn("Killing thread for group because mailbox is no longer synced", group_id)
-              data[:obj]&.disconnect!
+            else
-
+              ImapSyncLog.warn("Thread for group is dead", group_id)
-              false
             end
 
-            # Spawn new threads for groups that are now synchronized.
+            data[:thread].kill
-            groups.each do |group_id, group|
+            data[:thread].join
-              if !@sync_data[db][group_id]
+            data[:syncer]&.disconnect!
-                puts("[EmailSync] Starting thread for group #{group.name} (id = #{group.id}) and mailbox #{group.imap_mailbox_name}")
+
-                @sync_data[db][group_id] = {
+            false
-                  thread: start_thread(db, group), obj: nil
+          end
-                }
+
-              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

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
 

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

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