Является ли Log4r на самом деле Threadsafe в приложении Rails 4?

Question

Настройка сцены

Стремясь сделать ведение журнала Rails по умолчанию более полезным в производственной среде, я использовал преимущества Log4r и его диагностического контекста, в частности MDC. В дополнение к журналам, которые выходят из самого приложения Rails, я также вставляю часть своего собственного промежуточного программного обеспечения, чтобы я мог получать согласованное ведение журнала даже в промежуточном программном обеспечении Rack.

Например, как только я получаю доступ к вошедшему в систему пользователю через Warden, я добавляю запись MDC, необходимую для этой части.

def call(env)
  user = env['warden'].user
  user_context = user ? user.to_log_format : 'indetermined'
  MDC.put :user, user_context

  @app.call(env)
end

Другими зарегистрированными вещами в промежуточном программном обеспечении Rack являются родительский PID, идентификатор запроса и т. Д.

Эта проблема

Проблема в том, что мои записи в журнале заметно неверны. Под нагрузкой я постоянно вижу, как идентичность одного пользователя смешивается с запросом, который совершенно другой пользователь направил бы в API, если запросы приходят достаточно близко друг к другу.

Мне сказали, что Log4r MDC является потокобезопасным, а Rails 4 по умолчанию безопасен для потоков, но, очевидно, что-то не так. Я также задавался вопросом, является ли проблема с Rack, но в Threads, как правило, верно понимается, что потокобезопасность в Rails достаточно уверена для удаления Rack:: Lock, тогда это тоже не кажется правильным.

Что мне не хватает? Кажется, что вся информация говорит о том, что она безопасна для потоков, но я не уверен, что это так.

Под капотом

• Рельсы 4.1.10
• Log4r 1.1.10
• Пассажир 4.0.59

Рекомендации

• http://www.rubydoc.info/github/colbygk/log4r/Log4r/MDC
• http://log4r.rubyforge.org/rdoc/log4r/rdoc/MDC.html
• https://cb.platan.us/multithreading-rails-4
• https://tenderlovemaking.com/2012/06/18/removing-config-threadsafe.html

Answer 1

После некоторых исследований и экспериментов выяснилось, что это вовсе не проблема безопасности потоков; это скорее проблема устаревших данных из другого запроса. Чтобы понять проблему, вы должны понять, как хранится материал Log4r MDC, чтобы понять, в чем проблема:

Куски MDC хранятся вместе с потоком, чтобы они были доступны для регистрации в течение всего запроса.

def self.put( a_key, a_value )
  self.check_thread_instance()
  Thread.current[MDCNAME][a_key] = a_value
end

Поэтому, когда поток полностью заканчивает обработку запроса, он получает другой запрос. К сожалению, похоже, что он все еще содержит детали из предыдущего запроса - ничего не было очищено. Таким образом, все эти старые, не связанные детали могут оказаться диагностическим контекстом для несвязанного запроса.

Решение состоит в том, чтобы гарантировать, что части MDC будут очищены, прежде чем вы начнете добавлять новый контекст в ваш новый запрос:

MDC.get_context.keys.each { |k| MDC.remove(k) }

К сожалению.