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

Author: mefellows

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

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

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

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

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

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 = {}

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

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

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

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

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

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!

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]
 

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

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

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

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])

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

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]
 

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'

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

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
 

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