Log events to structured logging

- Rename `logger` to `structured_logger` to avoid confusion
with the `Logger` delivery option
- CLI: Interrupt/Terminal signal received
- Connection: Started, processing, idling, set mailbox, start TLS,
logged in, disconnected
- Mailbox: Delivery arbitrator
- Delivery options (postback/que/sidekiq): Message delivered
- Watcher: setup

lib/mail_room.rb

@@ -3,12 +3,12 @@
 require 'yaml'
 
 module MailRoom
-  def self.logger
-    @logger ||= StructuredLogger.new(STDOUT)
+  def self.structured_logger
+    @structured_logger ||= StructuredLogger.new(STDOUT)
   end
 
-  def self.logger=(logger)
-    @logger = (logger ? logger : StructuredLogger.new("/dev/null"))
+  def self.structured_logger=(structured_logger)
+    @structured_logger = (structured_logger ? structured_logger : StructuredLogger.new("/dev/null"))
   end
 end
 

lib/mail_room/cli.rb

@@ -42,10 +42,12 @@ def initialize(args)
     # Start the coordinator running, sets up signal traps
     def start
       Signal.trap(:INT) do
+        structured_logger.info("Interrupt signal received")
         coordinator.running = false
       end
 
       Signal.trap(:TERM) do
+        structured_logger.info("Terminate signal received")
         exit
       end
 

lib/mail_room/connection.rb

@@ -50,6 +50,7 @@ def wait
 
         process_mailbox
       rescue Net::IMAP::Error, IOError
+        MailRoom.structured_logger.warn("#{@mailbox.context} Disconnected. Resetting...")
         reset
         setup
       end
@@ -64,8 +65,13 @@ def reset
     end
 
     def setup
+      MailRoom.structured_logger.info("#{@mailbox.context} Starting TLS session")
       start_tls
+
+      MailRoom.structured_logger.info("#{@mailbox.context} Logging in to the mailbox")
       log_in
+
+      MailRoom.structured_logger.info("#{@mailbox.context} Setting the mailbox to #{@mailbox.name}")
       set_mailbox
     end
 
@@ -106,6 +112,7 @@ def idle_handler
     def idle
       return unless ready_to_idle?
 
+      MailRoom.structured_logger.info("#{@mailbox.context} Idling...")
       @idling = true
 
       imap.idle(@mailbox.idle_timeout, &idle_handler)
@@ -126,6 +133,8 @@ def stop_idling
     def process_mailbox
       return unless @new_message_handler
 
+      MailRoom.structured_logger.info("#{@mailbox.context} Processing started")
+
       msgs = new_messages
 
       msgs.
@@ -158,7 +167,12 @@ def new_messages
     # @return [Array<Integer>] message ids
     def new_message_ids
       # uid_search still leaves messages UNSEEN
-      imap.uid_search(@mailbox.search_command).select { |uid| @mailbox.deliver?(uid) }
+      all_unread = @imap.uid_search(@mailbox.search_command)
+      MailRoom.structured_logger.info("#{@mailbox.context} #{all_unread.count} new messages with ids: #{all_unread.join(', ')}")
+
+      to_deliver = all_unread.select { |uid| @mailbox.deliver?(uid) }
+      MailRoom.structured_logger.info("#{@mailbox.context} #{to_deliver.count} messages to be delivered by this mail_room instance.\n Their ids: #{all_unread.join(', ')}")
+      to_deliver
     end
 
     # @private

lib/mail_room/delivery/postback.rb

@@ -33,6 +33,7 @@ def deliver(message)
           # request.headers['Content-Type'] = 'text/plain'
         end
 
+        MailRoom.structured_logger.info("Message delivered to #{@delivery_options.delivery_url}")
         true
       end
     end

lib/mail_room/delivery/que.rb

@@ -34,6 +34,7 @@ def initialize(options)
       # @param message [String] the email message as a string, RFC822 format
       def deliver(message)
         queue_job(message)
+        MailRoom.structured_logger.info("Message pushed onto Que queue")
       end
 
       private

lib/mail_room/delivery/sidekiq.rb

@@ -35,6 +35,7 @@ def deliver(message)
 
         client.lpush("queue:#{options.queue}", JSON.generate(item))
 
+        MailRoom.structured_logger.info("Message pushed onto Sidekiq queue")
         true
       end
 

lib/mail_room/mailbox.rb

@@ -75,6 +75,8 @@ def arbitrator
     end
 
     def deliver?(uid)
+      MailRoom.structured_logger.info("#{context} Asking #{arbitrator.class.name} if we should deliver #{uid}")
+
       arbitrator.deliver?(uid)
     end
 
@@ -84,6 +86,7 @@ def deliver(message)
       body = message.attr['RFC822']
       return true unless body
 
+      MailRoom.structured_logger.info("#{context} Delivering #{message.attr['UID']} through #{delivery.class.name} (#{message.attr['RFC822.SIZE']} bytes)")
       delivery.deliver(body)
     end
 
@@ -92,6 +95,10 @@ def ssl_options
       replace_verify_mode(ssl)
     end
 
+    def context
+      "[#{self.email}-#{self.name}]:"
+    end
+
     def validate!
       if self[:idle_timeout] > IMAP_IDLE_TIMEOUT
         raise IdleTimeoutTooLarge.new("Please use an idle timeout smaller than #{29*60} to prevent IMAP server disconnects")

lib/mail_room/mailbox_watcher.rb

@@ -23,6 +23,7 @@ def running?
 
     # run the mailbox watcher
     def run
+      MailRoom.structured_logger.info("#{@mailbox.context} Setting up watcher")
       @running = true
 
       connection.on_new_message do |message|

spec/lib/mailbox_spec.rb

@@ -1,6 +1,8 @@
 require 'spec_helper'
 
 describe MailRoom::Mailbox do
+  let(:sample_message) { {'RFC822' => 'a message', 'UID' => 123} }
+
   describe "#deliver" do
     context "with arbitration_method of noop" do
       it 'arbitrates with a Noop instance' do
@@ -14,6 +16,18 @@
 
         expect(noop).to have_received(:deliver?).with(uid)
       end
+
+      it 'logs the arbitration' do
+        mailbox = MailRoom::Mailbox.new({:arbitration_method => 'noop'})
+        noop = stub(:deliver?)
+        MailRoom::Arbitration['noop'].stubs(:new => noop)
+
+        uid = 123
+
+        mailbox.deliver?(uid)
+
+        expect(noop).to have_received(:deliver?).with(uid)
+      end
     end
 
     context "with arbitration_method of redis" do
@@ -36,7 +50,7 @@
         noop = stub(:deliver)
         MailRoom::Delivery['noop'].stubs(:new => noop)
 
-        mailbox.deliver(stub(:attr => {'RFC822' => 'a message'}))
+        mailbox.deliver(stub(:attr => sample_message))
 
         expect(noop).to have_received(:deliver).with('a message')
       end
@@ -48,7 +62,7 @@
         logger = stub(:deliver)
         MailRoom::Delivery['logger'].stubs(:new => logger)
 
-        mailbox.deliver(stub(:attr => {'RFC822' => 'a message'}))
+        mailbox.deliver(stub(:attr => sample_message))
 
         expect(logger).to have_received(:deliver).with('a message')
       end
@@ -60,7 +74,7 @@
         postback = stub(:deliver)
         MailRoom::Delivery['postback'].stubs(:new => postback)
 
-        mailbox.deliver(stub(:attr => {'RFC822' => 'a message'}))
+        mailbox.deliver(stub(:attr => sample_message))
 
         expect(postback).to have_received(:deliver).with('a message')
       end
@@ -72,7 +86,7 @@
         letter_opener = stub(:deliver)
         MailRoom::Delivery['letter_opener'].stubs(:new => letter_opener)
 
-        mailbox.deliver(stub(:attr => {'RFC822' => 'a message'}))
+        mailbox.deliver(stub(:attr => sample_message))
 
         expect(letter_opener).to have_received(:deliver).with('a message')
       end

spec/spec_helper.rb

@@ -7,6 +7,7 @@
 require 'mocha/api'
 require 'bourne'
 require 'fakeredis/rspec'
+require 'mail_room/structured_logger'
 
 require File.expand_path('../../lib/mail_room', __FILE__)
 
@@ -20,4 +21,8 @@
   # the seed, which is printed after each run.
   #     --seed 1234
   config.order = 'random'
+
+  config.before do
+    MailRoom.structured_logger = MailRoom::StructuredLogger.new('/dev/null')
+  end
 end