Tags leak across broadcasted loggers

[thomasgt]

I'm trying to create a tagged logger (final_logger) from another tagged logger (tagged_logger2) that is receiving broadcasts from yet another tagged logger (tagged_logger1). This situation triggers an odd behaviour: tags applied to final_logger leak upstream to the original tagged_logger1.

Steps to reproduce

To reproduce, run this test case (it can be found on my fork here):

  test "tags do not leak across loggers" do
    sink1 = StringIO.new
    sink2 = StringIO.new

    tagged_logger1 = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(sink1))
    tagged_logger2 = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(sink2))
    tagged_logger2.extend(ActiveSupport::Logger.broadcast(tagged_logger1))

    final_logger = ActiveSupport::TaggedLogging.new(tagged_logger2).tagged("test")

    tagged_logger1.info("foo") # should write "foo" to sink1
    tagged_logger2.info("bar") # should write "bar" to sink1 (via broadcast) and "bar" to sink2
    final_logger.info("baz")   # should write "baz" to sink1 (via broadcast) and "[test] baz" to sink2

    sink1_lines = sink1.string.each_line.to_a
    sink2_lines = sink2.string.each_line.to_a

    assert_equal 3, sink1_lines.length
    assert_equal 2, sink2_lines.length

    assert_equal "foo\n", sink1_lines[0]
    assert_equal "bar\n", sink1_lines[1]
    assert_equal "baz\n", sink1_lines[2]

    assert_equal "bar\n", sink2_lines[0]
    assert_equal "[test] baz\n", sink2_lines[1]
  end

Expected behavior

I would expect this test to pass.

Actual behavior

The assertions on the logs in sink1 fail; they are prefixed with "[test]":

Failure:
TaggedLoggingWithoutBlockTest#test_tags_do_not_leak_across_loggers [/Users/thomasgt/src/github.com/thomasgt/rails/activesupport/test/tagged_logging_test.rb:250]:
--- expected
+++ actual
@@ -1,2 +1,2 @@
-"foo
+"[test] foo
 "

System configuration

We originally thought this bug was related to this PR. It was reverted, but the problem persists. Our thinking now is that the PR re-implemented the bug in a different way, so reverting had no effect.

Rails version:

• After revert: https://github.com/thomasgt/rails/tree/logger-leak-1
• Before revert: https://github.com/thomasgt/rails/tree/logger-leak-2

Ruby version:
3.1.2

[tiegz]

I'm trying to create a tagged logger (final_logger) from another tagged logger (tagged_logger2) that is receiving broadcasts from yet another tagged logger (tagged_logger1).

@thomasgt correct me if I'm wrong, but in this example aren't you doing the opposite and sending broadcasts from tagged_logger2 to tagged_logger1?

tagged_logger2.extend(ActiveSupport::Logger.broadcast(tagged_logger1))

[khall]

You are creating two tagged loggers, tagged_logger1 and tagged_logger2. When you call broadcast and pass in tagged_logger1 the formatter= method is overwritten via

define_method(:formatter=) do |formatter|
  logger.formatter = formatter
  super(formatter)
end

Now when you call final_logger = ActiveSupport::TaggedLogging.new(tagged_logger2).tagged("test") you are creating a new tagged logger using tagged_logger2 as the logger to clone from. In the self.new method of TaggedLogging the formatter is copied from tagged_logger2. But since formatter= has been overwritten, it copies the same formatter to tagged_logger1 as well. Then you call .tagged("test"), but the tags exist on the formatter, so both tagged_logger1 and tagged_logger2 are changed.

Is this intentional? I'm not sure. There is a test ensuring formatter= assigns formats to all loggers being broadcast to (see broadcast_logger_test's #formatter= assigns to all the loggers), so I suspect it is intentional. Maybe somebody more familiar can weigh in.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 7-0-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

[oggy]

This is still a bug. I think it happens because of the way broadcasting extends the logger with a module that closes over the secondary logger, and then tagging later clones the logger, which can't clone the local variable trapped in the closure. So adding tags to the formatter ends up modifying the base logger's formatter.

The idea in #44695 about "using composition" sounded right, but it's not without its own complexities. It means we need to carefully delegate a lot of methods in different ways. Methods that just get sent to the child loggers vs methods that take a block vs methods that return something (e.g., #formatter). It's probably doable, but seems a bit messy.

I'm thinking a more fundamental problem is that broadcasting is implemented at the wrong level. It shouldn't wrap the logger, just the log device inside the logger. This isn't currently exposed by ruby's Logger, but maybe that can change (ruby/logger#88). That thing only has 3 methods: write, close, reopen, which could be much more easily reimplemented to delegate to the wrapped loggers' logdevs.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 7-0-stable branch or on main, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.

[Edouard-chin]

I'm working on refactoring TaggedLogging and implement a public API for broadcasting logs in #48615 and as I was adding a regression test to make sure this use case is taken in consideration.
But after second thoughts, I felt like what you are describing is what I would expect, but I could be misunderstanding.

To summarise your use case in your test, this is a small schema.

flowchart TD;
    subgraph B2["Broadcasting loggers"]
        direction LR
        tagged_logger2["tagger_logger_2 (Has no tags applied)"]-- clone ---
        final_logger["final_logger (Has the ['test'] tag applied)"]
    end
tagged_logger2-->tagged_logger1
final_logger-->tagged_logger1

When you call final_logger = ActiveSupport::TaggedLogging.new(tagged_logger2).tagged("test"), you are creating a clone of tagged_logger2 which itself broadcasts to tagged_logger1.

This is what I would expect:

1. Any logs from tagged_logger2 and final_logger (since it's a clone) would show up in the sink from tagged_logger1. Your test case covers this, so I think we aligned here.
2. Any tags applied to tagged_logger2 would show up in tagged_logger1.
3. Any tags applied to final_logger would show up in tagged_logger1.
4. Any tags applied to tagged_logger2 would not show up in final logger (and vice versa).

---

Your test case doesn't cover 2), but would that be what would expect in your logs?
If yes, why do you think final_logger tags should not show up in tagger_logger1's sink?
If no, does that mean you expects any tags applied to a broadcasting loger to never propagate to the sink it broadcasts to?

Thanks ❤️ !