Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Calling original failed when stubbing logger for ActiveSupport::TaggedLogging #2594

Open
kimyu92 opened this issue Apr 17, 2022 · 2 comments

Comments

@kimyu92
Copy link

kimyu92 commented Apr 17, 2022

What Ruby, Rails and RSpec versions are you using?

Ruby version: 2.7+
Rails version: 7.0.2.3
RSpec version: 5.1.1

Observed behaviour

Tag from tagged logger is lost in between and content is not being honored when calling original if any logging (warn/info/debug/...) method is stubbed

Expected behaviour

The tagged logger content should be preserved when using and_call_original for stubbing any logging (warn/info/debug/...) methods

Can you provide an example app?

# 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', '~> 7.0.2.3'
  gem 'rspec-rails', '~> 5.1.1'
end

require 'active_support'
require 'active_support/core_ext/object/blank'

require 'action_controller/railtie'
require 'action_view/railtie'

require 'minitest/autorun'
class BugTest < Minitest::Test
  def test_custom_logger
    io = StringIO.new
    logger = ActiveSupport::Logger.new(io)
    tagged_logger = ActiveSupport::TaggedLogging.new(logger)

    tagged_logger.tagged('FOO') { |logger| logger.info 'bar 2333' }
    assert_equal "[FOO] bar 2333\n", io.string
  end
end

require 'rspec/autorun'
require 'rspec/rails'

RSpec.configure do |config|
  config.filter_run_excluding skip: true
  config.run_all_when_everything_filtered = true
  config.filter_run focus: true
end

RSpec.describe 'TaggedLogging' do
  let(:io) { StringIO.new }
  let(:logger) { Logger.new(io) }

  before do
    # commenting this out would allow the message pass through correctly
    allow(logger).to receive(:info).and_call_original

    tagged_logger = ActiveSupport::TaggedLogging.new(logger)
    tagged_logger.tagged('FOO') { |logger| logger.info 'bar 2333' }
  end

  it { expect(logger).to have_received(:info).once }

  it 'includes tags' do
    # Expectation: [FOO] bar 2333
    # Result: I, [2022-04-16T23:23:44.481396 #12280]  INFO -- : bar 2333
    expect(io.string).to eq("[FOO] bar 2333\n")
  end
end
@JonRowe
Copy link
Member

JonRowe commented Apr 22, 2022

Can yoiu check out #2587 and see if it fixes this? Theres no built in support for the tagged logger currently and I suspect this is an "ordering" issue with the method calls

@kimyu92
Copy link
Author

kimyu92 commented Apr 22, 2022

Can you check out #2587 and see if it fixes this? Theres no built in support for the tagged logger currently and I suspect this is an "ordering" issue with the method calls

I have tried one of the branch directly, unless I have to call include RSpec::Rails::TaggedLoggingAdapter in the setup, i believe the issue hasn't been fixed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants