From 0dd8eea2b427da31a8208695c435e428354c59bb Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:53:27 +1300 Subject: [PATCH 1/4] Log Integer provider job IDs as strings Active Job backends set provider_job_id to a String or an Integer; SolidQueue uses the ID of its job row. The log subscriber passed it straight into a T.nilable(String) field, so every job event raised a TypeError under SolidQueue. Builders::ActiveJob had the same bug, but nothing requires or calls it, so it's removed rather than fixed. Fixes #7 --- lib/log_struct/builders/active_job.rb | 87 ------------------- .../integrations/active_job/log_subscriber.rb | 3 +- .../active_job/log_subscriber_test.rb | 14 +++ 3 files changed, 16 insertions(+), 88 deletions(-) delete mode 100644 lib/log_struct/builders/active_job.rb diff --git a/lib/log_struct/builders/active_job.rb b/lib/log_struct/builders/active_job.rb deleted file mode 100644 index d7c8fa0a..00000000 --- a/lib/log_struct/builders/active_job.rb +++ /dev/null @@ -1,87 +0,0 @@ -# typed: strict -# frozen_string_literal: true - -require_relative "../log/active_job/enqueue" -require_relative "../log/active_job/schedule" -require_relative "../log/active_job/start" -require_relative "../log/active_job/finish" - -module LogStruct - module Builders - module ActiveJob - extend T::Sig - - sig { params(job: T.untyped).returns(T.nilable(String)) } - def self.safe_provider_job_id(job) - job.respond_to?(:provider_job_id) ? job.provider_job_id : nil - end - - sig { params(job: T.untyped).returns(T.nilable(Integer)) } - def self.safe_executions(job) - job.respond_to?(:executions) ? job.executions : nil - end - - # Respect log_arguments? setting on job classes. - # Arguments are logged by default but can be opted-out per job class. - # When logged, sensitive keys are filtered by Formatter.process_values. - sig { params(job: T.untyped).returns(T.nilable(T::Array[T.untyped])) } - def self.safe_arguments(job) - return job.arguments unless job.class.respond_to?(:log_arguments?) - job.class.log_arguments? ? job.arguments : nil - end - - sig { params(job: T.untyped).returns(Log::ActiveJob::Enqueue) } - def self.enqueue(job) - Log::ActiveJob::Enqueue.new( - job_id: job.job_id, - job_class: job.class.to_s, - queue_name: job.queue_name, - arguments: safe_arguments(job), - executions: safe_executions(job), - provider_job_id: safe_provider_job_id(job) - ) - end - - sig { params(job: T.untyped, scheduled_at: Time).returns(Log::ActiveJob::Schedule) } - def self.schedule(job, scheduled_at:) - Log::ActiveJob::Schedule.new( - job_id: job.job_id, - job_class: job.class.to_s, - queue_name: job.queue_name, - arguments: safe_arguments(job), - executions: safe_executions(job), - provider_job_id: safe_provider_job_id(job), - scheduled_at: scheduled_at - ) - end - - sig { params(job: T.untyped, started_at: Time, attempt: T.nilable(Integer)).returns(Log::ActiveJob::Start) } - def self.start(job, started_at:, attempt:) - Log::ActiveJob::Start.new( - job_id: job.job_id, - job_class: job.class.to_s, - queue_name: job.queue_name, - arguments: safe_arguments(job), - executions: safe_executions(job), - provider_job_id: safe_provider_job_id(job), - started_at: started_at, - attempt: attempt - ) - end - - sig { params(job: T.untyped, duration_ms: Float, finished_at: Time).returns(Log::ActiveJob::Finish) } - def self.finish(job, duration_ms:, finished_at:) - Log::ActiveJob::Finish.new( - job_id: job.job_id, - job_class: job.class.to_s, - queue_name: job.queue_name, - arguments: safe_arguments(job), - executions: safe_executions(job), - provider_job_id: safe_provider_job_id(job), - duration_ms: duration_ms, - finished_at: finished_at - ) - end - end - end -end diff --git a/lib/log_struct/integrations/active_job/log_subscriber.rb b/lib/log_struct/integrations/active_job/log_subscriber.rb index 78039ff7..534b2d4e 100644 --- a/lib/log_struct/integrations/active_job/log_subscriber.rb +++ b/lib/log_struct/integrations/active_job/log_subscriber.rb @@ -83,7 +83,8 @@ def build_base_fields(job) job_class: job.class.to_s, queue_name: job.queue_name&.to_sym, executions: job.executions, - provider_job_id: job.provider_job_id, + # Backends use Strings or Integers (SolidQueue uses its job row ID) + provider_job_id: job.provider_job_id&.to_s, arguments: ((job.class.respond_to?(:log_arguments?) && job.class.log_arguments?) ? job.arguments : nil) ) end diff --git a/test/log_struct/integrations/active_job/log_subscriber_test.rb b/test/log_struct/integrations/active_job/log_subscriber_test.rb index fc0c972e..25dab707 100644 --- a/test/log_struct/integrations/active_job/log_subscriber_test.rb +++ b/test/log_struct/integrations/active_job/log_subscriber_test.rb @@ -47,6 +47,20 @@ def perform assert_in_delta now.to_f, finished_at.to_f, 5.0 end + test "logs Integer provider job IDs as strings" do + clear_log_buffer(@log_output) + + job = TestActiveJob.new + job.provider_job_id = 2905 + start_time = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC) + event = build_event("perform.active_job", start_time, start_time + 0.1, {job: job}) + + @subscriber.perform(event) + ::SemanticLogger.flush + + assert_equal "2905", parse_first_log(@log_output)["provider_job_id"] + end + private def build_event(name, start_time, finish_time, payload) From ad8b47befd21b1ba258e7b528a83f8c4a53ac3e9 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:58:42 +1300 Subject: [PATCH 2/4] Depend on railties instead of rails LogStruct only needs railties for its Railtie, actionpack for its middleware and request logs, activesupport and globalid. Depending on the rails gem pulled Active Record, Active Storage, Action Cable and the other frameworks into apps that don't use them. The integrations for those frameworks already load only when the framework is present; the formatter's Active Record check no longer assumes it is. A new CI job boots an app whose bundle has railties and actionpack but none of the other frameworks, and checks that it logs JSON app and request lines. Fixes #9 --- .github/workflows/test.yml | 15 ++++++++ Gemfile.lock | 5 ++- lib/log_struct/formatter.rb | 9 +++-- logstruct.gemspec | 5 ++- scripts/railties_smoke_test.sh | 69 ++++++++++++++++++++++++++++++++++ 5 files changed, 97 insertions(+), 6 deletions(-) create mode 100755 scripts/railties_smoke_test.sh diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 5f852f60..5a6dad0d 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -243,3 +243,18 @@ jobs: - name: Run Rails integration tests run: scripts/rails_tests.sh + + railties_only: + name: 'Tests: railties without the rest of Rails' + needs: [lint] + runs-on: ubuntu-22.04 + steps: + - uses: actions/checkout@v4 + + - name: Setup Ruby + uses: ruby/setup-ruby@v1 + with: + ruby-version: '.ruby-version' + + - name: Boot an app that only bundles railties and actionpack + run: scripts/railties_smoke_test.sh diff --git a/Gemfile.lock b/Gemfile.lock index fa8e7e37..bc724838 100644 --- a/Gemfile.lock +++ b/Gemfile.lock @@ -2,8 +2,11 @@ PATH remote: . specs: logstruct (0.1.12) + actionpack (>= 7.1) + activesupport (>= 7.1) + globalid (>= 1.0) lograge (>= 0.11) - rails (>= 7.1) + railties (>= 7.1) semantic_logger (~> 4.15) sorbet-runtime (>= 0.5) diff --git a/lib/log_struct/formatter.rb b/lib/log_struct/formatter.rb index d37572db..4d0ef7f6 100644 --- a/lib/log_struct/formatter.rb +++ b/lib/log_struct/formatter.rb @@ -81,13 +81,14 @@ def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity) arg.to_global_id rescue begin - case arg - when ActiveRecord::Base - "#{arg.class}(##{arg.id})" + object = T.cast(arg, Object) + # Active Record is optional + if defined?(::ActiveRecord::Base) && object.is_a?(::ActiveRecord::Base) + "#{object.class}(##{object.id})" else # For non-ActiveRecord objects that failed to_global_id, try to get a string representation # If this also fails, we want to catch it and return the error placeholder - String(T.cast(arg, Object)) + String(object) end rescue => e LogStruct.handle_exception(e, source: Source::Internal) diff --git a/logstruct.gemspec b/logstruct.gemspec index 7bac4bbb..709db8a6 100644 --- a/logstruct.gemspec +++ b/logstruct.gemspec @@ -33,8 +33,11 @@ Gem::Specification.new do |spec| spec.executables = spec.files.grep(%r{\Aexe/}) { |f| File.basename(f) } spec.require_paths = ["lib"] + spec.add_dependency "actionpack", ">= 7.1" + spec.add_dependency "activesupport", ">= 7.1" + spec.add_dependency "globalid", ">= 1.0" spec.add_dependency "lograge", ">= 0.11" - spec.add_dependency "rails", ">= 7.1" + spec.add_dependency "railties", ">= 7.1" spec.add_dependency "semantic_logger", "~> 4.15" spec.add_dependency "sorbet-runtime", ">= 0.5" diff --git a/scripts/railties_smoke_test.sh b/scripts/railties_smoke_test.sh new file mode 100755 index 00000000..b74d620d --- /dev/null +++ b/scripts/railties_smoke_test.sh @@ -0,0 +1,69 @@ +#!/usr/bin/env bash +# Boots a Rails app whose bundle has railties and actionpack but not the rest of Rails +# (no Active Record, Active Job, Action Mailer, etc.), and checks that LogStruct sets up +# and logs a request. +set -euo pipefail + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +PROJECT_ROOT="$(dirname "$SCRIPT_DIR")" +APP_DIR="$(mktemp -d)" +trap 'rm -rf "$APP_DIR"' EXIT + +cat > "$APP_DIR/Gemfile" <= 7.1}" +# ActiveSupport's JSON encoder passes quirks_mode to JSON.generate, which json 3 rejects +gem "json", "< 3" +GEMFILE + +cat > "$APP_DIR/app.rb" <<'RUBY' +require "bundler/setup" +require "rails" +require "action_controller/railtie" +require "logstruct" + +class SmokeApp < Rails::Application + config.load_defaults Rails::VERSION::STRING.to_f + config.eager_load = false + config.secret_key_base = "0" * 64 + config.hosts.clear + config.logger = ActiveSupport::Logger.new(nil) + routes.append { root "smoke#index" } +end + +class SmokeController < ActionController::Base + def index + Rails.logger.info("smoke test") + render plain: "ok" + end +end + +Rails.application.initialize! + +status, = Rack::MockRequest.new(Rails.application).get("/").then { |r| [r.status] } +SemanticLogger.flush + +missing = %w[activerecord activejob actionmailer activestorage actioncable].select { |name| Gem.loaded_specs.key?(name) } +raise "Bundle includes #{missing.join(", ")}" if missing.any? +raise "Expected 200, got #{status}" unless status == 200 +raise "LogStruct isn't enabled" unless LogStruct.enabled? + +lines = File.readlines(ENV.fetch("SMOKE_LOG")).map { |line| JSON.parse(line) } +raise "No app log line in #{lines.inspect}" unless lines.any? { |line| line["msg"] == "smoke test" } +raise "No request log line in #{lines.inspect}" unless lines.any? { |line| line["evt"] == "request" && line["status"] == 200 } + +puts "Railties-only app booted and logged #{lines.size} JSON lines" +RUBY + +mkdir -p "$APP_DIR/log" +cd "$APP_DIR" +unset BUNDLE_GEMFILE BUNDLE_PATH BUNDLE_WITH BUNDLE_WITHOUT RUBYOPT +export BUNDLE_GEMFILE="$APP_DIR/Gemfile" +export BUNDLE_PATH="$APP_DIR/vendor/bundle" +bundle install --quiet +LOGSTRUCT_ENABLED=true RAILS_ENV=production SMOKE_LOG="$APP_DIR/log.jsonl" \ + bundle exec ruby -e 'STDOUT.reopen(ENV.fetch("SMOKE_LOG"), "w"); STDOUT.sync = true; load "app.rb"' || + { echo "Smoke test failed. Log output:"; cat "$APP_DIR/log.jsonl"; exit 1; } +tail -1 "$APP_DIR/log.jsonl" From ac40eb20d067adf1749ab8edb5277ac95205aef1 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 10:54:22 +1300 Subject: [PATCH 3/4] Write to STDOUT without buffering Ruby buffers STDOUT when it isn't a terminal, as in a container, so log lines waited until the buffer filled or the process exited, and a crash lost them. Puma and Sidekiq sync STDOUT themselves, but GoodJob's executable only does when it adds its own text logger. The STDOUT appender now syncs STDOUT. --- lib/log_struct/semantic_logger/setup.rb | 5 +++++ test/log_struct/semantic_logger_test.rb | 20 ++++++++++++++++++++ 2 files changed, 25 insertions(+) diff --git a/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index bb3164dc..fe1488c1 100644 --- a/lib/log_struct/semantic_logger/setup.rb +++ b/lib/log_struct/semantic_logger/setup.rb @@ -138,6 +138,11 @@ def self.add_appenders(app) # Determine output destination io = determine_output(app) + # Ruby buffers STDOUT when it isn't a terminal, so in a container lines waited until the buffer + # filled or the process exited. (GoodJob's executable only syncs STDOUT when it writes its own + # text logs there.) + io.sync = true if io.equal?($stdout) + if Rails.env.development? if config.prefer_json_in_development # Default to production-style JSON in development when enabled diff --git a/test/log_struct/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index 2abbc0f4..1632c4ff 100644 --- a/test/log_struct/semantic_logger_test.rb +++ b/test/log_struct/semantic_logger_test.rb @@ -4,6 +4,7 @@ require "test_helper" require "log_struct/semantic_logger/formatter" require "log_struct/semantic_logger/logger" +require "tempfile" module LogStruct class SemanticLoggerTest < ActiveSupport::TestCase @@ -16,6 +17,25 @@ class SemanticLoggerTest < ActiveSupport::TestCase teardown_isolated_logger end + test "writes to STDOUT without buffering" do + # Like STDOUT when it's a pipe or a file + stdout = Tempfile.new("stdout") + stdout.sync = false + saved_stdout = $stdout + $stdout = stdout + + ClimateControl.modify(RAILS_LOG_TO_STDOUT: "true") do + LogStruct::SemanticLogger::Setup.add_appenders(Rails.application) + end + + assert stdout.sync + ensure + # Remove the appenders writing to it before closing it; teardown puts back the others + ::SemanticLogger.clear_appenders! + $stdout = saved_stdout + stdout&.close! + end + test "logs plain messages through SemanticLogger" do @logger.info("Test message") ::SemanticLogger.flush From 3e9b26629b19c2569696090898c3e56846992706 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 10:55:14 +1300 Subject: [PATCH 4/4] Don't also write a log file when RAILS_LOG_TO_STDOUT is set LogStruct added a file appender whenever Rails had a log path, so with RAILS_LOG_TO_STDOUT set every line was written to STDOUT and to log/.log as well. In a container nothing reads or rotates that file, so it only grew. RAILS_LOG_TO_STDOUT now means STDOUT only, as it does for Rails' own logger. --- lib/log_struct/semantic_logger/setup.rb | 5 +++-- test/log_struct/semantic_logger_test.rb | 10 ++++++++++ 2 files changed, 13 insertions(+), 2 deletions(-) diff --git a/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index fe1488c1..07129f2a 100644 --- a/lib/log_struct/semantic_logger/setup.rb +++ b/lib/log_struct/semantic_logger/setup.rb @@ -176,8 +176,9 @@ def self.add_appenders(app) ) end - # Add file appender if Rails has a log path configured (normal Rails behavior) - if app.config.paths["log"].first + # Add file appender if Rails has a log path configured (normal Rails behavior), unless + # RAILS_LOG_TO_STDOUT says to log to STDOUT instead: in a container the file only fills the disk + if app.config.paths["log"].first && ENV["RAILS_LOG_TO_STDOUT"].blank? ::SemanticLogger.add_appender( file_name: app.config.paths["log"].first, formatter: LogStruct::SemanticLogger::Formatter.new, diff --git a/test/log_struct/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index 1632c4ff..aa1b40ff 100644 --- a/test/log_struct/semantic_logger_test.rb +++ b/test/log_struct/semantic_logger_test.rb @@ -36,6 +36,16 @@ class SemanticLoggerTest < ActiveSupport::TestCase stdout&.close! end + test "logs only to STDOUT when RAILS_LOG_TO_STDOUT is set" do + ClimateControl.modify(RAILS_LOG_TO_STDOUT: "true") do + LogStruct::SemanticLogger::Setup.add_appenders(Rails.application) + end + + assert_empty(::SemanticLogger.appenders.select { |appender| appender.is_a?(::SemanticLogger::Appender::File) }) + ensure + ::SemanticLogger.clear_appenders! + end + test "logs plain messages through SemanticLogger" do @logger.info("Test message") ::SemanticLogger.flush