From a9133bd5fe5de42c8a26e780addbcf93a536eb23 Mon Sep 17 00:00:00 2001 From: Matt Fellows Date: Fri, 21 Sep 2018 20:42:34 +1000 Subject: [PATCH] feat(logging): implement structured logging - Replaces default Ruby logger with semantic_logger for better log shipping experience - Make backwards compatible with existing config, by logging to file with the same format as default Ruby - TODO: documentation --- lib/db.rb | 2 +- .../api/renderers/html_pact_renderer.rb | 2 +- .../api/resources/base_resource.rb | 2 +- .../api/resources/error_handler.rb | 1 + lib/pact_broker/app.rb | 18 ++++++++---- lib/pact_broker/badges/service.rb | 2 +- lib/pact_broker/certificates/service.rb | 1 + lib/pact_broker/config/load.rb | 2 +- lib/pact_broker/config/save.rb | 2 +- lib/pact_broker/configuration.rb | 13 ++------- lib/pact_broker/default_formatter.rb | 18 ++++++++++++ lib/pact_broker/domain/order_versions.rb | 2 +- lib/pact_broker/domain/webhook_request.rb | 2 +- lib/pact_broker/logging.rb | 20 +------------ lib/pact_broker/matrix/row.rb | 2 +- lib/pact_broker/pacts/repository.rb | 2 +- lib/pact_broker/pacts/service.rb | 2 +- lib/pact_broker/webhooks/job.rb | 1 + .../webhooks/webhook_request_template.rb | 2 +- pact_broker.gemspec | 1 + .../api/renderers/html_pact_renderer_spec.rb | 11 ++++--- .../api/resources/error_handler_spec.rb | 8 ++++- spec/lib/pact_broker/badges/service_spec.rb | 5 ++-- .../pact_broker/certificates/service_spec.rb | 11 +++++-- .../domain/webhook_request_spec.rb | 29 +++++++++++-------- spec/lib/pact_broker/webhooks/job_spec.rb | 2 ++ 26 files changed, 91 insertions(+), 72 deletions(-) create mode 100644 lib/pact_broker/default_formatter.rb diff --git a/lib/db.rb b/lib/db.rb index d4627d4bc..419b29810 100644 --- a/lib/db.rb +++ b/lib/db.rb @@ -6,7 +6,7 @@ require 'pact_broker/project_root' module DB - include PactBroker::Logging + include SemanticLogger::Loggable ## # Sequel by default does not test connections in its connection pool before # handing them to a client. To enable connection testing you need to load the diff --git a/lib/pact_broker/api/renderers/html_pact_renderer.rb b/lib/pact_broker/api/renderers/html_pact_renderer.rb index 011f0a149..ab5fa525d 100644 --- a/lib/pact_broker/api/renderers/html_pact_renderer.rb +++ b/lib/pact_broker/api/renderers/html_pact_renderer.rb @@ -12,7 +12,7 @@ class HtmlPactRenderer class NotAPactError < StandardError; end - include PactBroker::Logging + include SemanticLogger::Loggable def self.call pact, options = {} new(pact, options).call diff --git a/lib/pact_broker/api/resources/base_resource.rb b/lib/pact_broker/api/resources/base_resource.rb index 61bfa1844..5c7c323a4 100644 --- a/lib/pact_broker/api/resources/base_resource.rb +++ b/lib/pact_broker/api/resources/base_resource.rb @@ -21,7 +21,7 @@ class BaseResource < Webmachine::Resource include PactBroker::Services include PactBroker::Api::PactBrokerUrls include PactBroker::Api::Resources::Authentication - include PactBroker::Logging + include SemanticLogger::Loggable attr_accessor :user diff --git a/lib/pact_broker/api/resources/error_handler.rb b/lib/pact_broker/api/resources/error_handler.rb index ffabaccb3..fce2aa66e 100644 --- a/lib/pact_broker/api/resources/error_handler.rb +++ b/lib/pact_broker/api/resources/error_handler.rb @@ -6,6 +6,7 @@ module Api module Resources class ErrorHandler + include SemanticLogger::Loggable include PactBroker::Logging def self.call e, request, response diff --git a/lib/pact_broker/app.rb b/lib/pact_broker/app.rb index ef901d494..dcc43cd01 100644 --- a/lib/pact_broker/app.rb +++ b/lib/pact_broker/app.rb @@ -1,6 +1,7 @@ require 'pact_broker/configuration' require 'pact_broker/db' require 'pact_broker/project_root' +require 'pact_broker/default_formatter' require 'rack-protection' require 'rack/hal_browser' require 'rack/pact_broker/store_base_url' @@ -18,6 +19,7 @@ module PactBroker class App + include SemanticLogger::Loggable attr_accessor :configuration @@ -58,13 +60,9 @@ def call env private - def logger - PactBroker.logger - end - def post_configure - PactBroker.logger = configuration.logger - SuckerPunch.logger = configuration.logger + configure_logger + SuckerPunch.logger = SemanticLogger['SuckerPunch'] configure_database_connection configure_sucker_punch end @@ -166,6 +164,14 @@ def configure_sucker_punch end end + def configure_logger + if SemanticLogger.appenders.empty? + path = configuration.log_dir + "/pact_broker.log" + FileUtils.mkdir_p(configuration.log_dir) + SemanticLogger.add_appender(file_name: path, formatter: PactBroker::Logging::DefaultFormatter.new) + end + end + def running_app @running_app ||= begin apps = @cascade_apps diff --git a/lib/pact_broker/badges/service.rb b/lib/pact_broker/badges/service.rb index a20b89e9f..30a7bfeed 100644 --- a/lib/pact_broker/badges/service.rb +++ b/lib/pact_broker/badges/service.rb @@ -10,7 +10,7 @@ module Badges module Service extend self - include PactBroker::Logging + include SemanticLogger::Loggable SPACE_DASH_UNDERSCORE = /[\s_\-]/ CACHE = {} diff --git a/lib/pact_broker/certificates/service.rb b/lib/pact_broker/certificates/service.rb index 8b73937e6..ac9d74d52 100644 --- a/lib/pact_broker/certificates/service.rb +++ b/lib/pact_broker/certificates/service.rb @@ -8,6 +8,7 @@ module Service extend self extend PactBroker::Logging + include SemanticLogger::Loggable def cert_store cert_store = OpenSSL::X509::Store.new diff --git a/lib/pact_broker/config/load.rb b/lib/pact_broker/config/load.rb index cba0cfb22..a952cb52e 100644 --- a/lib/pact_broker/config/load.rb +++ b/lib/pact_broker/config/load.rb @@ -7,7 +7,7 @@ module PactBroker module Config class Load - include PactBroker::Logging + include SemanticLogger::Loggable def self.call configuration new(configuration).call diff --git a/lib/pact_broker/config/save.rb b/lib/pact_broker/config/save.rb index 37a3dd861..aff45da92 100644 --- a/lib/pact_broker/config/save.rb +++ b/lib/pact_broker/config/save.rb @@ -6,7 +6,7 @@ module PactBroker module Config class Save - include PactBroker::Logging + include SemanticLogger::Loggable def self.call configuration, setting_names new(configuration, setting_names).call diff --git a/lib/pact_broker/configuration.rb b/lib/pact_broker/configuration.rb index 42d690a4f..ca7e2b7f7 100644 --- a/lib/pact_broker/configuration.rb +++ b/lib/pact_broker/configuration.rb @@ -1,5 +1,6 @@ require 'pact_broker/error' require 'pact_broker/config/space_delimited_string_list' +require 'semantic_logger' module PactBroker @@ -15,6 +16,7 @@ def self.reset_configuration end class Configuration + include SemanticLogger::Loggable SAVABLE_SETTING_NAMES = [ :order_versions_by_date, @@ -52,10 +54,6 @@ def initialize @api_error_reporters = [] end - def logger - @logger ||= create_logger log_path - end - def self.default_configuration require 'pact_broker/versions/parse_semantic_version' require 'pact_broker/pacts/generate_sha' @@ -202,13 +200,6 @@ def parse_space_delimited_string_list_property property_name, property_value end end - def create_logger path - FileUtils::mkdir_p File.dirname(path) - logger = Logger.new(path) - logger.level = Logger::DEBUG - logger - end - def log_path log_dir + "/pact_broker.log" end diff --git a/lib/pact_broker/default_formatter.rb b/lib/pact_broker/default_formatter.rb new file mode 100644 index 000000000..7875a9349 --- /dev/null +++ b/lib/pact_broker/default_formatter.rb @@ -0,0 +1,18 @@ +require 'logger' +require 'semantic_logger' + +module PactBroker + + module Logging + + class DefaultFormatter < SemanticLogger::Formatters::Default + def initialize + @formatter = ::Logger::Formatter.new + end + + def call(log, output) + @formatter.call(log.level.upcase, log.time, nil, log.message) + end + end + end +end \ No newline at end of file diff --git a/lib/pact_broker/domain/order_versions.rb b/lib/pact_broker/domain/order_versions.rb index bed5f388c..512503ba6 100644 --- a/lib/pact_broker/domain/order_versions.rb +++ b/lib/pact_broker/domain/order_versions.rb @@ -4,7 +4,7 @@ module PactBroker module Domain class OrderVersions - include PactBroker::Logging + include SemanticLogger::Loggable def self.call new_version new_version.lock! diff --git a/lib/pact_broker/domain/webhook_request.rb b/lib/pact_broker/domain/webhook_request.rb index f0b32add8..f72544901 100644 --- a/lib/pact_broker/domain/webhook_request.rb +++ b/lib/pact_broker/domain/webhook_request.rb @@ -53,7 +53,7 @@ def redact? name class WebhookRequest - include PactBroker::Logging + include SemanticLogger::Loggable include PactBroker::Messages HEADERS_TO_REDACT = [/authorization/i, /token/i] diff --git a/lib/pact_broker/logging.rb b/lib/pact_broker/logging.rb index 5a33f48da..ccff07be3 100644 --- a/lib/pact_broker/logging.rb +++ b/lib/pact_broker/logging.rb @@ -1,36 +1,18 @@ -require 'logger' require 'pathname' +require 'semantic_logger' module PactBroker module Logging - - # Need to make this configurable based on the calling app! - LOG_DIR = Pathname.new(File.join(File.dirname(__FILE__), '..', '..', 'log')).cleanpath - LOG_FILE_NAME = "#{ENV['RACK_ENV'] || 'development'}.log" - def self.included(base) base.extend(self) end - def logger= logger - @@logger = logger - end - def log_error e, description = nil message = "#{e.class} #{e.message} #{e.backtrace.join("\n")}" message = "#{description} - #{message}" if description logger.error message end - - def logger - @@logger ||= begin - FileUtils.mkdir_p(LOG_DIR) - logger = Logger.new(File.join(LOG_DIR, LOG_FILE_NAME)) - logger.level = Logger::DEBUG - logger - end - end end include Logging diff --git a/lib/pact_broker/matrix/row.rb b/lib/pact_broker/matrix/row.rb index 784b7b179..aa0c53980 100644 --- a/lib/pact_broker/matrix/row.rb +++ b/lib/pact_broker/matrix/row.rb @@ -24,7 +24,7 @@ class Row < Sequel::Model(:matrix) dataset_module do include PactBroker::Repositories::Helpers - include PactBroker::Logging + include SemanticLogger::Loggable def matching_selectors selectors if selectors.size == 1 diff --git a/lib/pact_broker/pacts/repository.rb b/lib/pact_broker/pacts/repository.rb index 88cf2906c..ff3bd8837 100644 --- a/lib/pact_broker/pacts/repository.rb +++ b/lib/pact_broker/pacts/repository.rb @@ -17,7 +17,7 @@ module PactBroker module Pacts class Repository - include PactBroker::Logging + include SemanticLogger::Loggable include PactBroker::Repositories def create params diff --git a/lib/pact_broker/pacts/service.rb b/lib/pact_broker/pacts/service.rb index a1fbe308e..e7d1da18b 100644 --- a/lib/pact_broker/pacts/service.rb +++ b/lib/pact_broker/pacts/service.rb @@ -11,7 +11,7 @@ module Service extend PactBroker::Repositories extend PactBroker::Services - include PactBroker::Logging + include SemanticLogger::Loggable def find_latest_pact params pact_repository.find_latest_pact(params[:consumer_name], params[:provider_name], params[:tag]) diff --git a/lib/pact_broker/webhooks/job.rb b/lib/pact_broker/webhooks/job.rb index b395a555f..79799da93 100644 --- a/lib/pact_broker/webhooks/job.rb +++ b/lib/pact_broker/webhooks/job.rb @@ -7,6 +7,7 @@ module Webhooks class Job include SuckerPunch::Job + include SemanticLogger::Loggable include PactBroker::Logging def perform data diff --git a/lib/pact_broker/webhooks/webhook_request_template.rb b/lib/pact_broker/webhooks/webhook_request_template.rb index a0e344d73..1bbf234eb 100644 --- a/lib/pact_broker/webhooks/webhook_request_template.rb +++ b/lib/pact_broker/webhooks/webhook_request_template.rb @@ -7,7 +7,7 @@ module PactBroker module Webhooks class WebhookRequestTemplate - include PactBroker::Logging + include SemanticLogger::Loggable include PactBroker::Messages HEADERS_TO_REDACT = [/authorization/i, /token/i] diff --git a/pact_broker.gemspec b/pact_broker.gemspec index 15f61ff4d..0dac04c0c 100644 --- a/pact_broker.gemspec +++ b/pact_broker.gemspec @@ -39,6 +39,7 @@ Gem::Specification.new do |gem| gem.add_runtime_dependency 'rack-protection', '~>2.0' gem.add_runtime_dependency 'dry-types', '~> 0.10.3' # https://travis-ci.org/pact-foundation/pact_broker/jobs/249448621 gem.add_runtime_dependency 'table_print', '~> 1.5' + gem.add_runtime_dependency 'semantic_logger', '~> 4.3' gem.add_development_dependency 'pact', '~>1.14' gem.add_development_dependency 'rspec-pact-matchers', '~>0.1' diff --git a/spec/lib/pact_broker/api/renderers/html_pact_renderer_spec.rb b/spec/lib/pact_broker/api/renderers/html_pact_renderer_spec.rb index c30635be9..611a02465 100644 --- a/spec/lib/pact_broker/api/renderers/html_pact_renderer_spec.rb +++ b/spec/lib/pact_broker/api/renderers/html_pact_renderer_spec.rb @@ -11,6 +11,8 @@ module Renderers ENV['BACKUP_TZ'] = ENV['TZ'] ENV['TZ'] = "Australia/Melbourne" PactBroker.configuration.enable_public_badge_access = true + allow(PactBroker::Api::PactBrokerUrls).to receive(:pact_url).with('', pact).and_return(pact_url) + allow_any_instance_of(HtmlPactRenderer).to receive(:logger).and_return(logger) Timecop.freeze(created_at + 3) end @@ -32,10 +34,7 @@ module Renderers badge_url: 'http://badge' } end - - before do - allow(PactBroker::Api::PactBrokerUrls).to receive(:pact_url).with('', pact).and_return(pact_url) - end + let(:logger) { double('logger').as_null_object } subject { HtmlPactRenderer.call pact, options } @@ -95,8 +94,8 @@ module Renderers end it "logs a warning" do - allow(PactBroker.logger).to receive(:warn).with(/Error/) - expect(PactBroker.logger).to receive(:warn).with(/Could not parse/) + allow(logger).to receive(:warn).with(/Error/) + expect(logger).to receive(:warn).with(/Could not parse/) subject end end diff --git a/spec/lib/pact_broker/api/resources/error_handler_spec.rb b/spec/lib/pact_broker/api/resources/error_handler_spec.rb index cf1ee03ab..c47f2c824 100644 --- a/spec/lib/pact_broker/api/resources/error_handler_spec.rb +++ b/spec/lib/pact_broker/api/resources/error_handler_spec.rb @@ -5,6 +5,12 @@ module Api module Resources describe ErrorHandler do describe "call" do + + before do + allow(ErrorHandler).to receive(:logger).and_return(logger) + end + + let(:logger) { double('logger').as_null_object } let(:error) { StandardError.new('test error') } let(:thing) { double('thing', call: nil, another_call: nil) } let(:options) { { env: env } } @@ -91,7 +97,7 @@ class TestError < StandardError; end end it "logs the error" do - expect(PactBroker.logger).to receive(:error).at_least(1).times + expect(logger).to receive(:error).at_least(1).times subject end diff --git a/spec/lib/pact_broker/badges/service_spec.rb b/spec/lib/pact_broker/badges/service_spec.rb index 2cf243f80..3df0fa61a 100644 --- a/spec/lib/pact_broker/badges/service_spec.rb +++ b/spec/lib/pact_broker/badges/service_spec.rb @@ -10,7 +10,7 @@ module Service let(:label) { nil } let(:initials) { false } let(:verification_status) { :success } - + let(:logger) { double('logger').as_null_object } let(:expected_url) { "https://img.shields.io/badge/#{expected_left_text}-#{expected_right_text}-#{expected_color}.svg" } let(:expected_color) { "brightgreen" } let(:expected_right_text) { "verified" } @@ -24,6 +24,7 @@ module Service before do Service.clear_cache + allow(Service).to receive(:logger).and_return(logger) end it "returns the svg file" do @@ -224,7 +225,7 @@ module Service end it "logs the error" do - expect(PactBroker.logger).to receive(:error).with(/Error retrieving badge from.*shield.*an error/) + expect(logger).to receive(:error).with(/Error retrieving badge from.*shield.*an error/) subject end diff --git a/spec/lib/pact_broker/certificates/service_spec.rb b/spec/lib/pact_broker/certificates/service_spec.rb index fa866e036..ec638bbca 100644 --- a/spec/lib/pact_broker/certificates/service_spec.rb +++ b/spec/lib/pact_broker/certificates/service_spec.rb @@ -4,6 +4,11 @@ module PactBroker module Certificates describe Service do let(:certificate_content) { File.read('spec/fixtures/certificate.pem') } + let(:logger) { double('logger').as_null_object } + + before do + allow(Service).to receive(:logger).and_return(logger) + end describe "#cert_store" do subject { Service.cert_store } @@ -19,7 +24,7 @@ module Certificates end it "logs the error" do - expect(PactBroker.logger).to receive(:error).with(/Error adding certificate/).at_least(1).times + expect(Service).to receive(:log_error).with(/Error adding certificate/).at_least(1).times subject end @@ -46,7 +51,7 @@ module Certificates let(:certificate_content) { File.read('spec/fixtures/certificates/cacert.pem') } it "returns all the X509 Certificate objects" do - expect(PactBroker.logger).to_not receive(:error).with(/Error.*1234/) + expect(logger).to_not receive(:error).with(/Error.*1234/) expect(subject.size).to eq 1 end end @@ -55,7 +60,7 @@ module Certificates let(:certificate_content) { File.read('spec/fixtures/certificate-invalid.pem') } it "logs an error" do - expect(PactBroker.logger).to receive(:error).with(/Error.*1234/) + expect(logger).to receive(:error).with(/Error.*1234/) subject end diff --git a/spec/lib/pact_broker/domain/webhook_request_spec.rb b/spec/lib/pact_broker/domain/webhook_request_spec.rb index f80d07eb3..772ba6876 100644 --- a/spec/lib/pact_broker/domain/webhook_request_spec.rb +++ b/spec/lib/pact_broker/domain/webhook_request_spec.rb @@ -11,6 +11,7 @@ module Domain let(:headers) { {'Content-Type' => 'text/plain', 'Authorization' => 'foo'} } let(:body) { 'reqbody' } let(:logs) { StringIO.new } + let(:logger) { double('logger').as_null_object } let(:execution_logger) { Logger.new(logs) } let(:options) { {failure_log_message: 'oops', show_response: show_response} } let(:show_response) { true } @@ -85,6 +86,12 @@ module Domain to_return(:status => 200, :body => "respbod", :headers => {'Content-Type' => 'text/foo, blah'}) end + before do + allow(WebhookRequest).to receive(:logger).and_return(logger) + allow(WebhookRequest.logger).to receive(:info) + allow(WebhookRequest.logger).to receive(:debug) + end + let(:request_body) { 'reqbody' } it "executes the configured request" do @@ -93,20 +100,18 @@ module Domain end it "logs the request" do - allow(PactBroker.logger).to receive(:info) - allow(PactBroker.logger).to receive(:debug) - expect(PactBroker.logger).to receive(:info).with(/POST.*example/) - expect(PactBroker.logger).to receive(:debug).with(/.*text\/plain/) - expect(PactBroker.logger).to receive(:debug).with(/.*reqbody/) + expect(logger).to receive(:info).with(/POST.*example/) + expect(logger).to receive(:debug).with(/.*text\/plain/) + expect(logger).to receive(:debug).with(/.*reqbody/) execute 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.*200/) - expect(PactBroker.logger).to receive(:debug).with(/text\/foo/) - expect(PactBroker.logger).to receive(:debug).with(/respbod/) + allow(logger).to receive(:info) + allow(logger).to receive(:debug) + expect(logger).to receive(:info).with(/response.*200/) + expect(logger).to receive(:debug).with(/text\/foo/) + expect(logger).to receive(:debug).with(/respbod/) execute end @@ -301,11 +306,11 @@ class WebhookTestError < StandardError; end before do allow(Net::HTTP).to receive(:start).and_raise(WebhookTestError.new("blah")) - allow(PactBroker.logger).to receive(:error) + allow(logger).to receive(:error) end it "logs the error" do - expect(PactBroker.logger).to receive(:error).with(/Error.*WebhookTestError.*blah/) + expect(logger).to receive(:error).with(/Error.*WebhookTestError.*blah/) execute end diff --git a/spec/lib/pact_broker/webhooks/job_spec.rb b/spec/lib/pact_broker/webhooks/job_spec.rb index 387bb771b..1b982493b 100644 --- a/spec/lib/pact_broker/webhooks/job_spec.rb +++ b/spec/lib/pact_broker/webhooks/job_spec.rb @@ -9,11 +9,13 @@ module Webhooks allow(PactBroker::Webhooks::Service).to receive(:execute_triggered_webhook_now).and_return(result) allow(PactBroker::Webhooks::Service).to receive(:update_triggered_webhook_status) allow(PactBroker::Webhooks::TriggeredWebhook).to receive(:find).and_return(triggered_webhook) + allow(Job).to receive(:logger).and_return(logger) end let(:triggered_webhook) { instance_double("PactBroker::Webhooks::TriggeredWebhook", webhook_uuid: '1234', id: 1) } let(:result) { instance_double("PactBroker::Domain::WebhookExecutionResult", success?: success)} let(:success) { true } + let(:logger) { double('logger').as_null_object } subject { Job.new.perform(triggered_webhook: triggered_webhook) }