Combing tagged logger without block and with block leaks tags across threads

[erikbelusic]

Using the tagged logger without a block does not appear to have the same threaded isolation that tagging with a block has. The documentation doesn't make it clear if its intended or not, but from a user's perspective, it is unexpected. From the existing tests, it looks like some of this is expected, but the inconsistency is confusing. I left a comment on the original PR to try and get some insight.

This could be in some ways related to #46084 - however the focus of that is broadcast logging and not threading, however the issues seem similar - tag leak.

Steps to reproduce

This example currently relies on identical setup to what is in activesupport/test/tagged_logging_test.rb which should make it easy to add these tests or some modified versions if its agreed this is a bug.

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  gem "rails", github: "rails/rails", branch: "main"
end

require "active_support"
require "active_support/core_ext/object/blank"
require "minitest/autorun"

class BugTest < Minitest::Test
  # Copied from activesupport/test/tagged_logging_test.rb
  class MyLogger < ::ActiveSupport::Logger
    def flush(*)
      info "[FLUSHED]"
    end
  end

  # Copied from activesupport/test/tagged_logging_test.rb
  def setup
    @output = StringIO.new
    @logger = ActiveSupport::TaggedLogging.new(MyLogger.new(@output))
  end

  # Copied from activesupport/test/tagged_logging_test.rb:80
  def test_keeps_each_tag_in_their_own_thread
    @logger.tagged("BCX") do
      Thread.new do
        @logger.info "Dull story"
        @logger.tagged("OMG") { @logger.info "Cool story" }
      end.join
      @logger.info "Funky time"
    end
    assert_equal "Dull story\n[OMG] Cool story\n[BCX] Funky time\n", @output.string
  end
  # PASS output:
  # Dull story
  # [OMG] Cool story
  # [BCX] Funky time

  def test_keeps_each_tag_in_their_own_thread_using_tagged_without_block
    logger1 = @logger.tagged("BCX")
    Thread.new do
      logger1.info "Dull story"
      logger2 = logger1.tagged("OMG")
      logger2.info "Cool story"
    end.join
    logger1.info "Funky time"

    assert_equal "Dull story\n[OMG] Cool story\n[BCX] Funky time\n", @output.string
  end
  # FAIL output:
  # [BCX] Dull story
  # [BCX] [OMG] Cool story
  # [BCX] Funky time

  def test_keeps_each_tag_in_their_own_thread_using_tagged_without_block_combined_with_tagged_block
    logger1 = @logger.tagged("BCX")
    Thread.new do
      logger1.info "Dull story"
      logger1.tagged("OMG") { logger1.info "Cool story" }
    end.join
    logger1.info "Funky time"

    assert_equal "Dull story\n[OMG] Cool story\n[BCX] Funky time\n", @output.string
  end
  # FAIL output:
  # [BCX] Dull story
  # [BCX] [OMG] Cool story
  # [BCX] Funky time

  def test_keeps_each_tag_in_their_own_thread_using_tagged_without_block_combined_with_tagged_block_nested
    logger = @logger.tagged("BASE_TAG")
    logger.tagged("BCX") do
      Thread.new do
        logger.info "Dull story"
        logger.tagged("OMG") { logger.info "Cool story" }
      end.join
      logger.info "Funky time"
    end
    assert_equal "[BASE_TAG] Dull story\n[BASE_TAG] [OMG] Cool story\n[BASE_TAG] [BCX] Funky time\n", @output.string
  end
  # FAIL output:
  # [BASE_TAG] [BCX] Dull story
  # [BASE_TAG] [BCX] [OMG] Cool story
  # [BASE_TAG] [BCX] Funky time
end

Expected behavior

I would expect that if #tagged has a certain level of thread isolation, it should always have that isolation and behave consistently. At a minimum test_keeps_each_tag_in_their_own_thread_using_tagged_without_block_combined_with_tagged_block_nested should pass. It seems awkward that depending on how your current logger instance was created, the behavior of tagging with a block could change. I think it is worth a conversation on the correct behavior here, as maybe my first two failures should remain failures due to some context or intent I am unaware of.

Actual behavior

1. When using a new logger created from #tagged, tags are shared across threads
2. When tagging with a block from a logger instance created from #tagged, all tags are shared

System configuration

Rails version: main

Ruby version: 3.0.0

[darkhelmet]

I think I hit this today and was very confused. I can break it (in my eyes) on the console:

Rails.logger.debug('hi') # => hi
Rails.logger.tagged('a tag').debug('hi') # => [a tag] hi
Rails.logger.debug('hi') # => [a tag] hi

The first 2 lines make sense, but that third line...why is it still tagged? The docs (my emphasis):

If called without a block, a new logger will be returned with applied tags:

A new logger is returned (object id is different), but...