Allow StructuredLogger to only accept a Hash

- Standardise structured log inputs for action, context,
delivery_option, byte size, uid...

lib/mail_room/cli.rb

@@ -42,12 +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")
+        structured_logger.info(action: "Interrupt signal received")
         coordinator.running = false
       end
 
       Signal.trap(:TERM) do
-        structured_logger.info("Terminate signal received")
+        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("#{@mailbox.context} Disconnected. Resetting...")
+        MailRoom.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("#{@mailbox.context} Starting TLS session")
+      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Starting TLS session" })
       start_tls
 
-      MailRoom.structured_logger.info("#{@mailbox.context} Logging in to the mailbox")
+      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Logging into mailbox" })
       log_in
 
-      MailRoom.structured_logger.info("#{@mailbox.context} Setting the mailbox to #{@mailbox.name}")
+      MailRoom.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("#{@mailbox.context} Idling...")
+      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Idling" })
       @idling = true
 
       imap.idle(@mailbox.idle_timeout, &idle_handler)
@@ -132,8 +132,7 @@ def stop_idling
 
     def process_mailbox
       return unless @new_message_handler
-
-      MailRoom.structured_logger.info("#{@mailbox.context} Processing started")
+      MailRoom.structured_logger.info({ context: @mailbox.context, action: "Processing started" })
 
       msgs = new_messages
 
@@ -168,10 +167,9 @@ def new_messages
     def new_message_ids
       # uid_search still leaves messages UNSEEN
       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(', ')}")
+      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 } })
       to_deliver
     end
 

lib/mail_room/delivery/postback.rb

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

lib/mail_room/delivery/que.rb

@@ -34,7 +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")
+        MailRoom.structured_logger.info({ delivery_method: 'Que', action: 'message pushed' })
       end
 
       private

lib/mail_room/delivery/sidekiq.rb

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

lib/mail_room/mailbox.rb

@@ -75,7 +75,7 @@ def arbitrator
     end
 
     def deliver?(uid)
-      MailRoom.structured_logger.info("#{context} Asking #{arbitrator.class.name} if we should deliver #{uid}")
+      MailRoom.structured_logger.info({context: context, uid: uid, action: "asking arbiter to deliver", arbitrator: arbitrator.class.name})
 
       arbitrator.deliver?(uid)
     end
@@ -86,7 +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)")
+      MailRoom.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
 
@@ -96,7 +96,7 @@ def ssl_options
     end
 
     def context
-      "[#{self.email}-#{self.name}]:"
+      { email: self.email, name: self.name }
     end
 
     def validate!

lib/mail_room/mailbox_watcher.rb

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

lib/mail_room/structured_logger.rb

@@ -5,15 +5,13 @@ module MailRoom
   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
-
-      if message.is_a? String
-        data[:message] = message
-      elsif message.is_a? Hash
-        data.merge!(message)
-      end
+      # only accept a Hash
+      data.merge!(message)
 
       data.to_json + "\n"
     end

spec/lib/structured_logger_spec.rb

@@ -7,7 +7,7 @@
   subject { described_class.new $stdout }
 
   let!(:now) { Time.now }
-  let(:message) { 'testing 123' }
+  let(:message) { { action: 'exciting development', message: 'testing 123' } }
 
   before do
     Time.stubs(:now).returns(now)
@@ -23,6 +23,10 @@
     expect { subject.unknown(message) }.to output(json_matching("ANY", message)).to_stdout_from_any_process
   end
 
+  it 'only accepts strings' do
+    expect { subject.unknown("just a string!") }.to raise_error(ArgumentError, /must be a Hash/)
+  end
+
   context 'logging a hash as a message' do
     it 'merges the contents' do
       input = {
@@ -41,9 +45,8 @@
   def json_matching(level, message)
     contents = {
         severity: level,
-        time: now,
-        message: message
-    }
+        time: now
+    }.merge(message)
 
     as_regex(contents)
   end