Skip to content

Commit

Permalink
Merge branch 'master' into metrics
Browse files Browse the repository at this point in the history
  • Loading branch information
reidmorrison committed Jul 8, 2024
2 parents 4697c01 + 6e1291f commit 1f8bcf0
Show file tree
Hide file tree
Showing 15 changed files with 212 additions and 208 deletions.
3 changes: 3 additions & 0 deletions .github/FUNDING.yml
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
# These are supported funding model platforms

github: reidmorrison
2 changes: 2 additions & 0 deletions .github/workflows/ci.yml
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,8 @@ jobs:

- rails: "7.1"
ruby: "3.1"
- rails: "7.1b"
ruby: "3.1"
- rails: "7.1.1"
ruby: "3.2"
- rails: "7.1"
Expand Down
6 changes: 6 additions & 0 deletions Appraisals
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,12 @@ appraise "rails_7.1" do
gem "sqlite3", "~> 1.4"
end

appraise "rails_7.1b" do
gem "rails", "~> 7.1.0"
gem "sidekiq", "~> 7.3.0"
gem "sqlite3", "~> 1.4"
end

appraise "rails_7.2" do
gem "rails", "~> 7.2.0.beta2"
gem "sidekiq", "~> 7.2.4"
Expand Down
18 changes: 18 additions & 0 deletions gemfiles/rails_7.1b.gemfile
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
# This file was generated by Appraisal

source "https://rubygems.org"

gem "appraisal"
gem "puma"
gem "active_model_serializers"
gem "amazing_print"
gem "minitest"
gem "minitest-rails"
gem "rake"
gem "sprockets", "< 4.0"
gem "rails", "~> 7.1.0"
gem "sidekiq", "~> 7.3.0"
gem "sqlite3", "~> 1.4"
gem "rubocop"

gemspec path: "../"
6 changes: 6 additions & 0 deletions lib/rails_semantic_logger.rb
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,12 @@ module DelayedJob
autoload :Plugin, "rails_semantic_logger/delayed_job/plugin"
end

module Sidekiq
autoload :Defaults, "rails_semantic_logger/sidekiq/defaults"
autoload :JobLogger, "rails_semantic_logger/sidekiq/job_logger"
autoload :Loggable, "rails_semantic_logger/sidekiq/loggable"
end

autoload :Options, "rails_semantic_logger/options"

# Swap an existing subscriber with a new one
Expand Down
35 changes: 27 additions & 8 deletions lib/rails_semantic_logger/engine.rb
Original file line number Diff line number Diff line change
Expand Up @@ -108,12 +108,31 @@ class Engine < ::Rails::Engine
Resque.logger = SemanticLogger[Resque] if defined?(Resque) && Resque.respond_to?(:logger=)

# Replace the Sidekiq logger
if defined?(Sidekiq)
if Sidekiq.respond_to?(:logger=)
Sidekiq.logger = SemanticLogger[Sidekiq]
elsif Sidekiq::VERSION[0..1] == "7."
method = Sidekiq.server? ? :configure_server : :configure_client
Sidekiq.public_send(method) { |cfg| cfg.logger = SemanticLogger[Sidekiq] }
if defined?(::Sidekiq)
::Sidekiq.configure_client do |config|
config.logger = ::SemanticLogger[::Sidekiq]
end

::Sidekiq.configure_server do |config|
config.logger = ::SemanticLogger[::Sidekiq]
if config.respond_to?(:options)
config.options[:job_logger] = RailsSemanticLogger::Sidekiq::JobLogger
else
config[:job_logger] = RailsSemanticLogger::Sidekiq::JobLogger
end

# Add back the default console logger unless already added
SemanticLogger.add_appender(io: $stdout, formatter: :color) unless SemanticLogger.appenders.console_output?

# Replace default error handler when present
existing = RailsSemanticLogger::Sidekiq::Defaults.delete_default_error_handler(config.error_handlers)
config.error_handlers << RailsSemanticLogger::Sidekiq::Defaults::ERROR_HANDLER if existing
end

if defined?(::Sidekiq::Job) && (::Sidekiq::VERSION.to_i != 5)
::Sidekiq::Job.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
else
::Sidekiq::Worker.singleton_class.prepend(RailsSemanticLogger::Sidekiq::Loggable)
end
end

Expand Down Expand Up @@ -154,15 +173,15 @@ class Engine < ::Rails::Engine

if config.rails_semantic_logger.semantic
# Active Job
if defined?(::ActiveJob) && defined?(::ActiveJob::Logging::LogSubscriber)
if defined?(::ActiveJob::Logging::LogSubscriber)
RailsSemanticLogger.swap_subscriber(
::ActiveJob::Logging::LogSubscriber,
RailsSemanticLogger::ActiveJob::LogSubscriber,
:active_job
)
end

if defined?(::ActiveJob) && defined?(::ActiveJob::LogSubscriber)
if defined?(::ActiveJob::LogSubscriber)
RailsSemanticLogger.swap_subscriber(
::ActiveJob::LogSubscriber,
RailsSemanticLogger::ActiveJob::LogSubscriber,
Expand Down
178 changes: 3 additions & 175 deletions lib/rails_semantic_logger/extensions/sidekiq/sidekiq.rb
Original file line number Diff line number Diff line change
@@ -1,89 +1,14 @@
# Sidekiq patches
#
# To re-enable stdout logging for sidekiq server processes, add the following snippet to config/initializers/sidekiq.rb:
# Sidekiq.configure_server do |config|
# SemanticLogger.add_appender(io: $stdout, level: :debug, formatter: :color)
# end
if Sidekiq::VERSION.to_i == 4
require "sidekiq/exception_handler"
require "sidekiq/logging"
require "sidekiq/middleware/server/logging"
require "sidekiq/processor"
require "sidekiq/worker"
elsif Sidekiq::VERSION.to_i == 5
require "sidekiq/exception_handler"
require "sidekiq/job_logger"
require "sidekiq/logging"
require "sidekiq/worker"
elsif Sidekiq::VERSION.to_i == 6 && Sidekiq::VERSION.to_f < 6.5
require "sidekiq/exception_handler"
require "sidekiq/job_logger"
require "sidekiq/worker"
elsif Sidekiq::VERSION.to_i == 6
require "sidekiq/job_logger"
require "sidekiq/worker"
else
require "sidekiq/config"
require "sidekiq/job_logger"
require "sidekiq/job"
end

module Sidekiq
# Sidekiq > v4
if defined?(::Sidekiq::JobLogger)
# Let Semantic Logger handle duration logging
class JobLogger
def call(item, queue, &block)
klass = item["wrapped"] || item["class"]
logger = klass ? SemanticLogger[klass] : Sidekiq.logger

SemanticLogger.tagged(queue: queue) do
# Latency is the time between when the job was enqueued and when it started executing.
logger.info(
"Start #perform",
metric: "sidekiq.queue.latency",
metric_amount: job_latency_ms(item)
)

# Measure the duration of running the job
logger.measure_info(
"Completed #perform",
on_exception_level: :error,
log_exception: :full,
metric: "sidekiq.job.perform",
&block
)
end
end

def prepare(job_hash, &block)
level = job_hash["log_level"]
if level
SemanticLogger.silence(level) do
SemanticLogger.tagged(job_hash_context(job_hash), &block)
end
else
SemanticLogger.tagged(job_hash_context(job_hash), &block)
end
end

def job_hash_context(job_hash)
h = {jid: job_hash["jid"]}
h[:bid] = job_hash["bid"] if job_hash["bid"]
h[:tags] = job_hash["tags"] if job_hash["tags"]
h[:queue] = job_hash["queue"] if job_hash["queue"]
h
end

def job_latency_ms(job)
return unless job && job["enqueued_at"]

(Time.now.to_f - job["enqueued_at"].to_f) * 1000
end
end
end

# Sidekiq <= v6
# Sidekiq v4 & v5
if defined?(::Sidekiq::Logging)
# Replace Sidekiq logging context
module Logging
Expand All @@ -100,106 +25,8 @@ def self.job_hash_context(job_hash)
end
end

# Exception is already logged by Semantic Logger during the perform call
if defined?(::Sidekiq::ExceptionHandler)
# Sidekiq <= v6.5
module ExceptionHandler
class Logger
def call(_exception, ctx)
return if ctx.empty?

job_hash = ctx[:job] || {}
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
end
end
end
elsif defined?(::Sidekiq::Config)
# Sidekiq >= v7
class Config
remove_const :ERROR_HANDLER

ERROR_HANDLER = ->(ex, ctx, cfg = Sidekiq.default_configuration) do
unless ctx.empty?
job_hash = ctx[:job] || {}
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
end
end
end
elsif Sidekiq.error_handlers.delete(Sidekiq::DEFAULT_ERROR_HANDLER)
# Sidekiq >= 6.5
# Replace default error handler if present
Sidekiq.error_handlers << ->(ex, ctx) do
unless ctx.empty?
job_hash = ctx[:job] || {}
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
end
end
end

# Logging within each worker should use its own logger
case Sidekiq::VERSION.to_i
when 4
module Worker
def self.included(base)
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}"
end

base.extend(ClassMethods)
base.include(SemanticLogger::Loggable)
base.class_attribute :sidekiq_options_hash
base.class_attribute :sidekiq_retry_in_block
base.class_attribute :sidekiq_retries_exhausted_block
end
end
when 5
module Worker
def self.included(base)
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
raise ArgumentError, "You cannot include Sidekiq::Worker in an ActiveJob: #{base.name}"
end

base.extend(ClassMethods)
base.include(SemanticLogger::Loggable)
base.sidekiq_class_attribute :sidekiq_options_hash
base.sidekiq_class_attribute :sidekiq_retry_in_block
base.sidekiq_class_attribute :sidekiq_retries_exhausted_block
end
end
when 6
module Worker
def self.included(base)
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
raise ArgumentError, "Sidekiq::Worker cannot be included in an ActiveJob: #{base.name}"
end

base.include(Options)
base.extend(ClassMethods)
base.include(SemanticLogger::Loggable)
end
end
else
module Job
def self.included(base)
if base.ancestors.any? { |c| c.name == "ActiveJob::Base" }
raise ArgumentError, "Sidekiq::Job cannot be included in an ActiveJob: #{base.name}"
end

base.include(Options)
base.extend(ClassMethods)
base.include(SemanticLogger::Loggable)
end
end
end

# Sidekiq v4
if defined?(::Sidekiq::Middleware::Server::Logging)
# Sidekiq v4
# Convert string to machine readable format
class Processor
def log_context(job_hash)
Expand All @@ -214,6 +41,7 @@ def log_context(job_hash)
module Middleware
module Server
class Logging
# rubocop:disable Style/ExplicitBlockArgument
def call(worker, item, queue)
SemanticLogger.tagged(queue: queue) do
worker.logger.info(
Expand Down
40 changes: 40 additions & 0 deletions lib/rails_semantic_logger/sidekiq/defaults.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,40 @@
module RailsSemanticLogger
module Sidekiq
module Defaults
# Prevent exception logging during standard error handling since the Job Logger below already logs the exception.
ERROR_HANDLER =
if ::Sidekiq::VERSION.to_f < 7.1 ||
(::Sidekiq::VERSION.to_f == 7.1 && ::Sidekiq::VERSION.split(".").last.to_i < 6)
lambda do |_ex, ctx|
unless ctx.empty?
job_hash = ctx[:job] || {}
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
end
end
else
lambda do |_ex, ctx, _default_configuration|
unless ctx.empty?
job_hash = ctx[:job] || {}
klass = job_hash["display_class"] || job_hash["wrapped"] || job_hash["class"]
logger = klass ? SemanticLogger[klass] : Sidekiq.logger
ctx[:context] ? logger.warn(ctx[:context], ctx) : logger.warn(ctx)
end
end
end

# Returns the default logger after removing from the supplied list.
# Returns [nil] when the default logger was not present.
def self.delete_default_error_handler(error_handlers)
return error_handlers.delete(::Sidekiq::Config::ERROR_HANDLER) if defined?(::Sidekiq::Config::ERROR_HANDLER)
return error_handlers.delete(::Sidekiq::DEFAULT_ERROR_HANDLER) if defined?(::Sidekiq::DEFAULT_ERROR_HANDLER)

return unless defined?(::Sidekiq::ExceptionHandler)

existing = error_handlers.find { |handler| handler.is_a?(::Sidekiq::ExceptionHandler::Logger) }
error_handlers.delete(existing) if existing
end
end
end
end
Loading

0 comments on commit 1f8bcf0

Please sign in to comment.