Add structured logging

lib/mail_room.rb

@@ -12,3 +12,4 @@ module MailRoom
 require "mail_room/connection"
 require "mail_room/coordinator"
 require "mail_room/cli"
+require 'mail_room/structured_logging/structured_logger'

lib/mail_room/connection.rb

@@ -50,6 +50,7 @@ def wait
 
         process_mailbox
       rescue Net::IMAP::Error, IOError
+        @mailbox.structured_logger.warn({ context: @mailbox.context, action: "Disconnected. Resetting..." })
         reset
         setup
       end
@@ -64,8 +65,13 @@ def reset
     end
 
     def setup
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Starting TLS session" })
       start_tls
+
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Logging into mailbox" })
       log_in
+
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Setting mailbox" })
       set_mailbox
     end
 
@@ -106,6 +112,7 @@ def idle_handler
     def idle
       return unless ready_to_idle?
 
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Idling" })
       @idling = true
 
       imap.idle(@mailbox.idle_timeout, &idle_handler)
@@ -125,6 +132,7 @@ def stop_idling
 
     def process_mailbox
       return unless @new_message_handler
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Processing started" })
 
       msgs = new_messages
 
@@ -166,7 +174,11 @@ 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)
+
+      to_deliver = all_unread.select { |uid| @mailbox.deliver?(uid) }
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Getting new messages", unread: {count: all_unread.count, ids: all_unread}, to_be_delivered: { count: to_deliver.count, ids: all_unread } })
+      to_deliver
     end
 
     # @private

lib/mail_room/delivery/postback.rb

@@ -5,12 +5,13 @@ module Delivery
     # Postback Delivery method
     # @author Tony Pitale
     class Postback
-      Options = Struct.new(:delivery_url, :delivery_token) do
+      Options = Struct.new(:delivery_url, :delivery_token, :structured_logger) do
         def initialize(mailbox)
           delivery_url = mailbox.delivery_url || mailbox.delivery_options[:delivery_url]
           delivery_token = mailbox.delivery_token || mailbox.delivery_options[:delivery_token]
+          structured_logger = mailbox.structured_logger
 
-          super(delivery_url, delivery_token)
+          super(delivery_url, delivery_token, structured_logger)
         end
       end
 
@@ -33,6 +34,7 @@ def deliver(message)
           # request.headers['Content-Type'] = 'text/plain'
         end
 
+        @delivery_options.structured_logger.info({ delivery_method: 'Postback', action: 'message pushed', url: @delivery_options.delivery_url })
         true
       end
     end

lib/mail_room/delivery/que.rb

@@ -6,7 +6,7 @@ module Delivery
     # Que Delivery method
     # @author Tony Pitale
     class Que
-      Options = Struct.new(:host, :port, :database, :username, :password, :queue, :priority, :job_class) do
+      Options = Struct.new(:host, :port, :database, :username, :password, :queue, :priority, :job_class, :structured_logger) do
         def initialize(mailbox)
           host = mailbox.delivery_options[:host] || "localhost"
           port = mailbox.delivery_options[:port] || 5432
@@ -17,8 +17,9 @@ def initialize(mailbox)
           queue = mailbox.delivery_options[:queue] || ''
           priority = mailbox.delivery_options[:priority] || 100 # lowest priority for Que
           job_class = mailbox.delivery_options[:job_class]
+          structured_logger = mailbox.structured_logger
 
-          super(host, port, database, username, password, queue, priority, job_class)
+          super(host, port, database, username, password, queue, priority, job_class, structured_logger)
         end
       end
 
@@ -34,6 +35,7 @@ def initialize(options)
       # @param message [String] the email message as a string, RFC822 format
       def deliver(message)
         queue_job(message)
+        @options.structured_logger.info({ delivery_method: 'Que', action: 'message pushed' })
       end
 
       private

lib/mail_room/delivery/sidekiq.rb

@@ -8,15 +8,16 @@ module Delivery
     # Sidekiq Delivery method
     # @author Douwe Maan
     class Sidekiq
-      Options = Struct.new(:redis_url, :namespace, :sentinels, :queue, :worker) do
+      Options = Struct.new(:redis_url, :namespace, :sentinels, :queue, :worker, :structured_logger) do
         def initialize(mailbox)
           redis_url = mailbox.delivery_options[:redis_url] || "redis://localhost:6379"
           namespace = mailbox.delivery_options[:namespace]
           sentinels = mailbox.delivery_options[:sentinels]
           queue     = mailbox.delivery_options[:queue] || "default"
           worker    = mailbox.delivery_options[:worker]
+          structured_logger = mailbox.structured_logger
 
-          super(redis_url, namespace, sentinels, queue, worker)
+          super(redis_url, namespace, sentinels, queue, worker, structured_logger)
         end
       end
 
@@ -35,6 +36,7 @@ def deliver(message)
 
         client.lpush("queue:#{options.queue}", JSON.generate(item))
 
+        @options.structured_logger.info({ delivery_method: 'Sidekiq', action: 'message pushed' })
         true
       end
 

lib/mail_room/mailbox.rb

@@ -23,7 +23,8 @@ module MailRoom
     :location, # for letter_opener
     :delivery_options,
     :arbitration_method,
-    :arbitration_options
+    :arbitration_options,
+    :structured_logger_file_name,
   ]
 
   ConfigurationError = Class.new(RuntimeError)
@@ -53,7 +54,7 @@ module MailRoom
       :expunge_deleted => false,
       :delivery_options => {},
       :arbitration_method => 'noop',
-      :arbitration_options => {}
+      :arbitration_options => {},
     }
 
     # Store the configuration and require the appropriate delivery method
@@ -64,6 +65,10 @@ def initialize(attributes={})
       validate!
     end
 
+    def structured_logger
+      @structured_logger ||= MailRoom::StructuredLogging::StructuredLogger.new(structured_logger_file_name)
+    end
+
     def delivery_klass
       self[:delivery_klass] ||= Delivery[delivery_method]
     end
@@ -81,6 +86,8 @@ def arbitrator
     end
 
     def deliver?(uid)
+      structured_logger.info({context: context, uid: uid, action: "asking arbiter to deliver", arbitrator: arbitrator.class.name})
+
       arbitrator.deliver?(uid)
     end
 
@@ -90,6 +97,7 @@ def deliver(message)
       body = message.attr['RFC822']
       return true unless body
 
+      structured_logger.info({context: context, uid: message.attr['UID'], action: "sending to deliverer", deliverer: delivery.class.name, byte_size: message.attr['RFC822.SIZE']})
       delivery.deliver(body)
     end
 
@@ -98,6 +106,10 @@ def ssl_options
       replace_verify_mode(ssl)
     end
 
+    def context
+      { email: self.email, name: self.name }
+    end
+
     def validate!
       if self[:idle_timeout] > IMAP_IDLE_TIMEOUT
         raise IdleTimeoutTooLarge,

lib/mail_room/mailbox_watcher.rb

@@ -23,6 +23,7 @@ def running?
 
     # run the mailbox watcher
     def run
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Setting up watcher" })
       @running = true
 
       connection.on_new_message do |message|
@@ -40,6 +41,7 @@ def run
 
     # stop running, cleanup connection
     def quit
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Quitting connection..." })
       @running = false
 
       if @connection

lib/mail_room/structured_logging/structured_logger.rb

@@ -0,0 +1,26 @@
+require 'logger'
+require 'json'
+
+module MailRoom
+  module StructuredLogging
+    class StructuredLogger < Logger
+
+      def format_message(severity, timestamp, progname, message)
+        raise ArgumentError.new("Message must be a Hash") unless message.is_a? Hash
+
+        data = {}
+        data[:severity] = severity
+        data[:time] = timestamp || Time.now.to_s
+        # only accept a Hash
+        data.merge!(message)
+
+        data.to_json + "\n"
+      end
+
+      def noop?
+        # swallow any log messages if no logfile has been set up
+        @logdev.nil?
+      end
+    end
+  end
+end

spec/fixtures/test_config.yml

@@ -6,6 +6,7 @@
     :name: "inbox"
     :delivery_url: "http://localhost:3000/inbox"
     :delivery_token: "abcdefg"
+    :structured_logger_file_name: "logfile.log"
   -
     :email: "user2@gmail.com"
     :password: "password"

spec/lib/configuration_spec.rb

@@ -4,22 +4,37 @@
   let(:config_path) {File.expand_path('../fixtures/test_config.yml', File.dirname(__FILE__))}
 
   describe 'set_mailboxes' do
-    it 'parses yaml into mailbox objects' do
-      MailRoom::Mailbox.stubs(:new).returns('mailbox1', 'mailbox2')
+    context 'with config_path' do
+      let(:configuration) { MailRoom::Configuration.new(:config_path => config_path) }
 
-      configuration = MailRoom::Configuration.new(:config_path => config_path)
+      it 'parses yaml into mailbox objects' do
+        MailRoom::Mailbox.stubs(:new).returns('mailbox1', 'mailbox2')
 
-      expect(configuration.mailboxes).to eq(['mailbox1', 'mailbox2'])
+        expect(configuration.mailboxes).to eq(['mailbox1', 'mailbox2'])
+      end
+
+      it 'sets logger with filename if structured logfile is specified' do
+        mailbox_with_logfile = configuration.mailboxes[0]
+        expect(mailbox_with_logfile.structured_logger.noop?).to be_falsey
+      end
+
+      it 'sets logger to no-op if no structured logfile is specified' do
+        # this also matches existing behaviour, so should have no effect if someone upgrades from a previous version
+        mailbox_without_logfile = configuration.mailboxes[1]
+        expect(mailbox_without_logfile.structured_logger.noop?).to be_truthy
+      end
     end
 
-    it 'sets mailboxes to an empty set when config_path is missing' do
-      MailRoom::Mailbox.stubs(:new)
+    context 'without config_path' do
+      let(:configuration) { MailRoom::Configuration.new }
 
-      configuration = MailRoom::Configuration.new
+      it 'sets mailboxes to an empty set' do
+        MailRoom::Mailbox.stubs(:new)
 
-      expect(configuration.mailboxes).to eq([])
+        expect(configuration.mailboxes).to eq([])
 
-      expect(MailRoom::Mailbox).to have_received(:new).never
+        expect(MailRoom::Mailbox).to have_received(:new).never
+      end
     end
   end
 end

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
@@ -36,7 +38,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 +50,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 +62,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,15 +74,15 @@
         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
     end
 
     context "without an RFC822 attribute" do
       it "doesn't deliver the message" do
-        mailbox = build_mailbox({:delivery_method => 'noop'})
+        mailbox = build_mailbox({ name: "magic mailbox", delivery_method: 'noop' })
         noop = stub(:deliver)
         MailRoom::Delivery['noop'].stubs(:new => noop)
 
@@ -97,6 +99,20 @@
         expect(mailbox.ssl_options).to eq({:verify_mode => OpenSSL::SSL::VERIFY_NONE})
       end
     end
+
+    context 'structured logger setup' do
+      it 'sets up the logger correctly and does not error' do
+        mailbox = build_mailbox({ name: "magic mailbox", structured_logger_file_name: '/dev/null' })
+
+        expect{ mailbox.structured_logger.info(message: "asdf") }.not_to raise_error
+      end
+
+      it 'sets up the noop logger correctly and does not error' do
+        mailbox = build_mailbox({ name: "magic mailbox" })
+
+        expect{ mailbox.structured_logger.info(message: "asdf") }.not_to raise_error
+      end
+    end
   end
 
   describe "#validate!" do