Incompatibility with ActiveSupport::TaggedLogging

[leehambley]

Describe the bug

When using dry-effects (specifically something like include Dry::Effects::Handler::State(:counter), inside a provide(..) { ... } block, any ActiveSupport::TaggedLogging tags may be lost.

A bug report to Rails was opened by my colleague:

• https://github.com/rails/rails/issues/37535

This issue has been opened here to draw the issue to your attention only. I don't know if it's appropriate to workaround AS here, or if some concession can be made to make this more reliable.

At least, maybe a documentation entry could be added to highlight the incompatibility.

To Reproduce

A simple example that simulates what's going on inside AS::TaggedLogging looks like this:

Thread.current[:fiber_local_var] = 'Result'
Fiber.new do
  puts Thread.current[:fiber_local_var]
end.resume
# => <Empty output>

Thread.current.thread_variable_set(:thread_local_var, 'Result')
Fiber.new do
  puts Thread.current.thread_variable_get(:thread_local_var)
end.resume
# => "Result"

In practice however trying to do something like this would/should cause the issue:

logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
include Dry::Effects::Handler.Resolve
include Dry::Effects.Resolve(:anything)
logger.tagged("A") do
  logger.info "before provide"
  provide(anything: :foo) { anything; logger.info "in provide" }
  logger.info "after provide"
end

Expected behavior

The code above should print:

[A] before provide
[A] in provide
[A] after provide

but it actually prints:

[A] before provide
in provide
[A] after provide

Your environment

$ ruby --version
ruby 2.6.5p114 (2019-10-01 revision 67812) [x86_64-linux]
$ bin/rails version
Rails 6.0.2.1
$ uname -r
5.3.16-300.fc31.x86_64

• Affects my production application: No (yes, but we around by using https://github.com/steveklabnik/request_store as a "replacemnt" for dry-effects DI)

[flash-gordon]

Yeah, such things can break with dry-effects. Ideally, all libraries will use dry-effects, and this is it. Until this day comes, my strategy is writing "official" monkey patches for broken gems. Luckily, this doesn't happen often. I did so for rspec, used it for months with no issues. I'll try to do the same for ActiveSupport::TaggedLogging.

By the way, the logger I use runs effects for storing tags. Just saying.

Thank for reporting, I'll take another look sometime later this week.

[leehambley]

Short update that this quick hacky monkey patch works. I took the code directly from @rafadc's patch to Rails for the same issue.

I'm not sure how "dry-effect"y it is, I see you used different provide-consume techniques for your otner semi-official monkeypatches.

• https://github.com/rails/rails/pull/37566

module ActiveSupport
  module TaggedLogging
    Formatter.prepend(Module.new {
      def current_tags
        thread_key = @thread_key ||= "activesupport_tagged_logging_tags:#{object_id}"
        Thread.current.thread_variable_set(thread_key, []) unless Thread.current.thread_variable_get(thread_key)
        Thread.current.thread_variable_get(thread_key)
      end
    })
  end
end

logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT))
include Dry::Effects::Handler.Resolve
include Dry::Effects.Resolve(:anything)
logger.tagged("A") do
  logger.info "before provide"
  provide(anything: :foo) { anything; logger.info "in provide" }
  logger.info "after provide"
end

Which yields in an Rails 6 IRB session:

[A] before provide
[A] in provide
[A] after provide
=> true

[leehambley]

@flash-gordon what do you think of this solution? If I package this as a PR rather than just a comment are you interested in maybe merging it?

Thanks!

[flash-gordon]

@leehambley sorry for the delay, I'll get back to you ASAP, I've had no spare time in the last two weeks but now it's getting better :) I'll have a deeper look tomorrow

[flash-gordon]

@leehambley after considering for a while, I believe your approach is good. I didn't know AS has thread_variable_get/thread_variable_set, this will work for us. Would you like to send a PR? If not, I'm planning to apply your patch on the weekend.

For the record, effects-style approach would be

ActiveSupport::TaggedLogging::Formatter.prepend(Module.new {
  prepend Dry::Effects.Cache(active_support: :current_tags)

  def current_tags
    []
  end
})

This, however, will require adding wrapping code

class Middleware
  include Dry::Effects::Handler.Cache(:active_support)

  def initialize(app)
    @app = app
  end

  def call(env)
    with_cache { @app.(env) }
  end
end

I don't want people to change their code, this is why your solution is preferable.

[leehambley]

I was equally surprised, credit for finding it goes to @rafadc - it seems to be core ruby -

Sets a thread local with key to value. Note that these are local to threads, and not to fibers. Please see Thread#thread_variable_get and Thread#[] for more information.

• https://www.rubydoc.info/stdlib/core/Thread:thread_variable_set

Maybe I see prior to Rails 5 it was also in activesupport with a native Ruby implementation.

I'll follow up with a PR to add my solution (and a useful commit message) in a few minutes :pray:

[leehambley]

Opened https://github.com/dry-rb/dry-effects/pull/76

[flash-gordon]

Nicely pushed by https://rubygems.org/profiles/dry-bot as 0.1.5