2.2.0 breaks mdc when using Fibers

[uberjay]

Unfortunately #162 broke diagnostic contexts for applications using Fibers. If you don't use fibers, Thread.current#[] resolves to "the current thread’s root fiber if not explicitly inside a Fiber" (from the Thread documentation).

This means threaded code would have continued to function as expected, and fibered code also functions as expected. By changing to use thread_variable_get and thread_variable_set, you've made it so diagnostic contexts only work in threaded code.

I know this is basically ancient history, at this point, but I wonder if this change was fixing a bug that came up?

The following code demonstrates logging mdc from fiber and thread contexts. In 2.1.0 it works for either -- in 2.2.0 it only works for threads.

#!/usr/bin/env ruby

require 'logging'
require 'fiber'

Logging.appenders.stdout(
  :layout => Logging.layouts.pattern(:pattern => '[ID=%X{id}] %c %m\n')
)

Logging.mdc['id'] = 'CTL'

fiblog = Logging.logger['Fiber']
fiblog.add_appenders 'stdout'
fiblog.level = :debug

def new_fiber(id, logger, cycles, **mdc)
  Fiber.new do
    Logging.mdc['id'] = id
    Fiber.yield
    cycles.times do |cycle|
      logger.info "(should have ctx id=#{id}) - cycle \##{cycle}"
      Fiber.yield
    end
  end
    .tap(&:resume)
end

fibers = [
  new_fiber('f01', fiblog, 5),
  new_fiber('f02', fiblog, 3),
  new_fiber('f03', fiblog, 7),
]

fiblog.info '*** starting fiber test...'
while fibers.any?(&:alive?)
  fibers.filter(&:alive?).each(&:resume)
end
fiblog.info '*** fiber test done'

thrlog = Logging.logger['Thread']
thrlog.add_appenders 'stdout'
thrlog.level = :debug

def new_thread(id, logger, cycles, **mdc)
  Thread.new do
    Logging.mdc['id'] = id
    cycles.times do |cycle|
      logger.info "(should have ctx id=#{id}) - cycle \##{cycle}"
    end
  end
end

thrlog.info '*** starting thread test...'

threads = [
  new_thread('t01', thrlog, 5),
  new_thread('t02', thrlog, 3),
  new_thread('t03', thrlog, 7),
]

threads.each(&:join)

thrlog.info '*** thread test done'

Output with 2.1.0:

[ID=CTL] Fiber *** starting fiber test...
[ID=f01] Fiber (should have ctx id=f01) - cycle #0
[ID=f02] Fiber (should have ctx id=f02) - cycle #0
[ID=f03] Fiber (should have ctx id=f03) - cycle #0
[ID=f01] Fiber (should have ctx id=f01) - cycle #1
[ID=f02] Fiber (should have ctx id=f02) - cycle #1
[ID=f03] Fiber (should have ctx id=f03) - cycle #1
[ID=f01] Fiber (should have ctx id=f01) - cycle #2
[ID=f02] Fiber (should have ctx id=f02) - cycle #2
[ID=f03] Fiber (should have ctx id=f03) - cycle #2
[ID=f01] Fiber (should have ctx id=f01) - cycle #3
[ID=f03] Fiber (should have ctx id=f03) - cycle #3
[ID=f01] Fiber (should have ctx id=f01) - cycle #4
[ID=f03] Fiber (should have ctx id=f03) - cycle #4
[ID=f03] Fiber (should have ctx id=f03) - cycle #5
[ID=f03] Fiber (should have ctx id=f03) - cycle #6
[ID=CTL] Fiber *** fiber test done
[ID=CTL] Thread *** starting thread test...
[ID=t02] Thread (should have ctx id=t02) - cycle #0
[ID=t02] Thread (should have ctx id=t02) - cycle #1
[ID=t02] Thread (should have ctx id=t02) - cycle #2
[ID=t01] Thread (should have ctx id=t01) - cycle #0
[ID=t01] Thread (should have ctx id=t01) - cycle #1
[ID=t01] Thread (should have ctx id=t01) - cycle #2
[ID=t01] Thread (should have ctx id=t01) - cycle #3
[ID=t01] Thread (should have ctx id=t01) - cycle #4
[ID=t03] Thread (should have ctx id=t03) - cycle #0
[ID=t03] Thread (should have ctx id=t03) - cycle #1
[ID=t03] Thread (should have ctx id=t03) - cycle #2
[ID=t03] Thread (should have ctx id=t03) - cycle #3
[ID=t03] Thread (should have ctx id=t03) - cycle #4
[ID=t03] Thread (should have ctx id=t03) - cycle #5
[ID=t03] Thread (should have ctx id=t03) - cycle #6
[ID=CTL] Thread *** thread test done

Output with 2.2.0:

[ID=f03] Fiber *** starting fiber test...
[ID=f03] Fiber (should have ctx id=f01) - cycle #0
[ID=f03] Fiber (should have ctx id=f02) - cycle #0
[ID=f03] Fiber (should have ctx id=f03) - cycle #0
[ID=f03] Fiber (should have ctx id=f01) - cycle #1
[ID=f03] Fiber (should have ctx id=f02) - cycle #1
[ID=f03] Fiber (should have ctx id=f03) - cycle #1
[ID=f03] Fiber (should have ctx id=f01) - cycle #2
[ID=f03] Fiber (should have ctx id=f02) - cycle #2
[ID=f03] Fiber (should have ctx id=f03) - cycle #2
[ID=f03] Fiber (should have ctx id=f01) - cycle #3
[ID=f03] Fiber (should have ctx id=f03) - cycle #3
[ID=f03] Fiber (should have ctx id=f01) - cycle #4
[ID=f03] Fiber (should have ctx id=f03) - cycle #4
[ID=f03] Fiber (should have ctx id=f03) - cycle #5
[ID=f03] Fiber (should have ctx id=f03) - cycle #6
[ID=f03] Fiber *** fiber test done
[ID=f03] Thread *** starting thread test...
[ID=t02] Thread (should have ctx id=t02) - cycle #0
[ID=t01] Thread (should have ctx id=t01) - cycle #0
[ID=t01] Thread (should have ctx id=t01) - cycle #1
[ID=t01] Thread (should have ctx id=t01) - cycle #2
[ID=t01] Thread (should have ctx id=t01) - cycle #3
[ID=t01] Thread (should have ctx id=t01) - cycle #4
[ID=t02] Thread (should have ctx id=t02) - cycle #1
[ID=t02] Thread (should have ctx id=t02) - cycle #2
[ID=t03] Thread (should have ctx id=t03) - cycle #0
[ID=t03] Thread (should have ctx id=t03) - cycle #1
[ID=t03] Thread (should have ctx id=t03) - cycle #2
[ID=t03] Thread (should have ctx id=t03) - cycle #3
[ID=t03] Thread (should have ctx id=t03) - cycle #4
[ID=t03] Thread (should have ctx id=t03) - cycle #5
[ID=t03] Thread (should have ctx id=t03) - cycle #6
[ID=f03] Thread *** thread test done

As you can see, in 2.2.0+ all of the fibers' log messages have a MDC['id'] value of f003, which is the most-recently created fiber id.

Unfortunately, this means I'm stuck on logging 2.1.0, or maintaining a fork which reverts #162. I'm happy to submit a PR to revert it, but I'm concerned that it may have actually been fixing something. Any thoughts?

[marknuzz]

From the description of #162 it seems it was intended to preserve originally intended behavior. It should be possible to implement fiber contexts for MDC without affecting the original MDC feature. Perhaps a configuration option to be set to something other than default, or to have a different MDC class altogether.

I'm not sure if this project is maintained anymore but I vote that this is a good idea in principle. @uberjay