feat(webhook status): log number of seconds until next webhook attempt in webhook logs

Author: bethesque

lib/pact_broker/domain/webhook.rb

@@ -31,9 +31,9 @@ def request_description
         request && request.description
       end
 
-      def execute
+      def execute options
         logger.info "Executing #{self}"
-        request.execute
+        request.execute options
       end
 
       def to_s

lib/pact_broker/domain/webhook_request.rb

@@ -47,58 +47,80 @@ def display_password
         password.nil? ? nil : "**********"
       end
 
-      def execute
-
+      def execute options = {}
         logs = StringIO.new
         execution_logger = Logger.new(logs)
-
         begin
-          req = http_request
-          execution_logger.info "HTTP/1.1 #{method.upcase} #{url_with_credentials}"
+          execute_and_build_result(options, logs, execution_logger)
+        rescue StandardError => e
+          handle_error_and_build_result(e, options, logs, execution_logger)
+        end
+      end
 
-          headers.each_pair do | name, value |
-            execution_logger.info Webhooks::RedactLogs.call("#{name}: #{value}")
-            req[name] = value
-          end
+      private
 
-          req.basic_auth(username, password) if username
+      def execute_and_build_result options, logs, execution_logger
+        req = build_request(execution_logger)
+        response = do_request(req)
+        log_response(response, execution_logger)
+        result = WebhookExecutionResult.new(response, logs.string)
+        log_completion_message(options, execution_logger, result.success?)
+        result
+      end
 
-          unless body.nil?
-            if String === body
-              req.body = body
-            else
-              req.body = body.to_json
-            end
-          end
+      def handle_error_and_build_result e, options, logs, execution_logger
+        logger.error "Error executing webhook #{uuid} #{e.class.name} - #{e.message} #{e.backtrace.join("\n")}"
+        execution_logger.error "Error executing webhook #{uuid} #{e.class.name} - #{e.message}"
+        log_completion_message(options, execution_logger, false)
+        WebhookExecutionResult.new(nil, logs.string, e)
+      end
 
-          execution_logger.info req.body
+      def build_request execution_logger
+        req = http_request
+        execution_logger.info "HTTP/1.1 #{method.upcase} #{url_with_credentials}"
 
-          logger.info "Making webhook #{uuid} request #{to_s}"
+        headers.each_pair do | name, value |
+          execution_logger.info Webhooks::RedactLogs.call("#{name}: #{value}")
+          req[name] = value
+        end
 
-          response = Net::HTTP.start(uri.hostname, uri.port,
-            :use_ssl => uri.scheme == 'https') do |http|
-            http.request req
-          end
+        req.basic_auth(username, password) if username
 
-          execution_logger.info(" ")
-          logger.info "Received response for webhook #{uuid} status=#{response.code}"
-          execution_logger.info "HTTP/#{response.http_version} #{response.code} #{response.message}"
-          response.each_header do | header |
-            execution_logger.info "#{header.split("-").collect(&:capitalize).join('-')}: #{response[header]}"
+        unless body.nil?
+          if String === body
+            req.body = body
+          else
+            req.body = body.to_json
           end
-          logger.debug "body=#{response.body}"
-          execution_logger.info response.body
-          WebhookExecutionResult.new(response, logs.string)
+        end
 
-        rescue StandardError => e
-          logger.error "Error executing webhook #{uuid} #{e.class.name} - #{e.message}"
-          logger.error e.backtrace.join("\n")
-          execution_logger.error "Error executing webhook #{uuid} #{e.class.name} - #{e.message}"
-          WebhookExecutionResult.new(nil, logs.string, e)
+        execution_logger.info req.body
+        req
+      end
+
+      def do_request req
+        logger.info "Making webhook #{uuid} request #{to_s}"
+        Net::HTTP.start(uri.hostname, uri.port,
+          :use_ssl => uri.scheme == 'https') do |http|
+          http.request req
         end
       end
 
-      private
+      def log_response response, execution_logger
+        execution_logger.info(" ")
+        logger.info "Received response for webhook #{uuid} status=#{response.code}"
+        execution_logger.info "HTTP/#{response.http_version} #{response.code} #{response.message}"
+        response.each_header do | header |
+          execution_logger.info "#{header.split("-").collect(&:capitalize).join('-')}: #{response[header]}"
+        end
+        logger.debug "body=#{response.body}"
+        execution_logger.info response.body
+      end
+
+      def log_completion_message options, execution_logger, success
+        execution_logger.info(options[:success_log_message]) if options[:success_log_message] && success
+        execution_logger.info(options[:failure_log_message]) if options[:failure_log_message] && !success
+      end
 
       def to_s
         "#{method.upcase} #{url}, username=#{username}, password=#{display_password}, headers=#{headers}, body=#{body}"

lib/pact_broker/webhooks/job.rb

@@ -14,7 +14,7 @@ def perform data
         @triggered_webhook = data[:triggered_webhook]
         @error_count = data[:error_count] || 0
         begin
-          webhook_execution_result = PactBroker::Webhooks::Service.execute_triggered_webhook_now triggered_webhook
+          webhook_execution_result = PactBroker::Webhooks::Service.execute_triggered_webhook_now triggered_webhook, execution_options
           if webhook_execution_result.success?
             handle_success
           else
@@ -29,6 +29,21 @@ def perform data
 
       attr_reader :triggered_webhook, :error_count
 
+      def execution_options
+        {
+          success_log_message: "Successfully executed webhook",
+          failure_log_message: failure_log_message
+        }
+      end
+
+      def failure_log_message
+        if reschedule_job?
+          "Retrying webhook in #{backoff_time} seconds"
+        else
+          "Webhook execution failed after #{retry_schedule.size + 1} attempts"
+        end
+      end
+
       def handle_error e
         log_error e
         handle_failure
@@ -43,7 +58,7 @@ def handle_failure
           reschedule_job
           update_triggered_webhook_status TriggeredWebhook::STATUS_RETRYING
         else
-          logger.error "Failed to execute webhook #{triggered_webhook.webhook_uuid} after #{retry_schedule.size} times."
+          logger.error "Failed to execute webhook #{triggered_webhook.webhook_uuid} after #{retry_schedule.size + 1} attempts."
           update_triggered_webhook_status TriggeredWebhook::STATUS_FAILURE
         end
       end
@@ -53,7 +68,7 @@ def reschedule_job?
       end
 
       def reschedule_job
-        logger.debug "Re-enqeuing job for webhook #{triggered_webhook.webhook_uuid} to run in #{retry_schedule[error_count]} seconds"
+        logger.debug "Re-enqeuing job for webhook #{triggered_webhook.webhook_uuid} to run in #{backoff_time} seconds"
         Job.perform_in(backoff_time, @data.merge(error_count: error_count+1))
       end
 

lib/pact_broker/webhooks/service.rb

@@ -56,7 +56,7 @@ def self.find_all
 
       def self.execute_webhook_now webhook, pact
         triggered_webhook = webhook_repository.create_triggered_webhook(next_uuid, webhook, pact, USER)
-        webhook_execution_result = execute_triggered_webhook_now triggered_webhook
+        webhook_execution_result = execute_triggered_webhook_now triggered_webhook, failure_log_message: "Webhook execution failed"
         if webhook_execution_result.success?
           webhook_repository.update_triggered_webhook_status triggered_webhook, TriggeredWebhook::STATUS_SUCCESS
         else
@@ -65,8 +65,8 @@ def self.execute_webhook_now webhook, pact
         webhook_execution_result
       end
 
-      def self.execute_triggered_webhook_now triggered_webhook
-        webhook_execution_result = triggered_webhook.execute
+      def self.execute_triggered_webhook_now triggered_webhook, options
+        webhook_execution_result = triggered_webhook.execute options
         webhook_repository.create_execution triggered_webhook, webhook_execution_result
         webhook_execution_result
       end

lib/pact_broker/webhooks/triggered_webhook.rb

@@ -28,8 +28,8 @@ def request_description
         webhook.to_domain.request_description
       end
 
-      def execute
-        webhook.to_domain.execute
+      def execute options
+        webhook.to_domain.execute options
       end
 
       def consumer_name

spec/features/execute_webhook_spec.rb

@@ -27,7 +27,6 @@
     end
 
     it "returns a 200 response" do
-      puts subject.body
       expect(subject.status).to be 200
     end
 

spec/lib/pact_broker/domain/webhook_request_spec.rb

@@ -14,6 +14,7 @@ module Domain
       let(:body) { 'body' }
       let(:logs) { StringIO.new }
       let(:execution_logger) { Logger.new(logs) }
+      let(:options) { {failure_log_message: 'oops'}}
 
       subject do
         WebhookRequest.new(
@@ -25,6 +26,8 @@ module Domain
           body: body)
       end
 
+      let(:logs) { subject.execute(options).logs }
+
       describe "description" do
         it "returns a brief description of the HTTP request" do
           expect(subject.description).to eq 'POST example.org'
@@ -54,28 +57,26 @@ module Domain
         end
 
         it "executes the configured request" do
-          subject.execute
+          subject.execute(options)
           expect(http_request).to have_been_made
         end
 
         it "logs the request" do
           allow(PactBroker.logger).to receive(:info)
           expect(PactBroker.logger).to receive(:info).with(/POST.*example.*text.*body/)
-          subject.execute
+          subject.execute(options)
         end
 
         it "logs the response" do
           allow(PactBroker.logger).to receive(:info)
           allow(PactBroker.logger).to receive(:debug)
           expect(PactBroker.logger).to receive(:info).with(/response.*302/)
           expect(PactBroker.logger).to receive(:debug).with(/respbod/)
-          subject.execute
+          subject.execute(options)
         end
 
         describe "execution logs" do
 
-          let(:logs) { subject.execute.logs }
-
           it "logs the request method and path" do
             expect(logs).to include "POST http://example.org/hook"
           end
@@ -104,6 +105,20 @@ module Domain
             expect(logs).to include "respbod"
           end
 
+          context "when the response code is a success" do
+            it "does not log the failure_log_message" do
+              allow_any_instance_of(WebhookExecutionResult).to receive(:success?).and_return(true)
+              expect(logs).to_not include "oops"
+            end
+          end
+
+          context "when the response code is not successful" do
+            it "logs the failure_log_message" do
+              allow_any_instance_of(WebhookExecutionResult).to receive(:success?).and_return(false)
+              expect(logs).to include "oops"
+            end
+          end
+
           context "with basic auth" do
             let(:username) { 'username' }
             let(:password) { 'password' }
@@ -129,7 +144,7 @@ module Domain
           end
 
           it "uses the credentials" do
-            subject.execute
+            subject.execute(options)
             expect(http_request_with_basic_auth).to have_been_made
           end
         end
@@ -145,7 +160,7 @@ module Domain
           end
 
           it "uses SSL" do
-            subject.execute
+            subject.execute(options)
             expect(https_request).to have_been_made
           end
         end
@@ -160,7 +175,7 @@ module Domain
           end
 
           it "converts the body to JSON before submitting the request" do
-            subject.execute
+            subject.execute(options)
             expect(http_request).to have_been_made
           end
         end
@@ -175,18 +190,18 @@ module Domain
           end
 
           it "executes the request without a body" do
-            subject.execute
+            subject.execute(options)
             expect(http_request).to have_been_made
           end
         end
 
         context "when the request is successful" do
           it "returns a WebhookExecutionResult with success=true" do
-            expect(subject.execute.success?).to be true
+            expect(subject.execute(options).success?).to be true
           end
 
           it "sets the response on the result" do
-            expect(subject.execute.response).to be_instance_of(Net::HTTPFound)
+            expect(subject.execute(options).response).to be_instance_of(Net::HTTPFound)
           end
         end
 
@@ -199,11 +214,11 @@ module Domain
           end
 
           it "returns a WebhookExecutionResult with success=false" do
-            expect(subject.execute.success?).to be false
+            expect(subject.execute(options).success?).to be false
           end
 
           it "sets the response on the result" do
-            expect(subject.execute.response).to be_instance_of(Net::HTTPInternalServerError)
+            expect(subject.execute(options).response).to be_instance_of(Net::HTTPInternalServerError)
           end
         end
 
@@ -218,22 +233,22 @@ class WebhookTestError < StandardError; end
           it "logs the error" do
             allow(PactBroker.logger).to receive(:error)
             expect(PactBroker.logger).to receive(:error).with(/Error.*WebhookTestError.*blah/)
-            subject.execute
+            subject.execute(options)
           end
 
           it "returns a WebhookExecutionResult with success=false" do
-            expect(subject.execute.success?).to be false
+            expect(subject.execute(options).success?).to be false
           end
 
           it "returns a WebhookExecutionResult with an error" do
-            expect(subject.execute.error).to be_instance_of WebhookTestError
+            expect(subject.execute(options).error).to be_instance_of WebhookTestError
           end
-        end
 
+          it "logs the failure_log_message" do
+            expect(logs).to include "oops"
+          end
+        end
       end
-
     end
-
   end
-
 end