WIP: Logger

lib/mail_room.rb

@@ -1,8 +1,16 @@
 require 'net/imap'
 require 'optparse'
 require 'yaml'
+require 'logger'
 
 module MailRoom
+  def self.logger
+    @logger ||= Logger.new(STDOUT)
+  end
+
+  def self.logger=(logger)
+    @logger = (logger ? logger : Logger.new("/dev/null"))
+  end
 end
 
 require "mail_room/version"

lib/mail_room/arbitration/redis.rb

@@ -26,7 +26,7 @@ def deliver?(uid)
 
         incr = nil
         redis.multi do |client|
-          # At this point, `incr` is a future, which will get its value after 
+          # At this point, `incr` is a future, which will get its value after
           # the MULTI command returns.
           incr = client.incr(key)
 
@@ -37,7 +37,10 @@ def deliver?(uid)
         # we are the first mail_room to try to deliver this message, so we get to.
         # If we get any other value, another mail_room already (tried to) deliver
         # the message, so we don't have to anymore.
-        incr.value == 1
+        result = incr.value == 1
+        MailRoom.logger.info("Arbitration result for #{uid} =  #{result}")
+
+        result
       end
 
       private

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
+        logger.info("Interrupt signal received")
         coordinator.running = false
       end
 
       Signal.trap(:TERM) do
+        logger.info("Terminate signal received")
         exit
       end
 

lib/mail_room/coordinator.rb

@@ -17,9 +17,9 @@ def initialize(mailboxes)
     # start each of the watchers to running
     def run
       watchers.each(&:run)
-      
+
       self.running = true
-      
+
       sleep_while_running
     ensure
       quit

lib/mail_room/delivery/postback.rb

@@ -29,10 +29,9 @@ def deliver(message)
         connection.post do |request|
           request.url @delivery_options.delivery_url
           request.body = message
-          # request.options[:timeout] = 3
-          # request.headers['Content-Type'] = 'text/plain'
         end
 
+        MailRoom.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.logger.info("Message pushed onto Que queue")
       end
 
       private

lib/mail_room/delivery/sidekiq.rb

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

lib/mail_room/mailbox.rb

@@ -63,6 +63,8 @@ def arbitrator
     end
 
     def deliver?(uid)
+      MailRoom.logger.info("#{context} Asking #{arbitrator.class.name} if we should deliver #{uid}")
+
       arbitrator.deliver?(uid)
     end
 
@@ -72,6 +74,7 @@ def deliver(message)
       body = message.attr['RFC822']
       return true unless body
 
+      MailRoom.logger.info("#{context} Delivering #{message.attr['UID']} through #{delivery.class.name}")
       delivery.deliver(body)
     end
 
@@ -80,6 +83,10 @@ def ssl_options
       replace_verify_mode(ssl)
     end
 
+    def context
+      "[#{self.email}-#{self.name}]:"
+    end
+
     private
 
     def parsed_arbitration_options

lib/mail_room/mailbox_handler.rb

@@ -19,6 +19,7 @@ def process
         delivered = @mailbox.deliver(message)
 
         if delivered && @mailbox.delete_after_delivery
+          MailRoom.logger.info("#{@mailbox.context} Add DELETED flag to #{message.attr['UID']}")
           @imap.store(message.seqno, "+FLAGS", [Net::IMAP::DELETED])
         end
       end
@@ -43,7 +44,12 @@ def new_messages
     # search for all new (unseen) message ids
     # @return [Array<Integer>] message ids
     def new_message_ids
-      @imap.uid_search(@mailbox.search_command).select { |uid| @mailbox.deliver?(uid) }
+      all_unread = @imap.uid_search(@mailbox.search_command)
+      MailRoom.logger.info("#{@mailbox.context} #{all_unread.count} new messages with ids: #{all_unread.join(', ')}")
+
+      to_deliver = all_unread.select { |uid| @mailbox.deliver?(uid) }
+      MailRoom.logger.info("#{@mailbox.context} #{to_deliver.count} messages to be delivered by this mailroom instance.\n Their ids: #{all_unread.join(', ')}")
+      to_deliver
     end
 
     # @private

lib/mail_room/mailbox_watcher.rb

@@ -64,9 +64,16 @@ def message_exists?(response)
 
     # log in and set the mailbox
     def setup
+      MailRoom.logger.info("#{@mailbox.context} Setting up watcher")
       reset
+
+      MailRoom.logger.info("#{@mailbox.context} Start TLS session")
       start_tls
+
+      MailRoom.logger.info("#{@mailbox.context} Logging in to the mailbox")
       log_in
+
+      MailRoom.logger.info("#{@mailbox.context} Set the mailbox to #{@mailbox.name}")
       set_mailbox
     end
 
@@ -98,6 +105,7 @@ def set_mailbox
     def idle
       return unless ready_to_idle?
 
+      MailRoom.logger.info("#{@mailbox.context} Idling...")
       @idling = true
 
       self.timeout_thread = Thread.start do
@@ -122,7 +130,7 @@ def stop_idling
       return unless idling?
 
       imap.idle_done
-      
+
       idling_thread.join
       self.idling_thread = nil
     end
@@ -146,6 +154,7 @@ def run
             process_mailbox
           rescue Net::IMAP::Error, IOError => e
             # we've been disconnected, so re-setup
+            MailRoom.logger.warn("#{@mailbox.context} Disconnected")
             setup
           end
         end
@@ -163,6 +172,7 @@ def quit
 
     # trigger the handler to process this mailbox for new messages
     def process_mailbox
+      MailRoom.logger.info("#{@mailbox.context} Processing started")
       handler.process
     end
 

spec/lib/mailbox_watcher_spec.rb

@@ -73,8 +73,9 @@
   end
 
   describe '#idle' do
-    let(:imap) {stub}
-    let(:watcher) {MailRoom::MailboxWatcher.new(nil)}
+    let(:mailbox) { MailRoom::Mailbox.new(email: "mep@mep.mep", name: "inbox") }
+    let(:imap) { stub }
+    let(:watcher) {MailRoom::MailboxWatcher.new(mailbox) }
 
     before :each do
       watcher.stubs(:imap).returns(imap)
@@ -89,7 +90,7 @@
     end
 
     context "when logged in" do
-      before :each do
+      before do
         imap.stubs(:idle_done)
 
         watcher.stubs(:logged_in?).returns(true)