diff --git a/lib/mail_room/connection.rb b/lib/mail_room/connection.rb index 27c467a..cefa36f 100644 --- a/lib/mail_room/connection.rb +++ b/lib/mail_room/connection.rb @@ -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 diff --git a/lib/mail_room/delivery/postback.rb b/lib/mail_room/delivery/postback.rb index 5ce7467..c1ce6fc 100644 --- a/lib/mail_room/delivery/postback.rb +++ b/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 diff --git a/lib/mail_room/delivery/que.rb b/lib/mail_room/delivery/que.rb index ebbb5ce..b7d32c9 100644 --- a/lib/mail_room/delivery/que.rb +++ b/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 diff --git a/lib/mail_room/delivery/sidekiq.rb b/lib/mail_room/delivery/sidekiq.rb index 4df684b..acb68d9 100644 --- a/lib/mail_room/delivery/sidekiq.rb +++ b/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 diff --git a/lib/mail_room/mailbox.rb b/lib/mail_room/mailbox.rb index 4cc07ae..691f9a7 100644 --- a/lib/mail_room/mailbox.rb +++ b/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! diff --git a/lib/mail_room/mailbox_watcher.rb b/lib/mail_room/mailbox_watcher.rb index 3b19d97..5a2ab37 100644 --- a/lib/mail_room/mailbox_watcher.rb +++ b/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| diff --git a/lib/mail_room/structured_logger.rb b/lib/mail_room/structured_logger.rb index b47bee6..0742e46 100644 --- a/lib/mail_room/structured_logger.rb +++ b/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 diff --git a/spec/lib/structured_logger_spec.rb b/spec/lib/structured_logger_spec.rb index 8ba3d68..13a18b2 100644 --- a/spec/lib/structured_logger_spec.rb +++ b/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