Logging

lib/em-aws.rb

@@ -1,10 +1,12 @@
 require "eventmachine"
 require "em-aws/version"
 require "em-aws/service"
+require "em-aws/logger"
 
 
 module EventMachine
   module AWS
+    extend Logger
 
     # Default values
     @region = 'us-east-1'

lib/em-aws/logger.rb

@@ -0,0 +1,44 @@
+require "logger"
+
+module EventMachine
+  module AWS
+    module Logger
+      attr_writer :logger
+
+      # Resets the logger with the given IO object.
+      def logfile=(dev)
+        @logfile = dev
+        @logger = nil
+      end
+
+      # The IO object used for logging. Defaults to STDERR.
+      def logfile
+        @logfile ||= STDERR
+      end
+
+      # Minimum severity level for logging. Defaults to WARN.
+      def loglevel
+        @loglevel ||= ::Logger::WARN
+      end
+
+      # Set the logging severity level.
+      def loglevel=(level)
+        @loglevel = logger.level = level
+      end
+
+      # An instance of the standard Ruby Logger or some compatible object.
+      # Defaults to logging warnings & above to STDERR.  You can supply
+      # your own object, but if you do, the 'logfile' and 'loglevel' attributes
+      # will no longer apply.
+      def logger
+        @logger ||= begin
+          l = ::Logger.new logfile
+          l.level = loglevel
+          l.progname = "EM::AWS"
+          l
+        end
+      end
+
+    end
+  end
+end

lib/em-aws/query.rb

@@ -32,10 +32,28 @@ def call(action, params = {}, &block)
           }
         query.merge! queryize_params(params)
         query.merge! @signer.signature(query) if @signer
-
+        
         request = Request.new(self, method, query)
+        request_id = "#{self.class.name}##{action} (#{request.object_id})"
+        AWS.logger.info "Calling #{request_id}"
+        AWS.logger.debug "#{request_id} params: #{query}"
+
         request.callback(&block) if block
 
+        if AWS.logger.info?
+          request.callback do |r|
+            duration = Time.now - request.start_time
+            AWS.logger.info "Completed #{request_id} in #{duration} seconds"
+            AWS.logger.debug "#{request_id} result: #{r.result}"
+          end
+
+          request.errback do |r|
+            duration = Time.now - request.start_time
+            AWS.logger.info "Failed #{request_id} in #{duration} seconds"
+            AWS.logger.debug "#{request_id} result: #{r.result}"
+          end
+        end
+
         handle_request(request)
 
       end

lib/em-aws/request.rb

@@ -11,11 +11,12 @@ class Request
       include Deferrable
       include Inflections
 
-      attr_reader :service, :method, :params, :response
+      attr_reader :service, :method, :params, :response, :start_time
       attr_accessor :attempts
 
       def initialize(service, method, params)
         @service, @method, @params = service, method, params
+        @start_time = Time.now
         @attempts = 0
 
         self.callback {|r| @response = r}

lib/em-aws/service.rb

@@ -62,20 +62,23 @@ def handle_request(request)
 
       def send_request(request)
         request.attempts += 1
-        http_request = EventMachine::HttpRequest.new(self.url)
+        http_client = EventMachine::HttpRequest.new(self.url)
 
         if request.method == :get
-          http_request.get query: request.params
+          http_request = http_client.get query: request.params
         else
-          http_request.send request.method, body: request.params
+          http_request = http_client.send request.method, body: request.params
         end
 
         http_request.errback do |raw_response|
           # Send again until retry limit is exceeded
           if request.attempts <= EM::AWS.retries
+            AWS.logger.warn("HTTP client error; retry #{request.attempts} of #{EM::AWS.retries}")
             EM.add_timer(next_delay(request.attempts)) {send_request request}
           else
-            request.fail FailureResponse.new(raw_response)
+            f = FailureResponse.new(raw_response)
+            AWS.logger.error("HTTP client error; gave up after #{EM::AWS.retries} retries: #{f.error}")
+            request.fail f
           end
         end
 
@@ -85,12 +88,17 @@ def send_request(request)
             request.succeed success_response(raw_response)
           when 500, 502, 503, 504
             if request.attempts <= EM::AWS.retries
+              AWS.logger.warn("Amazon #{raw_response.response_header.status} error; retry #{request.attempts} of #{EM::AWS.retries}")
               EM.add_timer(next_delay(request.attempts)) {send_request request}
             else
-              request.fail failure_response(raw_response)
+              f = failure_response(raw_response)
+              AWS.logger.error("Amazon #{raw_response.response_header.status} error; gave up after #{EM::AWS.retries} retries: #{f.error}")
+              request.fail f
             end
           else
-            request.fail failure_response(raw_response)
+            f = failure_response(raw_response)
+            AWS.logger.error("Amazon #{raw_response.response_header.status} error: #{f.error}")
+            request.fail f
           end
         end
 

spec/em-aws/sqs_spec.rb

@@ -42,7 +42,7 @@
 
     it "can set attributes on the queue" do
       subject.set_queue_attributes attribute: {maximum_message_size: 1024}
-      sleep 10
+      sleep 20
       response = subject.get_queue_attributes attribute_name: ['MaximumMessageSize']
       response.maximum_message_size.should == 1024
     end

spec/spec_helper.rb

@@ -16,6 +16,7 @@
   config.filter_run_excluding slow: true unless ENV['AWS_SLOW_TESTS'] == 'true'
   # config.filter_run :focus
 
+  # EM::AWS.loglevel = ::Logger::DEBUG
 
   # Run in 'mock' or 'live' mode based on the AWS_TEST_MODE variable. (Defaults to 'mock.')
   # If in live mode, the credentials must also be set in the environment.