From 5d1633057975c3d16241544af225649eccdcc67a Mon Sep 17 00:00:00 2001 From: Beth Skurrie Date: Wed, 6 Sep 2017 17:46:39 +1000 Subject: [PATCH] feat(webhook status): log number of seconds until next webhook attempt in webhook logs --- lib/pact_broker/domain/webhook.rb | 4 +- lib/pact_broker/domain/webhook_request.rb | 96 ++++++++++++------- lib/pact_broker/webhooks/job.rb | 21 +++- lib/pact_broker/webhooks/service.rb | 6 +- lib/pact_broker/webhooks/triggered_webhook.rb | 4 +- spec/features/execute_webhook_spec.rb | 1 - .../domain/webhook_request_spec.rb | 55 +++++++---- spec/lib/pact_broker/domain/webhook_spec.rb | 10 +- spec/lib/pact_broker/webhooks/job_spec.rb | 49 ++++++---- 9 files changed, 156 insertions(+), 90 deletions(-) diff --git a/lib/pact_broker/domain/webhook.rb b/lib/pact_broker/domain/webhook.rb index ff0cde481..ad368b76b 100644 --- a/lib/pact_broker/domain/webhook.rb +++ b/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 diff --git a/lib/pact_broker/domain/webhook_request.rb b/lib/pact_broker/domain/webhook_request.rb index b88f8815e..883e2f0e5 100644 --- a/lib/pact_broker/domain/webhook_request.rb +++ b/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}" diff --git a/lib/pact_broker/webhooks/job.rb b/lib/pact_broker/webhooks/job.rb index 4c752976b..3fe7c4476 100644 --- a/lib/pact_broker/webhooks/job.rb +++ b/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 diff --git a/lib/pact_broker/webhooks/service.rb b/lib/pact_broker/webhooks/service.rb index 2c4fbe8cc..35af3d0ae 100644 --- a/lib/pact_broker/webhooks/service.rb +++ b/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 diff --git a/lib/pact_broker/webhooks/triggered_webhook.rb b/lib/pact_broker/webhooks/triggered_webhook.rb index 0ad310b4a..1daaff926 100644 --- a/lib/pact_broker/webhooks/triggered_webhook.rb +++ b/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 diff --git a/spec/features/execute_webhook_spec.rb b/spec/features/execute_webhook_spec.rb index 5195feafa..6315d9b55 100644 --- a/spec/features/execute_webhook_spec.rb +++ b/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 diff --git a/spec/lib/pact_broker/domain/webhook_request_spec.rb b/spec/lib/pact_broker/domain/webhook_request_spec.rb index c78bd7018..a03101dd3 100644 --- a/spec/lib/pact_broker/domain/webhook_request_spec.rb +++ b/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,14 +57,14 @@ 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 @@ -69,13 +72,11 @@ module Domain 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 diff --git a/spec/lib/pact_broker/domain/webhook_spec.rb b/spec/lib/pact_broker/domain/webhook_spec.rb index 4ebea4efa..8cd9cbf81 100644 --- a/spec/lib/pact_broker/domain/webhook_spec.rb +++ b/spec/lib/pact_broker/domain/webhook_spec.rb @@ -10,6 +10,7 @@ module Domain let(:consumer) { Pacticipant.new(name: 'Consumer')} let(:provider) { Pacticipant.new(name: 'Provider')} let(:request) { instance_double(PactBroker::Domain::WebhookRequest, execute: nil)} + let(:options) { double('options') } subject { Webhook.new(request: request, consumer: consumer, provider: provider,) } describe "description" do @@ -21,19 +22,16 @@ module Domain describe "execute" do it "executes the request" do - expect(request).to receive(:execute) - subject.execute + expect(request).to receive(:execute).with(options) + subject.execute options end it "logs before and after" do allow(PactBroker.logger).to receive(:info) expect(PactBroker.logger).to receive(:info).with(/Executing/) - subject.execute + subject.execute options end - end end - end - end diff --git a/spec/lib/pact_broker/webhooks/job_spec.rb b/spec/lib/pact_broker/webhooks/job_spec.rb index c577f272f..cd1439837 100644 --- a/spec/lib/pact_broker/webhooks/job_spec.rb +++ b/spec/lib/pact_broker/webhooks/job_spec.rb @@ -5,17 +5,16 @@ module Webhooks describe Job do before do - allow(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now) + PactBroker.configuration.webhook_retry_schedule = [10, 60, 120, 300, 600, 1200] + allow(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now).and_return(result) allow(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status) end let(:triggered_webhook) { instance_double("PactBroker::Webhooks::TriggeredWebhook", webhook_uuid: '1234') } + let(:result) { instance_double("PactBroker::Domain::WebhookExecutionResult", success?: success)} + let(:success) { true } context "when the job succeeds" do - before do - allow(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now).and_return(instance_double("PactBroker::Domain::WebhookExecutionResult", success?: true)) - end - subject { Job.new.perform(triggered_webhook: triggered_webhook) } it "does not reschedule the job" do @@ -24,7 +23,8 @@ module Webhooks end it "updates the triggered_webhook status to 'success'" do - expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status).with(triggered_webhook, TriggeredWebhook::STATUS_SUCCESS) + expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status) + .with(triggered_webhook, TriggeredWebhook::STATUS_SUCCESS) subject end end @@ -42,15 +42,14 @@ module Webhooks end it "updates the triggered_webhook status to 'retrying'" do - expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status).with(triggered_webhook, TriggeredWebhook::STATUS_RETRYING) + expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status) + .with(triggered_webhook, TriggeredWebhook::STATUS_RETRYING) subject end end context "when the webhook execution result is not successful for the first time" do - before do - allow(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now).and_return(instance_double("PactBroker::Domain::WebhookExecutionResult", success?: false)) - end + let(:success) { false } subject { Job.new.perform(triggered_webhook: triggered_webhook) } @@ -59,8 +58,18 @@ module Webhooks subject end + it "executes the job with an log message indicating that the webhook will be retried" do + expect(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now) + .with(triggered_webhook, { + failure_log_message: "Retrying webhook in 10 seconds", + success_log_message: "Successfully executed webhook" + }) + subject + end + it "updates the triggered_webhook status to 'retrying'" do - expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status).with(triggered_webhook, TriggeredWebhook::STATUS_RETRYING) + expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status) + .with(triggered_webhook, TriggeredWebhook::STATUS_RETRYING) subject end end @@ -78,18 +87,26 @@ module Webhooks end it "updates the triggered_webhook status to 'retrying'" do - expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status).with(triggered_webhook, TriggeredWebhook::STATUS_RETRYING) + expect(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status) + .with(triggered_webhook, TriggeredWebhook::STATUS_RETRYING) subject end end - context "when an error occurs for the last time" do - before do - allow(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now).and_raise("an error") - end + context "when the job is not successful for the last time" do + let(:success) { false } subject { Job.new.perform(triggered_webhook: triggered_webhook, error_count: 6) } + it "executes the job with an log message indicating that the webhook has failed" do + expect(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now) + .with(triggered_webhook, { + failure_log_message: "Webhook execution failed after 7 attempts", + success_log_message: "Successfully executed webhook" + }) + subject + end + it "does not reschedule the job" do expect(Job).to_not receive(:perform_in) subject