From fa0b2caf5c4ec518c1de8882a71ed6862c00a014 Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 12:06:23 -0700 Subject: [PATCH 1/9] Upgrade gems, no more old Sidekiq (use 8) --- .github/workflows/pr-checks.yml | 4 ++-- .rubocop.yml | 2 +- Gemfile.oldgems | 6 ------ appydays.gemspec | 16 ++++++++-------- 4 files changed, 11 insertions(+), 17 deletions(-) delete mode 100644 Gemfile.oldgems diff --git a/.github/workflows/pr-checks.yml b/.github/workflows/pr-checks.yml index 352cf20..10ea144 100644 --- a/.github/workflows/pr-checks.yml +++ b/.github/workflows/pr-checks.yml @@ -8,8 +8,8 @@ jobs: strategy: fail-fast: false matrix: - ruby: ['3.1', '3.2', '3.3'] - gemfile: ['Gemfile', 'Gemfile.oldgems', 'Gemfile.sentry'] + ruby: ['3.2', '3.3', '3.4'] + gemfile: ['Gemfile', 'Gemfile.sentry'] runs-on: ubuntu-latest env: BUNDLE_GEMFILE: ${{ matrix.gemfile }} diff --git a/.rubocop.yml b/.rubocop.yml index 1e104c8..3458d44 100644 --- a/.rubocop.yml +++ b/.rubocop.yml @@ -4,7 +4,7 @@ require: - rubocop-sequel AllCops: - TargetRubyVersion: 3.1 + TargetRubyVersion: 3.2 NewCops: enable SuggestExtensions: false diff --git a/Gemfile.oldgems b/Gemfile.oldgems deleted file mode 100644 index 415ad3d..0000000 --- a/Gemfile.oldgems +++ /dev/null @@ -1,6 +0,0 @@ -# frozen_string_literal: true - -source "https://rubygems.org" - -gemspec -gem "sidekiq", '= 6.4' diff --git a/appydays.gemspec b/appydays.gemspec index 565cb0a..d54c8c3 100644 --- a/appydays.gemspec +++ b/appydays.gemspec @@ -10,26 +10,26 @@ Gem::Specification.new do |s| s.author = "Lithic Tech" s.homepage = "https://github.com/lithictech/appydays" s.licenses = "MIT" - s.required_ruby_version = ">= 3.1.0" + s.required_ruby_version = ">= 3.2.0" s.description = <<~DESC appydays provides support for env-based configuration, and common structured logging capabilities DESC s.files = Dir["lib/**/*.rb"] - s.add_dependency("dotenv", "~> 2.7") + s.add_dependency("dotenv", "~> 3.1") s.add_dependency("semantic_logger", "~> 4.6") s.add_development_dependency("httparty", "~> 0.20") s.add_development_dependency("monetize", "~> 1.0") s.add_development_dependency("money", "~> 6.0") - s.add_development_dependency("rack", "~> 2.2") + s.add_development_dependency("rack", "~> 3.1") s.add_development_dependency("rspec", "~> 3.10") s.add_development_dependency("rspec-core", "~> 3.10") s.add_development_dependency("rspec-json_expectations", "~> 2.2") - s.add_development_dependency("rubocop", "~> 1.31.1") - s.add_development_dependency("rubocop-performance", "~> 1.14.2") - s.add_development_dependency("rubocop-rake", "~> 0.6.0") - s.add_development_dependency("rubocop-sequel", "~> 0.3.4") + s.add_development_dependency("rubocop", "~> 1.77.0") + s.add_development_dependency("rubocop-performance", "~> 1.25.0") + s.add_development_dependency("rubocop-rake", "~> 0.7.1") + s.add_development_dependency("rubocop-sequel", "~> 0.4.1") s.add_development_dependency("sequel", "~> 5.0") - s.add_development_dependency("sidekiq", "~> 6.0") + s.add_development_dependency("sidekiq", "~> 8.0") s.add_development_dependency("simplecov", "~> 0.22") s.add_development_dependency("webmock", "~> 3.1") s.metadata["rubygems_mfa_required"] = "true" From 066a8a25b40d12e9934e8077b74cbdf38d89a5fd Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 12:10:26 -0700 Subject: [PATCH 2/9] upgrade rubocop --- .rubocop.yml | 11 ++++++----- lib/appydays/configurable.rb | 12 ++++++------ lib/appydays/dotenviable.rb | 2 +- lib/appydays/loggable/sidekiq_job_logger.rb | 4 ++-- lib/appydays/loggable/spec_helpers.rb | 2 +- spec/appydays/loggable_spec.rb | 2 +- 6 files changed, 17 insertions(+), 16 deletions(-) diff --git a/.rubocop.yml b/.rubocop.yml index 3458d44..f9b66fd 100644 --- a/.rubocop.yml +++ b/.rubocop.yml @@ -1,4 +1,4 @@ -require: +plugins: - rubocop-performance - rubocop-rake - rubocop-sequel @@ -8,6 +8,9 @@ AllCops: NewCops: enable SuggestExtensions: false +Gemspec/DevelopmentDependencies: + Enabled: false + Layout/ParameterAlignment: EnforcedStyle: with_fixed_indentation Layout/CaseIndentation: @@ -68,15 +71,13 @@ Lint/UselessAssignment: # https://rubocop.readthedocs.io/en/latest/cops_naming/ Naming/AccessorMethodName: Enabled: false -Naming/PredicateName: +Naming/PredicatePrefix: Exclude: - 'spec/**/*' - 'lib/appydays/spec_helpers.rb' Naming/MethodParameterName: Enabled: false -Sequel/ColumnDefault: - Enabled: false Sequel/ConcurrentIndex: Enabled: false @@ -96,7 +97,7 @@ Style/Documentation: Style/FormatString: EnforcedStyle: percent Style/NumericPredicate: - IgnoredMethods: ['where'] + AllowedMethods: ['where'] Style/RedundantReturn: Enabled: false Style/RedundantSelf: diff --git a/lib/appydays/configurable.rb b/lib/appydays/configurable.rb index 578614e..f474e2a 100644 --- a/lib/appydays/configurable.rb +++ b/lib/appydays/configurable.rb @@ -107,7 +107,7 @@ def setting(name, default, key: nil, convert: nil, side_effect: nil) @target.define_singleton_method(name) do self.class_variable_get("@@#{name}") end - @target.define_singleton_method("#{name}=".to_sym) do |v| + @target.define_singleton_method(:"#{name}=") do |v| installer._set_value(name, v, side_effect) end @@ -136,10 +136,10 @@ def after_configured(&block) def _converter(default, converter) return converter if converter - return ->(v) { v.to_s } if default.nil? || default.is_a?(String) - return ->(v) { v.to_i } if default.is_a?(Integer) - return ->(v) { v.to_f } if default.is_a?(Float) - return ->(v) { v.to_sym } if default.is_a?(Symbol) + return lambda(&:to_s) if default.nil? || default.is_a?(String) + return lambda(&:to_i) if default.is_a?(Integer) + return lambda(&:to_f) if default.is_a?(Float) + return lambda(&:to_sym) if default.is_a?(Symbol) return ->(v) { v.casecmp("true").zero? } if [TrueClass, FalseClass].include?(default.class) raise TypeError, "Uncoercable type %p" % [default.class] end @@ -161,7 +161,7 @@ def _run_after_configured def _reset(overrides) @settings.each do |k, v| real_v = overrides.fetch(k, v) - @target.send("#{k}=".to_sym, real_v) + @target.send(:"#{k}=", real_v) end self._run_after_configured end diff --git a/lib/appydays/dotenviable.rb b/lib/appydays/dotenviable.rb index d43f36b..667a87b 100644 --- a/lib/appydays/dotenviable.rb +++ b/lib/appydays/dotenviable.rb @@ -41,7 +41,7 @@ def self.load(rack_env: nil, default_rack_env: "development", env: ENV) ".env", ] orig_env = nil - if env.object_id != ENV.object_id + unless env.equal?(ENV) orig_env = ENV.to_h ENV.replace(env) end diff --git a/lib/appydays/loggable/sidekiq_job_logger.rb b/lib/appydays/loggable/sidekiq_job_logger.rb index 6bebba3..2bb4a5f 100644 --- a/lib/appydays/loggable/sidekiq_job_logger.rb +++ b/lib/appydays/loggable/sidekiq_job_logger.rb @@ -47,9 +47,9 @@ def call(item, _queue, &) yield duration = self.elapsed(start) log_method = if duration >= self.slow_job_seconds - (self.log_level_slow_job || :warn) + self.log_level_slow_job || :warn else - (self.log_level_job_done || :info) + self.log_level_job_done || :info end self.logger.send(log_method, "job_done", duration: duration * 1000, **extra_tags, **self.class.job_tags) rescue StandardError diff --git a/lib/appydays/loggable/spec_helpers.rb b/lib/appydays/loggable/spec_helpers.rb index db93553..9831520 100644 --- a/lib/appydays/loggable/spec_helpers.rb +++ b/lib/appydays/loggable/spec_helpers.rb @@ -7,7 +7,7 @@ def self.included(context) # Appydays::Loggable.ensure_stderr_appender context.around(:each) do |example| - override_level = (example.metadata[:log] || example.metadata[:logging]) + override_level = example.metadata[:log] || example.metadata[:logging] if override_level orig_level = SemanticLogger.default_level SemanticLogger.default_level = override_level diff --git a/spec/appydays/loggable_spec.rb b/spec/appydays/loggable_spec.rb index 0930386..4a42a83 100644 --- a/spec/appydays/loggable_spec.rb +++ b/spec/appydays/loggable_spec.rb @@ -199,7 +199,7 @@ def generate_stack_trace(i=0) describe Appydays::Loggable::RequestLogger do def run_app(app, opts: {}, loggers: [], env: {}, cls: Appydays::Loggable::RequestLogger) - rl = cls.new(app, **opts.merge(reraise: false)) + rl = cls.new(app, **opts, reraise: false) return capture_logs_from(loggers << rl.logger, formatter: :json) do _, _, body = rl.call(env) body&.close From 0a7e8f2a4302336b344e65524d87840be0b95dfb Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 13:12:10 -0700 Subject: [PATCH 3/9] Fix internals changed with upgrade --- lib/appydays/loggable/request_logger.rb | 2 +- lib/appydays/loggable/sidekiq_job_logger.rb | 18 +++++++++--------- spec/appydays/loggable_spec.rb | 16 ++++++++-------- 3 files changed, 18 insertions(+), 18 deletions(-) diff --git a/lib/appydays/loggable/request_logger.rb b/lib/appydays/loggable/request_logger.rb index 2e3d10e..6c5421a 100644 --- a/lib/appydays/loggable/request_logger.rb +++ b/lib/appydays/loggable/request_logger.rb @@ -48,7 +48,7 @@ def call(env) status, header, body = SemanticLogger.named_tagged(request_id:) do @app.call(env) end - header = Rack::Utils::HeaderHash.new(header) + header = Rack::Headers.new(header) body = Rack::BodyProxy.new(body) { self.log_finished(env, began_at, status, header) } [status, header, body] rescue StandardError => e diff --git a/lib/appydays/loggable/sidekiq_job_logger.rb b/lib/appydays/loggable/sidekiq_job_logger.rb index 2bb4a5f..6c8fe97 100644 --- a/lib/appydays/loggable/sidekiq_job_logger.rb +++ b/lib/appydays/loggable/sidekiq_job_logger.rb @@ -1,8 +1,9 @@ # frozen_string_literal: true require "sidekiq" -require "sidekiq/version" +require "sidekiq/component" require "sidekiq/job_logger" +require "sidekiq/version" require "appydays/loggable" require "appydays/configurable" @@ -10,15 +11,14 @@ class Appydays::Loggable::SidekiqJobLogger < Sidekiq::JobLogger include Appydays::Configurable include Appydays::Loggable - begin - require "sidekiq/util" - include Sidekiq::Util - rescue LoadError - require "sidekiq/component" - include Sidekiq::Component - end + include Sidekiq::Component - Sidekiq.logger = self.logger + Sidekiq.configure_client do |config| + config.logger = self.logger + end + Sidekiq.configure_server do |config| + config.logger = self.logger + end # Level to log 'job_done' messages at. # Defaults to +:info+. diff --git a/spec/appydays/loggable_spec.rb b/spec/appydays/loggable_spec.rb index 4a42a83..c244b04 100644 --- a/spec/appydays/loggable_spec.rb +++ b/spec/appydays/loggable_spec.rb @@ -104,8 +104,8 @@ def generate_stack_trace(i=0) rescue RuntimeError => e logger1.info("hello", e) end - expect(lines[0]).to match(%r{:in `generate_stack_trace'","skipped \d\d\d frames","/}) - expect(lines[0]).to have_attributes(length: be_between(680, 730)) + expect(lines[0]).to match(%r{:in '.*generate_stack_trace'","skipped \d\d\d frames","/}) + expect(lines[0]).to have_attributes(length: be_between(700, 900)) end it "ignores non-array stack_trace keys" do @@ -353,16 +353,16 @@ def self.name end end - let(:logger) { logcls.new } + let(:logger) { logcls.new(Sidekiq::Config.new) } - def log(&block) + def log(reraise: true, &block) block ||= proc {} lines = capture_logs_from(logcls.logger, formatter: :json) do logger.call({}, nil) do block.call end rescue StandardError => e - nil + raise e if reraise end return lines end @@ -404,7 +404,7 @@ def log(&block) end it "logs at error (but does not log the exception) if the job fails" do - lines = log do + lines = log(reraise: false) do 1 / 0 end @@ -434,7 +434,7 @@ def log(&block) end it "can add log fields to the job_fail message" do - lines = log do + lines = log(reraise: false) do described_class.set_job_tags(tag1: "hi") raise "hello" end @@ -619,7 +619,7 @@ def log end expect(lines.lines).to contain_exactly( include("INFO -- : hello1\n"), - include("INFO -- : hello2; {:x=>1}"), + include("INFO -- : hello2; {x: 1}"), ) end From 48d771137eae3a3e1472ec6d9d0fdf7f5360243e Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 15:03:26 -0700 Subject: [PATCH 4/9] Fix busted header usage, was passing a default not a hash --- lib/appydays/loggable/request_logger.rb | 2 +- spec/appydays/loggable_spec.rb | 10 ++++++++-- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/lib/appydays/loggable/request_logger.rb b/lib/appydays/loggable/request_logger.rb index 6c5421a..e2329b3 100644 --- a/lib/appydays/loggable/request_logger.rb +++ b/lib/appydays/loggable/request_logger.rb @@ -48,7 +48,7 @@ def call(env) status, header, body = SemanticLogger.named_tagged(request_id:) do @app.call(env) end - header = Rack::Headers.new(header) + header = Rack::Headers[header] body = Rack::BodyProxy.new(body) { self.log_finished(env, began_at, status, header) } [status, header, body] rescue StandardError => e diff --git a/spec/appydays/loggable_spec.rb b/spec/appydays/loggable_spec.rb index c244b04..178a9b4 100644 --- a/spec/appydays/loggable_spec.rb +++ b/spec/appydays/loggable_spec.rb @@ -104,8 +104,9 @@ def generate_stack_trace(i=0) rescue RuntimeError => e logger1.info("hello", e) end - expect(lines[0]).to match(%r{:in '.*generate_stack_trace'","skipped \d\d\d frames","/}) - expect(lines[0]).to have_attributes(length: be_between(700, 900)) + # Error format is different between Ruby versions + expect(lines[0]).to match(%r{:in .*generate_stack_trace'","skipped \d\d\d frames","/}) + expect(lines[0]).to have_attributes(length: be_between(600, 900)) end it "ignores non-array stack_trace keys" do @@ -214,6 +215,11 @@ def run_app(app, opts: {}, loggers: [], env: {}, cls: Appydays::Loggable::Reques expect(lines).to have_a_line_matching(/"message":"request_finished".*"response_status":400/) end + it "logs content length" do + lines = run_app(proc { [200, {"content-LENGTH" => "5"}, ""] }) + expect(lines).to have_a_line_matching(/"response_content_length":"5"/) + end + it "logs at 599 (or configured value) if something errors" do lines = run_app(proc { raise "testing error" }) expect(lines).to have_a_line_matching(/"level":"error".*"response_status":599/) From a1df34558c1f0906a4f03388251a0a9167d7ef81 Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 16:56:25 -0700 Subject: [PATCH 5/9] fix tag format --- spec/appydays/loggable_spec.rb | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/spec/appydays/loggable_spec.rb b/spec/appydays/loggable_spec.rb index 178a9b4..8aba6fe 100644 --- a/spec/appydays/loggable_spec.rb +++ b/spec/appydays/loggable_spec.rb @@ -623,9 +623,11 @@ def log db.log_info("hello1") db.log_info("hello2", {x: 1}) end + tags = "{x: 1}" + tags = "{:x=>1}" if Gem::Version.new(RUBY_VERSION) < Gem::Version.new("3.4.0") expect(lines.lines).to contain_exactly( include("INFO -- : hello1\n"), - include("INFO -- : hello2; {x: 1}"), + include("INFO -- : hello2; #{tags}"), ) end From 566b9c0a4effa2e8f06f6532e7014b0906857159 Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 20:44:44 -0700 Subject: [PATCH 6/9] split out tests --- .../loggable/httparty_formatter_spec.rb | 20 + spec/appydays/loggable/request_logger_spec.rb | 150 ++++++ spec/appydays/loggable/sequel_logger_spec.rb | 183 +++++++ .../loggable/sidekiq_job_logger_spec.rb | 131 +++++ spec/appydays/loggable_spec.rb | 472 ------------------ 5 files changed, 484 insertions(+), 472 deletions(-) create mode 100644 spec/appydays/loggable/httparty_formatter_spec.rb create mode 100644 spec/appydays/loggable/request_logger_spec.rb create mode 100644 spec/appydays/loggable/sequel_logger_spec.rb create mode 100644 spec/appydays/loggable/sidekiq_job_logger_spec.rb diff --git a/spec/appydays/loggable/httparty_formatter_spec.rb b/spec/appydays/loggable/httparty_formatter_spec.rb new file mode 100644 index 0000000..a251bbb --- /dev/null +++ b/spec/appydays/loggable/httparty_formatter_spec.rb @@ -0,0 +1,20 @@ +# frozen_string_literal: true + +require "appydays/loggable/httparty_formatter" + +RSpec.describe "HTTParty formatter" do + it "logs structured request information" do + logger = SemanticLogger["http_spec_logging_test"] + stub_request(:post, "https://foo/bar").to_return(status: 200, body: "") + logs = capture_logs_from(logger, formatter: :json) do + HTTParty.post("https://foo/bar", body: {x: 1}, logger:, log_format: :appydays) + end + expect(logs).to contain_exactly( + include_json( + "message" => "httparty_request", + "level" => "info", + "context" => include("http_method" => "POST"), + ), + ) + end +end diff --git a/spec/appydays/loggable/request_logger_spec.rb b/spec/appydays/loggable/request_logger_spec.rb new file mode 100644 index 0000000..f762ef0 --- /dev/null +++ b/spec/appydays/loggable/request_logger_spec.rb @@ -0,0 +1,150 @@ +# frozen_string_literal: true + +require "appydays/loggable/request_logger" + +RSpec.describe Appydays::Loggable::RequestLogger do + def run_app(app, opts: {}, loggers: [], env: {}, cls: Appydays::Loggable::RequestLogger) + rl = cls.new(app, **opts, reraise: false) + return capture_logs_from(loggers << rl.logger, formatter: :json) do + _, _, body = rl.call(env) + body&.close + end + end + + it "logs info about the request" do + lines = run_app(proc { [200, {}, ""] }) + expect(lines).to have_a_line_matching(/"message":"request_finished".*"response_status":200/) + + lines = run_app(proc { [400, {}, ""] }) + expect(lines).to have_a_line_matching(/"message":"request_finished".*"response_status":400/) + end + + it "logs content length" do + lines = run_app(proc { [200, {"content-LENGTH" => "5"}, ""] }) + expect(lines).to have_a_line_matching(/"response_content_length":"5"/) + end + + it "logs at 599 (or configured value) if something errors" do + lines = run_app(proc { raise "testing error" }) + expect(lines).to have_a_line_matching(/"level":"error".*"response_status":599/) + expect(lines).to have_a_line_matching(/"message":"testing error"/) + end + + it "logs slow queries at warn" do + lines = run_app(proc { [200, {}, ""] }, opts: {slow_request_seconds: 0}) + expect(lines).to have_a_line_matching(/"level":"warn".*"response_status":200/) + end + + it "logs errors at error" do + lines = run_app(proc { [504, {}, ""] }, opts: {slow_request_seconds: 0}) + expect(lines).to have_a_line_matching(/"level":"error".*"response_status":504/) + end + + it "adds request_id tag around the execution of the request" do + logger = SemanticLogger["testlogger"] + lines = run_app(proc do + logger.info("check for tags") + [200, {}, ""] + end, + opts: {slow_request_seconds: 0}, loggers: [logger],) + expect(lines).to have_attributes(length: 2) + # This should have request_id, but not the other request tags, like the path + expect(lines[0]).to include_json(message: "check for tags", context: include("request_id")) + expect(lines[0]).to include_json(context: not_include("request_path")) + # This should have all tags + expect(lines[1]).to include_json(message: "request_finished", context: include("request_id", "request_path")) + end + + it "adds subclass tags" do + ReqLogger = Class.new(Appydays::Loggable::RequestLogger) do + def request_tags(env) + return {my_header_tag: env["HTTP_MY_HEADER"]} + end + end + lines = run_app(proc { [200, {}, ""] }, env: {"HTTP_MY_HEADER" => "myval"}, cls: ReqLogger) + expect(lines).to have_a_line_matching(/"my_header_tag":"myval"/) + end + + it "adds and sets request and trace ids if trace and request headers not set" do + env = {} + trace_id = nil + request_id = nil + lines = run_app(proc do + trace_id = env.fetch("HTTP_TRACE_ID") + request_id = env.fetch("HTTP_X_REQUEST_ID") + [200, {}, ""] + end, env:,) + expect(lines).to contain_exactly( + include_json(message: "request_finished", context: include( + "trace_id" => trace_id, + "request_id" => request_id, + ),), + ) + end + + it "reads the request and trace id headers" do + env = {"HTTP_TRACE_ID" => "t1", "HTTP_X_REQUEST_ID" => "r1"} + lines = run_app(proc do + expect(env).to include("HTTP_TRACE_ID" => "t1", "HTTP_X_REQUEST_ID" => "r1") + [200, {}, ""] + end, env:,) + expect(lines).to contain_exactly( + include_json(message: "request_finished", context: include( + "trace_id" => "t1", + "request_id" => "r1", + ),), + ) + end + + it "will use the trace id header" do + env = {"HTTP_TRACE_ID" => "t1"} + lines = run_app(proc do + expect(env).to include("HTTP_TRACE_ID" => "t1", "HTTP_X_REQUEST_ID" => have_attributes(length: 36)) + [200, {}, ""] + end, env:,) + expect(lines).to contain_exactly( + include_json(message: "request_finished", context: include( + "trace_id" => "t1", + "request_id" => have_attributes(length: 36), + ),), + ) + end + + it "can add log fields to the request_finished message" do + lines = run_app(proc do + described_class.set_request_tags(abc: "123") + [200, {}, ""] + end) + expect(lines).to contain_exactly( + include_json( + level: "info", + name: "Appydays::Loggable::RequestLogger", + message: "request_finished", + context: include("abc" => "123"), + ), + ) + end + + it "clears tags after the request (even if it raises an error)" do + lines = run_app(proc do + described_class.set_request_tags(tag1: "a") + [200, {}, ""] + end) + expect(lines).to contain_exactly(include_json(context: include("tag1" => "a"))) + + lines = run_app(proc do + described_class.set_request_tags(tag2: "a") + raise "oops" + end) + expect(lines).to contain_exactly(include_json(context: include("tag2" => "a"))) + expect(lines).to contain_exactly(include_json(context: not_include("tag1" => "a"))) + + lines = run_app(proc do + described_class.set_request_tags(tag3: "a") + [400, {}, ""] + end) + expect(lines).to contain_exactly(include_json(context: include("tag3" => "a"))) + expect(lines).to contain_exactly(include_json(context: not_include("tag1" => "a"))) + expect(lines).to contain_exactly(include_json(context: not_include("tag2" => "a"))) + end +end diff --git a/spec/appydays/loggable/sequel_logger_spec.rb b/spec/appydays/loggable/sequel_logger_spec.rb new file mode 100644 index 0000000..93ceae6 --- /dev/null +++ b/spec/appydays/loggable/sequel_logger_spec.rb @@ -0,0 +1,183 @@ +# frozen_string_literal: true + +require "appydays/loggable/sequel_logger" + +RSpec.describe "Sequel Logging" do + after(:each) do + Sequel::Database::AppydaysLogger.setdefaults + end + describe "with structure logging" do + def log + logger = SemanticLogger[Sequel] + db = Sequel.connect("mock://", logger:, log_warn_duration: 3) + return capture_logs_from(logger, formatter: :json) do + yield(db) + end + end + + it "logs info" do + lines = log do |db| + db.log_info("hello1") + db.log_info("hello2", {x: 1}) + end + expect(lines).to contain_exactly( + include_json( + level: "info", + name: "Sequel", + message: "sequel_log", + context: {"message" => "hello1"}, + ), + include_json( + context: {"message" => "hello2", "args" => {"x" => 1}}, + ), + ) + end + + it "logs exceptions" do + lines = log do |db| + db.log_exception(RuntimeError.new("nope"), "msg") + end + expect(lines).to contain_exactly( + include_json( + level: "error", + message: "sequel_exception", + exception: {"name" => "RuntimeError", "message" => "nope", "stack_trace" => nil}, + context: {"sequel_message" => "msg"}, + ), + ) + end + + it "logs 'table exists' exceptions at debug" do + lines = log do |db| + db.log_exception(RuntimeError.new("nope"), "SELECT NULL AS nil FROM sch.foobar LIMIT 1") + db.log_exception(RuntimeError.new("nope"), "select null as \"nil\" FROM \"sch\".\"foobar\" LIMIT 1") + end + expect(lines).to contain_exactly( + include_json(level: "debug", message: "sequel_exception"), + include_json(level: "debug", message: "sequel_exception"), + ) + end + + it "logs duration" do + lines = log do |db| + db.log_duration(4, "slow") + db.log_duration(1, "fast") + end + expect(lines).to contain_exactly( + include_json( + level: "warn", + message: "sequel_query", + duration_ms: 4000, + duration: "4.000s", + context: {"query" => "slow"}, + ), + include_json( + level: "info", + message: "sequel_query", + context: {"query" => "fast"}, + ), + ) + end + + it "truncates long messages at debug" do + Sequel::Database::AppydaysLogger.truncation_context = 3 + Sequel::Database::AppydaysLogger.truncation_message = "" + Sequel::Database::AppydaysLogger.log_full_message_level = :debug + + lines = log do |db| + db.log_duration(4, "a" * 3000) + db.log_duration(1, "a" * 3000) + end + + expect(lines).to contain_exactly( + include_json( + level: "warn", + message: "sequel_query", + context: {"query" => "aaaaaa", "truncated" => true}, + ), + include_json( + level: "debug", + message: "sequel_query_debug", + context: {"query" => have_length(3000)}, + ), + include_json( + level: "info", + message: "sequel_query", + context: {"query" => "aaaaaa", "truncated" => true}, + ), + include_json( + level: "debug", + message: "sequel_query_debug", + context: {"query" => have_length(3000)}, + ), + ) + end + + it "does not log untruncated messages if log_full_message_level is nil" do + Sequel::Database::AppydaysLogger.truncation_context = 3 + Sequel::Database::AppydaysLogger.truncation_message = "" + Sequel::Database::AppydaysLogger.log_full_message_level = nil + + lines = log do |db| + db.log_duration(4, "a" * 3000) + db.log_duration(1, "a" * 3000) + end + + expect(lines).to contain_exactly( + include_json( + level: "warn", + message: "sequel_query", + context: {"query" => "aaaaaa", "truncated" => true}, + ), + include_json( + level: "info", + message: "sequel_query", + context: {"query" => "aaaaaa", "truncated" => true}, + ), + ) + end + end + + describe "with standard logging" do + def log + device = StringIO.new + logger = Logger.new(device) + db = Sequel.connect("mock://", logger:, log_warn_duration: 3) + yield(db) + return device.string + end + + it "logs info" do + lines = log do |db| + db.log_info("hello1") + db.log_info("hello2", {x: 1}) + end + tags = "{x: 1}" + tags = "{:x=>1}" if Gem::Version.new(RUBY_VERSION) < Gem::Version.new("3.4.0") + expect(lines.lines).to contain_exactly( + include("INFO -- : hello1\n"), + include("INFO -- : hello2; #{tags}"), + ) + end + + it "logs exceptions" do + lines = log do |db| + db.log_exception(RuntimeError.new("nope"), "msg") + end + expect(lines.lines).to contain_exactly( + include("ERROR -- : RuntimeError: nope: msg\n"), + ) + end + + it "logs duration" do + lines = log do |db| + db.log_duration(4, "slow") + db.log_duration(1, "fast") + end + expect(lines.lines).to contain_exactly( + include("INFO -- : (1.000000s) fast\n"), + include("WARN -- : (4.000000s) slow\n"), + ) + end + end +end diff --git a/spec/appydays/loggable/sidekiq_job_logger_spec.rb b/spec/appydays/loggable/sidekiq_job_logger_spec.rb new file mode 100644 index 0000000..612c8c4 --- /dev/null +++ b/spec/appydays/loggable/sidekiq_job_logger_spec.rb @@ -0,0 +1,131 @@ +# frozen_string_literal: true + +require "appydays/loggable/sidekiq_job_logger" + +RSpec.describe Appydays::Loggable::SidekiqJobLogger do + before(:each) { @slow_secs = 5 } + let(:logcls) do + slow_secs = @slow_secs + Class.new(Appydays::Loggable::SidekiqJobLogger) do + attr_accessor :slow_secs + + def self.name + return "TestLogger" + end + define_method(:slow_job_seconds) { slow_secs } + end + end + + let(:logger) { logcls.new(Sidekiq::Config.new) } + + def log(reraise: true, &block) + block ||= proc {} + lines = capture_logs_from(logcls.logger, formatter: :json) do + logger.call({}, nil) do + block.call + end + rescue StandardError => e + raise e if reraise + end + return lines + end + + it "logs a info message for the job" do + lines = log + expect(lines).to contain_exactly( + include_json( + level: "info", + name: "TestLogger", + message: "job_done", + duration_ms: be_a(Numeric), + ), + ) + end + + it "logs duration properly (SemanticLogger uses milliseconds)" do + lines = log { sleep(0.001) } + expect(lines).to contain_exactly( + include_json( + message: "job_done", + duration: match(/^\d+\.\d+ms$/), + duration_ms: be >= 1, + ), + ) + end + + it "logs at warn if the time taken is more than the slow job seconds" do + @slow_secs = 0 + lines = log + expect(lines).to contain_exactly( + include_json( + level: "warn", + name: "TestLogger", + message: "job_done", + duration_ms: be_a(Numeric), + ), + ) + end + + it "logs at error (but does not log the exception) if the job fails" do + lines = log(reraise: false) do + 1 / 0 + end + + expect(lines).to contain_exactly( + include_json( + level: "error", + name: "TestLogger", + message: "job_fail", + duration_ms: be_a(Numeric), + ), + ) + expect(lines[0]).to_not include("exception") + end + + it "can add log fields to the job_done message" do + lines = log do + described_class.set_job_tags(tag1: "hi") + end + expect(lines).to contain_exactly( + include_json( + level: "info", + name: "TestLogger", + message: "job_done", + context: include("tag1" => "hi"), + ), + ) + end + + it "can add log fields to the job_fail message" do + lines = log(reraise: false) do + described_class.set_job_tags(tag1: "hi") + raise "hello" + end + expect(lines).to contain_exactly( + include_json( + level: "error", + name: "TestLogger", + message: "job_fail", + context: include("tag1" => "hi"), + ), + ) + end + + it "clears job tags after the job" do + lines = log do + described_class.set_job_tags(tag1: "hi") + end + expect(lines).to contain_exactly( + include_json( + context: include("tag1" => "hi"), + ), + ) + + lines = log + expect(lines).to contain_exactly( + include_json( + context: not_include("tag1"), + ), + ) + end +end diff --git a/spec/appydays/loggable_spec.rb b/spec/appydays/loggable_spec.rb index 8aba6fe..f73631d 100644 --- a/spec/appydays/loggable_spec.rb +++ b/spec/appydays/loggable_spec.rb @@ -197,476 +197,4 @@ def generate_stack_trace(i=0) SemanticLogger.remove_appender(other_appender) end end - - describe Appydays::Loggable::RequestLogger do - def run_app(app, opts: {}, loggers: [], env: {}, cls: Appydays::Loggable::RequestLogger) - rl = cls.new(app, **opts, reraise: false) - return capture_logs_from(loggers << rl.logger, formatter: :json) do - _, _, body = rl.call(env) - body&.close - end - end - - it "logs info about the request" do - lines = run_app(proc { [200, {}, ""] }) - expect(lines).to have_a_line_matching(/"message":"request_finished".*"response_status":200/) - - lines = run_app(proc { [400, {}, ""] }) - expect(lines).to have_a_line_matching(/"message":"request_finished".*"response_status":400/) - end - - it "logs content length" do - lines = run_app(proc { [200, {"content-LENGTH" => "5"}, ""] }) - expect(lines).to have_a_line_matching(/"response_content_length":"5"/) - end - - it "logs at 599 (or configured value) if something errors" do - lines = run_app(proc { raise "testing error" }) - expect(lines).to have_a_line_matching(/"level":"error".*"response_status":599/) - expect(lines).to have_a_line_matching(/"message":"testing error"/) - end - - it "logs slow queries at warn" do - lines = run_app(proc { [200, {}, ""] }, opts: {slow_request_seconds: 0}) - expect(lines).to have_a_line_matching(/"level":"warn".*"response_status":200/) - end - - it "logs errors at error" do - lines = run_app(proc { [504, {}, ""] }, opts: {slow_request_seconds: 0}) - expect(lines).to have_a_line_matching(/"level":"error".*"response_status":504/) - end - - it "adds request_id tag around the execution of the request" do - logger = SemanticLogger["testlogger"] - lines = run_app(proc do - logger.info("check for tags") - [200, {}, ""] - end, - opts: {slow_request_seconds: 0}, loggers: [logger],) - expect(lines).to have_attributes(length: 2) - # This should have request_id, but not the other request tags, like the path - expect(lines[0]).to include_json(message: "check for tags", context: include("request_id")) - expect(lines[0]).to include_json(context: not_include("request_path")) - # This should have all tags - expect(lines[1]).to include_json(message: "request_finished", context: include("request_id", "request_path")) - end - - it "adds subclass tags" do - ReqLogger = Class.new(Appydays::Loggable::RequestLogger) do - def request_tags(env) - return {my_header_tag: env["HTTP_MY_HEADER"]} - end - end - lines = run_app(proc { [200, {}, ""] }, env: {"HTTP_MY_HEADER" => "myval"}, cls: ReqLogger) - expect(lines).to have_a_line_matching(/"my_header_tag":"myval"/) - end - - it "adds and sets request and trace ids if trace and request headers not set" do - env = {} - trace_id = nil - request_id = nil - lines = run_app(proc do - trace_id = env.fetch("HTTP_TRACE_ID") - request_id = env.fetch("HTTP_X_REQUEST_ID") - [200, {}, ""] - end, env:,) - expect(lines).to contain_exactly( - include_json(message: "request_finished", context: include( - "trace_id" => trace_id, - "request_id" => request_id, - ),), - ) - end - - it "reads the request and trace id headers" do - env = {"HTTP_TRACE_ID" => "t1", "HTTP_X_REQUEST_ID" => "r1"} - lines = run_app(proc do - expect(env).to include("HTTP_TRACE_ID" => "t1", "HTTP_X_REQUEST_ID" => "r1") - [200, {}, ""] - end, env:,) - expect(lines).to contain_exactly( - include_json(message: "request_finished", context: include( - "trace_id" => "t1", - "request_id" => "r1", - ),), - ) - end - - it "will use the trace id header" do - env = {"HTTP_TRACE_ID" => "t1"} - lines = run_app(proc do - expect(env).to include("HTTP_TRACE_ID" => "t1", "HTTP_X_REQUEST_ID" => have_attributes(length: 36)) - [200, {}, ""] - end, env:,) - expect(lines).to contain_exactly( - include_json(message: "request_finished", context: include( - "trace_id" => "t1", - "request_id" => have_attributes(length: 36), - ),), - ) - end - - it "can add log fields to the request_finished message" do - lines = run_app(proc do - described_class.set_request_tags(abc: "123") - [200, {}, ""] - end) - expect(lines).to contain_exactly( - include_json( - level: "info", - name: "Appydays::Loggable::RequestLogger", - message: "request_finished", - context: include("abc" => "123"), - ), - ) - end - - it "clears tags after the request (even if it raises an error)" do - lines = run_app(proc do - described_class.set_request_tags(tag1: "a") - [200, {}, ""] - end) - expect(lines).to contain_exactly(include_json(context: include("tag1" => "a"))) - - lines = run_app(proc do - described_class.set_request_tags(tag2: "a") - raise "oops" - end) - expect(lines).to contain_exactly(include_json(context: include("tag2" => "a"))) - expect(lines).to contain_exactly(include_json(context: not_include("tag1" => "a"))) - - lines = run_app(proc do - described_class.set_request_tags(tag3: "a") - [400, {}, ""] - end) - expect(lines).to contain_exactly(include_json(context: include("tag3" => "a"))) - expect(lines).to contain_exactly(include_json(context: not_include("tag1" => "a"))) - expect(lines).to contain_exactly(include_json(context: not_include("tag2" => "a"))) - end - end - - describe Appydays::Loggable::SidekiqJobLogger, :db do - before(:each) { @slow_secs = 5 } - let(:logcls) do - slow_secs = @slow_secs - Class.new(Appydays::Loggable::SidekiqJobLogger) do - attr_accessor :slow_secs - - def self.name - return "TestLogger" - end - define_method(:slow_job_seconds) { slow_secs } - end - end - - let(:logger) { logcls.new(Sidekiq::Config.new) } - - def log(reraise: true, &block) - block ||= proc {} - lines = capture_logs_from(logcls.logger, formatter: :json) do - logger.call({}, nil) do - block.call - end - rescue StandardError => e - raise e if reraise - end - return lines - end - - it "logs a info message for the job" do - lines = log - expect(lines).to contain_exactly( - include_json( - level: "info", - name: "TestLogger", - message: "job_done", - duration_ms: be_a(Numeric), - ), - ) - end - - it "logs duration properly (SemanticLogger uses milliseconds)" do - lines = log { sleep(0.001) } - expect(lines).to contain_exactly( - include_json( - message: "job_done", - duration: match(/^\d+\.\d+ms$/), - duration_ms: be >= 1, - ), - ) - end - - it "logs at warn if the time taken is more than the slow job seconds" do - @slow_secs = 0 - lines = log - expect(lines).to contain_exactly( - include_json( - level: "warn", - name: "TestLogger", - message: "job_done", - duration_ms: be_a(Numeric), - ), - ) - end - - it "logs at error (but does not log the exception) if the job fails" do - lines = log(reraise: false) do - 1 / 0 - end - - expect(lines).to contain_exactly( - include_json( - level: "error", - name: "TestLogger", - message: "job_fail", - duration_ms: be_a(Numeric), - ), - ) - expect(lines[0]).to_not include("exception") - end - - it "can add log fields to the job_done message" do - lines = log do - described_class.set_job_tags(tag1: "hi") - end - expect(lines).to contain_exactly( - include_json( - level: "info", - name: "TestLogger", - message: "job_done", - context: include("tag1" => "hi"), - ), - ) - end - - it "can add log fields to the job_fail message" do - lines = log(reraise: false) do - described_class.set_job_tags(tag1: "hi") - raise "hello" - end - expect(lines).to contain_exactly( - include_json( - level: "error", - name: "TestLogger", - message: "job_fail", - context: include("tag1" => "hi"), - ), - ) - end - - it "clears job tags after the job" do - lines = log do - described_class.set_job_tags(tag1: "hi") - end - expect(lines).to contain_exactly( - include_json( - context: include("tag1" => "hi"), - ), - ) - - lines = log - expect(lines).to contain_exactly( - include_json( - context: not_include("tag1"), - ), - ) - end - end - - describe "Sequel Logging" do - after(:each) do - Sequel::Database::AppydaysLogger.setdefaults - end - describe "with structure logging" do - def log - logger = SemanticLogger[Sequel] - db = Sequel.connect("mock://", logger:, log_warn_duration: 3) - return capture_logs_from(logger, formatter: :json) do - yield(db) - end - end - - it "logs info" do - lines = log do |db| - db.log_info("hello1") - db.log_info("hello2", {x: 1}) - end - expect(lines).to contain_exactly( - include_json( - level: "info", - name: "Sequel", - message: "sequel_log", - context: {"message" => "hello1"}, - ), - include_json( - context: {"message" => "hello2", "args" => {"x" => 1}}, - ), - ) - end - - it "logs exceptions" do - lines = log do |db| - db.log_exception(RuntimeError.new("nope"), "msg") - end - expect(lines).to contain_exactly( - include_json( - level: "error", - message: "sequel_exception", - exception: {"name" => "RuntimeError", "message" => "nope", "stack_trace" => nil}, - context: {"sequel_message" => "msg"}, - ), - ) - end - - it "logs 'table exists' exceptions at debug" do - lines = log do |db| - db.log_exception(RuntimeError.new("nope"), "SELECT NULL AS nil FROM sch.foobar LIMIT 1") - db.log_exception(RuntimeError.new("nope"), "select null as \"nil\" FROM \"sch\".\"foobar\" LIMIT 1") - end - expect(lines).to contain_exactly( - include_json(level: "debug", message: "sequel_exception"), - include_json(level: "debug", message: "sequel_exception"), - ) - end - - it "logs duration" do - lines = log do |db| - db.log_duration(4, "slow") - db.log_duration(1, "fast") - end - expect(lines).to contain_exactly( - include_json( - level: "warn", - message: "sequel_query", - duration_ms: 4000, - duration: "4.000s", - context: {"query" => "slow"}, - ), - include_json( - level: "info", - message: "sequel_query", - context: {"query" => "fast"}, - ), - ) - end - - it "truncates long messages at debug" do - Sequel::Database::AppydaysLogger.truncation_context = 3 - Sequel::Database::AppydaysLogger.truncation_message = "" - Sequel::Database::AppydaysLogger.log_full_message_level = :debug - - lines = log do |db| - db.log_duration(4, "a" * 3000) - db.log_duration(1, "a" * 3000) - end - - expect(lines).to contain_exactly( - include_json( - level: "warn", - message: "sequel_query", - context: {"query" => "aaaaaa", "truncated" => true}, - ), - include_json( - level: "debug", - message: "sequel_query_debug", - context: {"query" => have_length(3000)}, - ), - include_json( - level: "info", - message: "sequel_query", - context: {"query" => "aaaaaa", "truncated" => true}, - ), - include_json( - level: "debug", - message: "sequel_query_debug", - context: {"query" => have_length(3000)}, - ), - ) - end - - it "does not log untruncated messages if log_full_message_level is nil" do - Sequel::Database::AppydaysLogger.truncation_context = 3 - Sequel::Database::AppydaysLogger.truncation_message = "" - Sequel::Database::AppydaysLogger.log_full_message_level = nil - - lines = log do |db| - db.log_duration(4, "a" * 3000) - db.log_duration(1, "a" * 3000) - end - - expect(lines).to contain_exactly( - include_json( - level: "warn", - message: "sequel_query", - context: {"query" => "aaaaaa", "truncated" => true}, - ), - include_json( - level: "info", - message: "sequel_query", - context: {"query" => "aaaaaa", "truncated" => true}, - ), - ) - end - end - - describe "with standard logging" do - def log - device = StringIO.new - logger = Logger.new(device) - db = Sequel.connect("mock://", logger:, log_warn_duration: 3) - yield(db) - return device.string - end - - it "logs info" do - lines = log do |db| - db.log_info("hello1") - db.log_info("hello2", {x: 1}) - end - tags = "{x: 1}" - tags = "{:x=>1}" if Gem::Version.new(RUBY_VERSION) < Gem::Version.new("3.4.0") - expect(lines.lines).to contain_exactly( - include("INFO -- : hello1\n"), - include("INFO -- : hello2; #{tags}"), - ) - end - - it "logs exceptions" do - lines = log do |db| - db.log_exception(RuntimeError.new("nope"), "msg") - end - expect(lines.lines).to contain_exactly( - include("ERROR -- : RuntimeError: nope: msg\n"), - ) - end - - it "logs duration" do - lines = log do |db| - db.log_duration(4, "slow") - db.log_duration(1, "fast") - end - expect(lines.lines).to contain_exactly( - include("INFO -- : (1.000000s) fast\n"), - include("WARN -- : (4.000000s) slow\n"), - ) - end - end - end - - describe "HTTParty formatter" do - it "logs structured request information" do - logger = SemanticLogger["http_spec_logging_test"] - stub_request(:post, "https://foo/bar").to_return(status: 200, body: "") - logs = capture_logs_from(logger, formatter: :json) do - HTTParty.post("https://foo/bar", body: {x: 1}, logger:, log_format: :appydays) - end - expect(logs).to contain_exactly( - include_json( - "message" => "httparty_request", - "level" => "info", - "context" => include("http_method" => "POST"), - ), - ) - end - end end From 0b0f1aba67a6fc60057ac52848777c8f22064d90 Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 21:08:45 -0700 Subject: [PATCH 7/9] Fix and test death/error handlers We can't really test this in context since it requires a sidekiq processor, but this is good enough. The error handler method args changed, the final arg is a config. --- lib/appydays/loggable/sidekiq_job_logger.rb | 9 +-- .../loggable/sidekiq_job_logger_spec.rb | 57 +++++++++++++++++++ 2 files changed, 58 insertions(+), 8 deletions(-) diff --git a/lib/appydays/loggable/sidekiq_job_logger.rb b/lib/appydays/loggable/sidekiq_job_logger.rb index 6c8fe97..9a070dd 100644 --- a/lib/appydays/loggable/sidekiq_job_logger.rb +++ b/lib/appydays/loggable/sidekiq_job_logger.rb @@ -13,13 +13,6 @@ class Appydays::Loggable::SidekiqJobLogger < Sidekiq::JobLogger include Appydays::Loggable include Sidekiq::Component - Sidekiq.configure_client do |config| - config.logger = self.logger - end - Sidekiq.configure_server do |config| - config.logger = self.logger - end - # Level to log 'job_done' messages at. # Defaults to +:info+. attr_accessor :log_level_job_done @@ -80,7 +73,7 @@ def self.set_job_tags(tags) def self.job_tags = Thread.current[:appydays_sidekiq_job_logger_job_tags] || {} - def self.error_handler(ex, ctx) + def self.error_handler(ex, ctx, _config) # ctx looks like: # { # :context=>"Job raised exception", diff --git a/spec/appydays/loggable/sidekiq_job_logger_spec.rb b/spec/appydays/loggable/sidekiq_job_logger_spec.rb index 612c8c4..957dc11 100644 --- a/spec/appydays/loggable/sidekiq_job_logger_spec.rb +++ b/spec/appydays/loggable/sidekiq_job_logger_spec.rb @@ -1,6 +1,7 @@ # frozen_string_literal: true require "appydays/loggable/sidekiq_job_logger" +require "sidekiq/testing" RSpec.describe Appydays::Loggable::SidekiqJobLogger do before(:each) { @slow_secs = 5 } @@ -128,4 +129,60 @@ def log(reraise: true, &block) ), ) end + + describe "error_handler" do + it "handles job errors" do + ctx = { + context: "Job raised exception", + job: { + "class" => "App::Async::FailingJobTester", + "args" => [ + { + "id" => "e8e03571-9851-4daa-a801-a0b43282f317", + "name" => "app.test_failing_job", + "payload" => [true], + }, + ], + "retry" => true, + "queue" => "default", + "jid" => "cb00c4fe9b2f16b72797d35c", + "created_at" => 1_567_811_837.798969, + "enqueued_at" => 1_567_811_837.79901, + }, + jobstr: "{\"class\":\"App::Async::FailingJobTester\", ", + } + lines = capture_logs_from(described_class.logger, formatter: :json) do + described_class.error_handler(RuntimeError.new, ctx, Sidekiq::Config.new) + end + expect(lines).to contain_exactly( + include_json(message: "job_error"), + ) + end + + it "logs an error if the context is bad" do + lines = capture_logs_from(described_class.logger, formatter: :json) do + described_class.error_handler(RuntimeError.new, {}, Sidekiq::Config.new) + end + expect(lines).to contain_exactly( + include_json(message: "job_error_no_job"), + ) + end + end + + describe "death_handler" do + it "handles job deaths" do + job = { + "class" => "App::Async::FailingJobTester", + "jid" => "cb00c4fe9b2f16b72797d35c", + "created_at" => 1_567_811_837.798969, + "enqueued_at" => 1_567_811_837.79901, + } + lines = capture_logs_from(described_class.logger, formatter: :json) do + described_class.death_handler(job, RuntimeError.new) + end + expect(lines).to contain_exactly( + include_json(message: "job_retries_exhausted"), + ) + end + end end From 973739c88906a0049e6c7227fadc020e70c1ffde Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 21:11:34 -0700 Subject: [PATCH 8/9] Add coverage upload --- .github/workflows/pr-checks.yml | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/.github/workflows/pr-checks.yml b/.github/workflows/pr-checks.yml index 10ea144..6c594ff 100644 --- a/.github/workflows/pr-checks.yml +++ b/.github/workflows/pr-checks.yml @@ -33,4 +33,8 @@ jobs: run: bundle exec rubocop - name: Run specs run: bundle exec rspec spec/ - + - name: Upload coverage reports to Codecov + uses: codecov/codecov-action@v5 + with: + token: ${{ secrets.CODECOV_TOKEN }} + slug: lithictech/appydays From d874b940303e0220d2fa023cbf747174c9d889a6 Mon Sep 17 00:00:00 2001 From: Rob Galanakis Date: Wed, 25 Jun 2025 21:45:59 -0700 Subject: [PATCH 9/9] update readme --- README.md | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index 8e9d9de..88629e1 100644 --- a/README.md +++ b/README.md @@ -220,9 +220,9 @@ end ```rb require 'appydays/loggable/sidekiq_job_logger' -Sidekiq.logger = Appydays::Loggable::SidekiqJobLogger.logger Sidekiq.configure_server do |config| - config.options[:job_logger] = Appydays::Loggable::SidekiqJobLogger::JobLogger + config.logger = Appydays::Loggable::SidekiqJobLogger.logger # Or whatever Loggable logger you like + config[:job_logger] = Appydays::Loggable::SidekiqJobLogger::JobLogger # We do NOT want the unstructured default error handler config.error_handlers.replace([Appydays::Loggable::SidekiqJobLogger::JobLogger.method(:error_handler)]) config.death_handlers << Appydays::Loggable::SidekiqJobLogger::JobLogger.method(:death_handler) @@ -244,9 +244,9 @@ class AppJobLogger < Appydays::Loggable::SidekiqJobLogger end end -Sidekiq.logger = AppJobLogger.logger Sidekiq.configure_server do |config| - config.options[:job_logger] = AppJobLogger::JobLogger + config.logger = AppJobLogger.logger + config[:job_logger] = AppJobLogger # We do NOT want the unstructured default error handler config.error_handlers.replace([AppJobLogger::JobLogger.method(:error_handler)]) config.death_handlers << AppJobLogger::JobLogger.method(:death_handler)