Merge pull request #109 from FundingCircle/loga-sidekiq-integration

Loga Sidekiq integration

.gitignore

@@ -25,3 +25,5 @@ spec/fixtures/**/*.log
 gemfiles/*.lock
 vendor/bundle
 .byebug_history
+.DS_Store
+

.rubocop.yml

@@ -4,6 +4,7 @@ AllCops:
     - 'gemfiles/*'
     - 'spec/fixtures/**/*'
     - 'vendor/bundle/**/*'
+    - 'gemfiles/vendor/bundle/**/*'
 
 require: rubocop-rspec
 

Appraisals

@@ -24,5 +24,9 @@ appraise 'rails52' do
   gem 'rails', '~> 5.2.0'
 end
 
+appraise 'sidekiq51' do
+  gem 'sidekiq', '~> 5.1.0'
+end
+
 appraise 'unit' do
 end

CHANGELOG.md

@@ -4,6 +4,10 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/)
 and this project adheres to [Semantic Versioning](http://semver.org/).
 
+## [2.3.0] - 2018-06-29
+### Added
+Support for Sidekiq `~> 5.0`.
+
 ## [2.2.0] - 2018-05-10
 ### Added
 Subscribe to `ActionMailer` events

Guardfile

@@ -39,6 +39,20 @@ group :rails do
   end
 end
 
+group :sidekiq do
+  cmd = 'bundle exec appraisal sidekiq51 rspec'
+
+  guard :rspec, all_on_start: true, cmd: cmd do
+    watch('lib/loga/sidekiq/job_logger.rb') do
+      [
+        'spec/integration/sidekiq_spec.rb',
+        'spec/loga/sidekiq/job_logger_spec.rb',
+        'spec/loga/sidekiq_spec.rb',
+      ]
+    end
+  end
+end
+
 group :unit do
   guard :rspec, cmd: 'bundle exec appraisal unit rspec' do
     watch(%r{^spec/unit/.+_spec\.rb$})

README.md

@@ -148,6 +148,10 @@ environment variable therefore it must be removed.
 LOGA_FORMAT=simple rackup
 ```
 
+### Sidekiq
+
+Loga `2.3` provides an out-of-the-box support for `Sidekiq ~> 5.0`.
+
 ## Output Example
 
 ### GELF Format

gemfiles/sidekiq51.gemfile

@@ -0,0 +1,11 @@
+# This file was generated by Appraisal
+
+source "https://rubygems.org"
+
+gem "sidekiq", "~> 5.1.0"
+
+group :test do
+  gem "simplecov"
+end
+
+gemspec path: "../"

lib/loga.rb

@@ -8,8 +8,8 @@
 require 'loga/rack/request'
 require 'loga/rack/request_id'
 require 'loga/railtie' if defined?(Rails)
+require 'loga/sidekiq'
 
-# rubocop:disable Naming/MemoizedInstanceVariableName
 module Loga
   ConfigurationError = Class.new(StandardError)
 
@@ -26,6 +26,8 @@ def self.configure(options, framework_options = {})
     raise ConfigurationError, 'Loga has already been configured' if @configuration
 
     @configuration ||= Configuration.new(options, framework_options)
+
+    Loga::Sidekiq.configure_logging
   end
 
   def self.logger
@@ -36,4 +38,3 @@ def self.reset
     @configuration = nil
   end
 end
-# rubocop:enable Naming/MemoizedInstanceVariableName

lib/loga/sidekiq.rb

@@ -0,0 +1,16 @@
+require 'loga/sidekiq/job_logger'
+
+module Loga
+  module Sidekiq
+    def self.configure_logging
+      return unless defined?(::Sidekiq)
+      return if Gem::Version.new(::Sidekiq::VERSION) < Gem::Version.new('5.0')
+
+      ::Sidekiq.configure_server do |config|
+        config.options[:job_logger] = Loga::Sidekiq::JobLogger
+      end
+
+      ::Sidekiq::Logging.logger = Loga.configuration.logger
+    end
+  end
+end

lib/loga/sidekiq/job_logger.rb

@@ -0,0 +1,62 @@
+module Loga
+  module Sidekiq
+    # The approach of using a custom job logger in sidekiq was introduced
+    # in v5.0: https://github.com/mperham/sidekiq/pull/3235
+    # This job logger does not support logging for Sidekiq versions
+    # that are before 5.0
+    class JobLogger
+      include Loga::Utilities
+
+      EVENT_TYPE = 'sidekiq'.freeze
+
+      attr_reader :started_at, :data
+
+      def initialize
+        @started_at = Time.now
+        @data = {}
+      end
+
+      def call(item, _queue)
+        yield
+      rescue Exception => ex # rubocop:disable Lint/RescueException
+        data['exception'] = ex
+
+        raise
+      ensure
+        assign_data(item)
+        send_message
+      end
+
+      private
+
+      def assign_data(item)
+        data['created_at']  = item['created_at']
+        data['enqueued_at'] = item['enqueued_at']
+        data['jid']         = item['jid']
+        data['queue']       = item['queue']
+        data['retry']       = item['retry']
+        data['params']      = item['args']
+        data['class']       = item['class']
+        data['duration']    = duration_in_ms(started_at)
+      end
+
+      def short_message
+        "#{data['class']} with jid: '#{data['jid']}' executed in #{data['duration']}ms"
+      end
+
+      def send_message
+        event = Event.new(data: data, message: short_message, type: EVENT_TYPE)
+
+        logger.public_send(compute_level, event)
+      end
+
+      def compute_level
+        data.key?('exception') ? :warn : :info
+      end
+
+      def logger
+        Loga.logger
+      end
+    end
+  end
+end

lib/loga/utilities.rb

@@ -1,6 +1,6 @@
 module Loga
   module Utilities
-    def duration_in_ms(started_at, ended_at)
+    def duration_in_ms(started_at, ended_at = Time.now)
       ((ended_at - started_at) * 1000).round
     end
   end

lib/loga/version.rb

@@ -1,3 +1,3 @@
 module Loga
-  VERSION = '2.2.0'.freeze
+  VERSION = '2.3.0'.freeze
 end

loga.gemspec

@@ -30,6 +30,7 @@ Gem::Specification.new do |spec|
   spec.add_development_dependency 'pry'
   spec.add_development_dependency 'rack-test'
   spec.add_development_dependency 'rake'
+  spec.add_development_dependency 'fakeredis'
   spec.add_development_dependency 'rspec',    '~> 3.7.0'
   spec.add_development_dependency 'rubocop',  '~> 0.57.0'
   spec.add_development_dependency 'rubocop-rspec'

spec/integration/sidekiq_spec.rb

@@ -0,0 +1,131 @@
+require 'spec_helper'
+require 'timecop'
+require 'fakeredis'
+
+dummy_redis_config = ConnectionPool.new(size: 5) { Redis.new }
+
+Sidekiq.configure_client do |config|
+  config.redis = dummy_redis_config
+end
+
+Sidekiq.configure_server do |config|
+  config.redis = dummy_redis_config
+end
+
+class MySidekiqWorker
+  include Sidekiq::Worker
+
+  def perform(_name); end
+end
+
+describe 'Sidekiq client logger' do
+  let(:target) { StringIO.new }
+
+  let(:json_line) do
+    target.rewind
+    JSON.parse(target.read)
+  end
+
+  before do
+    Redis.current.flushall
+
+    Loga.reset
+
+    Loga.configure(
+      service_name: 'hello_world_app',
+      service_version: '1.0',
+      device: target,
+      format: :gelf,
+    )
+  end
+
+  it 'has the proper job logger' do
+    job_logger = Loga::Sidekiq::JobLogger
+
+    expect(Sidekiq.options[:job_logger]).to eq job_logger
+  end
+
+  it 'has the proper logger Sidekiq::Logging.logger' do
+    expect(Sidekiq::Logging.logger).to eq Loga.logger
+  end
+
+  it 'has the proper logger for Sidekiq.logger' do
+    expect(Sidekiq.logger).to eq Loga.logger
+  end
+
+  it 'pushes a new element in the default queue' do
+    MySidekiqWorker.perform_async('Bob')
+
+    last_element = JSON.parse(Redis.current.lpop('queue:default'))
+
+    aggregate_failures do
+      expect(last_element['class']).to eq 'MySidekiqWorker'
+      expect(last_element['args']).to eq ['Bob']
+      expect(last_element['retry']).to eq true
+      expect(last_element['queue']).to eq 'default'
+    end
+  end
+
+  if ENV['BUNDLE_GEMFILE'] =~ /sidekiq51/
+    # https://github.com/mperham/sidekiq/blob/97363210b47a4f8a1d8c1233aaa059d6643f5040/test/test_actors.rb#L57-L79
+    let(:mgr) do
+      Class.new do
+        attr_reader :latest_error, :mutex, :cond
+
+        def initialize
+          @mutex = ::Mutex.new
+          @cond = ::ConditionVariable.new
+        end
+
+        def processor_died(_inst, err)
+          @latest_error = err
+
+          @mutex.synchronize { @cond.signal }
+        end
+
+        def processor_stopped(_inst)
+          @mutex.synchronize { @cond.signal }
+        end
+
+        def options
+          {
+            concurrency: 3,
+            queues: ['default'],
+            job_logger: Loga::Sidekiq::JobLogger,
+          }
+        end
+      end
+    end
+
+    it 'logs the job processing event' do
+      MySidekiqWorker.perform_async('Bob')
+
+      require 'sidekiq/processor'
+      Sidekiq::Processor.new(mgr.new).start
+      sleep 0.5
+
+      expected_attributes = {
+        '_queue'=> 'default',
+        '_retry'=> true,
+        '_params'=> ['Bob'],
+        '_class'=> 'MySidekiqWorker',
+        '_type'=> 'sidekiq',
+        '_service.name'=> 'hello_world_app',
+        '_service.version'=> '1.0',
+        '_tags'=> '',
+        'level'=> 6,
+        'version'=> '1.1',
+      }
+
+      aggregate_failures do
+        expect(json_line).to include(expected_attributes)
+
+        %w[_created_at _enqueued_at _jid _duration timestamp host].each do |key|
+          expect(json_line).to have_key(key)
+        end
+
+        expect(json_line['short_message']).to match(/MySidekiqWorker with jid:*/)
+      end
+    end
+  end
+end