Skip to content

Commit 647f352

Browse files
committed
Fixed a few issues, added tests for logs in tests
1 parent b840aed commit 647f352

File tree

10 files changed

+139
-17
lines changed

10 files changed

+139
-17
lines changed

.cspell/project-words.txt

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ dotenv
1717
Dotenv
1818
Fanout
1919
favicons
20+
popen
2021
gettime
2122
goodjob
2223
Healthcheck

lib/log_struct.rb

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,9 @@
2222
require "log_struct/semantic_logger/setup"
2323
require "log_struct/rails_boot_banner_silencer"
2424

25+
# Monkey patches for Rails compatibility
26+
require "log_struct/monkey_patches/active_support/tagged_logging/formatter"
27+
2528
module LogStruct
2629
extend T::Sig
2730

lib/log_struct/integrations/action_mailer/metadata_collection.rb

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -54,11 +54,13 @@ def self.extract_ids_to_log_data(mailer, log_data)
5454

5555
sig { params(log_data: T::Hash[Symbol, T.untyped]).void }
5656
def self.add_current_tags_to_log_data(log_data)
57-
# Get current tags from ActiveSupport::TaggedLogging if available
58-
if ::ActiveSupport::TaggedLogging.respond_to?(:current_tags)
59-
tags = T.unsafe(::ActiveSupport::TaggedLogging).current_tags
60-
log_data[:tags] = tags if tags.present?
57+
# Get current tags from thread-local storage or ActiveSupport::TaggedLogging
58+
tags = if ::ActiveSupport::TaggedLogging.respond_to?(:current_tags)
59+
T.unsafe(::ActiveSupport::TaggedLogging).current_tags
60+
else
61+
Thread.current[:activesupport_tagged_logging_tags] || []
6162
end
63+
log_data[:tags] = tags if tags.present?
6264

6365
# Get request_id from ActionDispatch if available
6466
if ::ActionDispatch::Request.respond_to?(:current_request_id) &&

lib/log_struct/integrations/active_job/log_subscriber.rb

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -81,7 +81,7 @@ def build_base_fields(job)
8181
Log::ActiveJob::BaseFields.new(
8282
job_id: job.job_id,
8383
job_class: job.class.to_s,
84-
queue_name: job.queue_name,
84+
queue_name: job.queue_name&.to_sym,
8585
executions: job.executions,
8686
provider_job_id: job.provider_job_id,
8787
arguments: ((job.class.respond_to?(:log_arguments?) && job.class.log_arguments?) ? job.arguments : nil)
@@ -98,7 +98,7 @@ def log_exception(exception, job, _event)
9898
logger.error(log_data)
9999
end
100100

101-
sig { returns(::ActiveSupport::Logger) }
101+
sig { returns(T.untyped) }
102102
def logger
103103
::ActiveJob::Base.logger
104104
end

lib/log_struct/monkey_patches/active_support/tagged_logging/formatter.rb

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,6 +8,16 @@
88
# directly into the hash instead of being prepended as strings
99
module ActiveSupport
1010
module TaggedLogging
11+
extend T::Sig
12+
13+
# Add class-level current_tags method for compatibility with Rails code
14+
# that expects to call ActiveSupport::TaggedLogging.current_tags
15+
# Use thread-local storage directly like Rails does internally
16+
sig { returns(T::Array[T.any(String, Symbol)]) }
17+
def self.current_tags
18+
Thread.current[:activesupport_tagged_logging_tags] || []
19+
end
20+
1121
module FormatterExtension
1222
extend T::Sig
1323
extend T::Helpers
@@ -23,7 +33,8 @@ def call(severity, time, progname, data)
2333
data = {message: data.to_s} unless data.is_a?(Hash)
2434

2535
# Add current tags to the hash if present
26-
tags = current_tags
36+
# Use thread-local storage directly as fallback if current_tags method doesn't exist
37+
tags = T.unsafe(self).respond_to?(:current_tags) ? current_tags : (Thread.current[:activesupport_tagged_logging_tags] || [])
2738
data[:tags] = tags if tags.present?
2839

2940
# Call the original formatter with our enhanced data

lib/log_struct/railtie.rb

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -33,9 +33,6 @@ class Railtie < ::Rails::Railtie
3333
initializer "logstruct.configure_logger", after: :initialize_logger do |app|
3434
next unless LogStruct.enabled?
3535

36-
# Apply TaggedLogging monkey patch only when enabled
37-
require_relative "monkey_patches/active_support/tagged_logging/formatter"
38-
3936
# Use SemanticLogger for powerful logging features
4037
LogStruct::SemanticLogger::Setup.configure_semantic_logger(app)
4138
end

lib/log_struct/semantic_logger/logger.rb

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -73,13 +73,19 @@ def initialize(name = "Application", level: nil, filter: nil)
7373
# T.untyped because users can pass any logger: ::Logger, ActiveSupport::Logger,
7474
# custom loggers (FakeLogger in tests), or third-party loggers
7575
@broadcasts = T.let([], T::Array[T.untyped])
76+
# ActiveJob expects logger.formatter to exist and respond to current_tags
77+
@formatter = T.let(FormatterProxy.new, FormatterProxy)
7678
end
7779

7880
# ActiveSupport::BroadcastLogger compatibility
7981
# These methods allow Rails.logger to broadcast to multiple loggers
8082
sig { returns(T::Array[T.untyped]) }
8183
attr_reader :broadcasts
8284

85+
# ActiveJob compatibility - expects logger.formatter.current_tags
86+
sig { returns(FormatterProxy) }
87+
attr_reader :formatter
88+
8389
# T.untyped for logger param because we accept any logger-like object:
8490
# ::Logger, ActiveSupport::Logger, test doubles, etc.
8591
sig { params(logger: T.untyped).returns(T.untyped) }
@@ -140,5 +146,15 @@ def <<(msg)
140146
self
141147
end
142148
end
149+
150+
# Proxy object to provide ActiveJob-compatible formatter interface
151+
class FormatterProxy
152+
extend T::Sig
153+
154+
sig { returns(T::Array[T.any(String, Symbol)]) }
155+
def current_tags
156+
Thread.current[:activesupport_tagged_logging_tags] || []
157+
end
158+
end
143159
end
144160
end

lib/log_struct/semantic_logger/setup.rb

Lines changed: 11 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -152,8 +152,8 @@ def self.add_appenders(app)
152152
)
153153
end
154154

155-
# Add file appender if configured and not already logging to STDOUT/StringIO
156-
if app.config.paths["log"].first && io != $stdout && !io.is_a?(StringIO)
155+
# Add file appender if Rails has a log path configured (normal Rails behavior)
156+
if app.config.paths["log"].first
157157
::SemanticLogger.add_appender(
158158
file_name: app.config.paths["log"].first,
159159
formatter: LogStruct::SemanticLogger::Formatter.new,
@@ -164,14 +164,14 @@ def self.add_appenders(app)
164164

165165
sig { params(app: T.untyped).returns(T.untyped) }
166166
def self.determine_output(app)
167-
# Always honor explicit STDOUT directive, even in test, or when LogStruct is enabled via env
168-
return $stdout if ENV["RAILS_LOG_TO_STDOUT"].present? || ENV["LOGSTRUCT_ENABLED"].to_s.strip.downcase == "true"
167+
# Always honor explicit STDOUT directive
168+
return $stdout if ENV["RAILS_LOG_TO_STDOUT"].present?
169169

170170
if Rails.env.test?
171-
# Default to StringIO to keep test output clean unless STDOUT is requested
171+
# Use StringIO in test to keep stdout clean
172172
StringIO.new
173173
else
174-
# Default to STDOUT for app logs
174+
# Use STDOUT for app logs in dev/production
175175
$stdout
176176
end
177177
end
@@ -222,7 +222,11 @@ def self.replace_rails_logger(app)
222222
# Also replace various component loggers
223223
ActiveRecord::Base.logger = logger if defined?(ActiveRecord::Base)
224224
ActionController::Base.logger = logger if defined?(ActionController::Base)
225-
ActionMailer::Base.logger = logger if defined?(ActionMailer::Base)
225+
if defined?(ActionMailer::Base)
226+
ActionMailer::Base.logger = logger
227+
# Ensure ActionMailer.logger is also set (it might be accessed directly)
228+
T.unsafe(::ActionMailer).logger = logger if T.unsafe(::ActionMailer).respond_to?(:logger=)
229+
end
226230
ActiveJob::Base.logger = logger if defined?(ActiveJob::Base)
227231
ActionView::Base.logger = logger if defined?(ActionView::Base)
228232
ActionCable.server.config.logger = logger if defined?(ActionCable)
Lines changed: 78 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,78 @@
1+
# typed: true
2+
3+
require "test_helper"
4+
require "open3"
5+
require "timeout"
6+
require "fileutils"
7+
8+
class TestLoggingIntegrationTest < ActiveSupport::TestCase
9+
def test_test_logs_go_to_file_not_stdout
10+
# Clean up log file before test
11+
log_file = Rails.root.join("log/test.log")
12+
FileUtils.rm_f(log_file)
13+
FileUtils.touch(log_file)
14+
15+
env = {
16+
"LOGSTRUCT_ENABLED" => "true",
17+
"RAILS_ENV" => "test"
18+
}
19+
20+
# Run a simple test that will generate logs
21+
cmd = ["bundle", "exec", "rails", "test", "test/models/user_test.rb"]
22+
23+
Open3.popen3(env, *cmd, chdir: Rails.root.to_s) do |_stdin, stdout, stderr, wait_thr|
24+
begin
25+
Timeout.timeout(30) do
26+
wait_thr.value # Wait for process to complete
27+
end
28+
rescue Timeout::Error
29+
begin
30+
Process.kill("TERM", wait_thr.pid)
31+
rescue
32+
nil
33+
end
34+
35+
flunk "Test process timed out"
36+
end
37+
38+
stdout_output = stdout.read
39+
stderr.read
40+
41+
# Check that stdout doesn't contain JSON logs
42+
json_lines_in_stdout = stdout_output.lines.select { |line|
43+
line.strip.start_with?("{") && begin
44+
JSON.parse(line)
45+
rescue
46+
nil
47+
end
48+
}
49+
50+
assert_equal 0,
51+
json_lines_in_stdout.length,
52+
"Expected no JSON logs in stdout, but found #{json_lines_in_stdout.length} lines. First few:\n#{json_lines_in_stdout.first(3).join}"
53+
54+
# Check that log/test.log contains JSON logs
55+
assert_path_exists log_file, "Expected log/test.log to exist"
56+
log_contents = File.read(log_file)
57+
58+
json_lines_in_file = log_contents.lines.select { |line|
59+
line.strip.start_with?("{") && begin
60+
JSON.parse(line)
61+
rescue
62+
nil
63+
end
64+
}
65+
66+
assert_operator json_lines_in_file.length, :>, 0, "Expected JSON logs in log/test.log, but found none. File size: #{log_contents.bytesize} bytes"
67+
68+
# Verify at least one structured log exists
69+
parsed_logs = json_lines_in_file.map { |line| JSON.parse(line) }
70+
71+
assert parsed_logs.any? { |log| log["src"] && log["evt"] && log["lvl"] },
72+
"Expected at least one properly structured log in log/test.log"
73+
end
74+
ensure
75+
# Clean up
76+
FileUtils.rm_f(log_file) if log_file
77+
end
78+
end
Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
# typed: true
2+
3+
require "test_helper"
4+
5+
class UserTest < ActiveSupport::TestCase
6+
test "simple test that generates logs" do # rubocop:disable Minitest/NoAssertions
7+
# This test just needs to run and generate some logs
8+
Rails.logger.info("Test log message")
9+
end
10+
end

0 commit comments

Comments
 (0)