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/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/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/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/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index bb3164dc..07129f2a 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 @@ -171,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/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" 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) diff --git a/test/log_struct/semantic_logger_test.rb b/test/log_struct/semantic_logger_test.rb index 2abbc0f4..aa1b40ff 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,35 @@ 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 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