DEV: IMAP log to database (#10435)

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

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 0000000..ac17cdd
--- /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 61a9864..358b089 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 0000000..7abf098
--- /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 0000000..96d7869
--- /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 dbf6d6f..f548e98 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}")

[... diff too long, it was truncated ...]

GitHub sha: 4670b629

This commit appears in #10435 which was merged by martin.

For reloading purposes you might want to add ||= here.

2 Likes

If your numbers are sequential starting with 1 you can get away only providing the keys here. Enum.new(:debug, :info, :warn, :error)

Did you mean to make level and message nullable? It seems to me they shouldn’t be.

1 Like

It’s dangerous to rescue nil like this because it’ll end up trapping exceptions you didn’t expect. It’s better to rescue the explicit exceptions that disconnecting can cause.

1 Like

Can use 6.days.ago here, it’s infinitesimally better :slight_smile:

2 Likes

Opened a PR for this, will merge when green DEV: Review fixes for ImapSyncLog by martin-brennan · Pull Request #10641 · discourse/discourse · GitHub