Configurable structured logging per mailbox

- Initial filename configurable in yml file
- No filename entry means no structured logging (current behaviour)
- Remove singleton structured logger in favour of per-mailbox logfiles

lib/mail_room.rb

@@ -3,13 +3,6 @@
 require 'yaml'
 
 module MailRoom
-  def self.structured_logger
-    @structured_logger ||= StructuredLogger.new(STDOUT)
-  end
-
-  def self.structured_logger=(structured_logger)
-    @structured_logger = (structured_logger ? structured_logger : StructuredLogger.new("/dev/null"))
-  end
 end
 
 require "mail_room/version"
@@ -20,4 +13,4 @@ def self.structured_logger=(structured_logger)
 require "mail_room/connection"
 require "mail_room/coordinator"
 require "mail_room/cli"
-require "mail_room/structured_logger"
+require 'mail_room/structured_logging/structured_logger'

lib/mail_room/cli.rb

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

lib/mail_room/connection.rb

@@ -50,7 +50,7 @@ def wait
 
         process_mailbox
       rescue Net::IMAP::Error, IOError
-        MailRoom.structured_logger.warn({ context: @mailbox.context, action: "Disconnected. Resetting..." })
+        @mailbox.structured_logger.warn({ context: @mailbox.context, action: "Disconnected. Resetting..." })
         reset
         setup
       end
@@ -65,13 +65,13 @@ def reset
     end
 
     def setup
-      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Starting TLS session" })
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Starting TLS session" })
       start_tls
 
-      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Logging into mailbox" })
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Logging into mailbox" })
       log_in
 
-      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Setting mailbox" })
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Setting mailbox" })
       set_mailbox
     end
 
@@ -112,7 +112,7 @@ def idle_handler
     def idle
       return unless ready_to_idle?
 
-      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Idling" })
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Idling" })
       @idling = true
 
       imap.idle(@mailbox.idle_timeout, &idle_handler)
@@ -132,7 +132,7 @@ def stop_idling
 
     def process_mailbox
       return unless @new_message_handler
-      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Processing started" })
+      @mailbox.structured_logger.info({ context: @mailbox.context, action: "Processing started" })
 
       msgs = new_messages
 
@@ -169,7 +169,7 @@ def new_message_ids
       all_unread = @imap.uid_search(@mailbox.search_command)
 
       to_deliver = all_unread.select { |uid| @mailbox.deliver?(uid) }
-      MailRoom.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 } })
+      @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
 

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,7 +34,7 @@ def deliver(message)
           # request.headers['Content-Type'] = 'text/plain'
         end
 
-        MailRoom.structured_logger.info({ delivery_method: 'Postback', action: 'message pushed', url: @delivery_options.delivery_url })
+        @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,7 +35,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({ delivery_method: 'Que', action: 'message pushed' })
+        @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,7 +36,7 @@ def deliver(message)
 
         client.lpush("queue:#{options.queue}", JSON.generate(item))
 
-        MailRoom.structured_logger.info({ delivery_method: 'Sidekiq', action: 'message pushed' })
+        @options.structured_logger.info({ delivery_method: 'Sidekiq', action: 'message pushed' })
         true
       end
 

lib/mail_room/mailbox.rb

@@ -21,7 +21,8 @@ module MailRoom
     :location, # for letter_opener
     :delivery_options,
     :arbitration_method,
-    :arbitration_options
+    :arbitration_options,
+    :structured_logger_file_name,
   ]
 
   IdleTimeoutTooLarge = Class.new(RuntimeError)
@@ -47,7 +48,7 @@ module MailRoom
       :delete_after_delivery => false,
       :delivery_options => {},
       :arbitration_method => 'noop',
-      :arbitration_options => {}
+      :arbitration_options => {},
     }
 
     # Store the configuration and require the appropriate delivery method
@@ -58,6 +59,10 @@ def initialize(attributes={})
       validate!
     end
 
+    def structured_logger
+      @structured_logger ||= MailRoom::StructuredLogging::StructuredLogger.new(structured_logger_file_name)
+    end
+
     def delivery_klass
       Delivery[delivery_method]
     end
@@ -75,7 +80,7 @@ def arbitrator
     end
 
     def deliver?(uid)
-      MailRoom.structured_logger.info({context: context, uid: uid, action: "asking arbiter to deliver", arbitrator: arbitrator.class.name})
+      structured_logger.info({context: context, uid: uid, action: "asking arbiter to deliver", arbitrator: arbitrator.class.name})
 
       arbitrator.deliver?(uid)
     end
@@ -86,7 +91,7 @@ def deliver(message)
       body = message.attr['RFC822']
       return true unless body
 
-      MailRoom.structured_logger.info({context: context, uid: message.attr['UID'], action: "sending to deliverer", deliverer: delivery.class.name, byte_size: message.attr['RFC822.SIZE']})
+      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
 

lib/mail_room/mailbox_watcher.rb

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

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

@@ -111,5 +111,19 @@
         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 = MailRoom::Mailbox.new({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 = MailRoom::Mailbox.new({ })
+
+        expect{ mailbox.structured_logger.info(message: "asdf") }.not_to raise_error
+      end
+    end
   end
 end

spec/lib/structured_logger_spec.rb → spec/lib/structured_logging/structured_logger_spec.rb

@@ -1,8 +1,8 @@
 require 'spec_helper'
-require 'mail_room/structured_logger'
+require 'mail_room/structured_logging/structured_logger'
 require 'json'
 
-describe MailRoom::StructuredLogger do
+describe MailRoom::StructuredLogging::StructuredLogger do
 
   subject { described_class.new $stdout }
 
@@ -42,6 +42,20 @@
     end
   end
 
+  describe '#noop?' do
+    it 'is a noop if the delivery log device is nil' do
+      noop_logger = MailRoom::StructuredLogging::StructuredLogger.new(nil)
+
+      expect(noop_logger.noop?).to be_truthy
+    end
+
+    it 'is not a noop if a logfile was provided' do
+      noop_logger = MailRoom::StructuredLogging::StructuredLogger.new(STDOUT)
+
+      expect(noop_logger.noop?).to be_falsey
+    end
+  end
+
   def json_matching(level, message)
     contents = {
         severity: level,

spec/spec_helper.rb

@@ -7,7 +7,7 @@
 require 'mocha/api'
 require 'bourne'
 require 'fakeredis/rspec'
-require 'mail_room/structured_logger'
+require 'mail_room/structured_logging/structured_logger'
 
 require File.expand_path('../../lib/mail_room', __FILE__)
 
@@ -21,8 +21,4 @@
   # 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