Действительно ли Log4r является потокобезопасным в приложении Rails 4?

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

Стремясь сделать ведение журнала 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, но безопасность потоков — всего лишь слово, верно? — в Rails кажется достаточно уверенным, чтобы remove Rack::Lock, то это тоже не кажется правильным.

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

Под капотом

Рельсы 4.1.10
Лог4р 1.1.10
Пассажирский 4.0.59

использованная литература

Devin Mitchell 29.04.2016 источник

Ответы (1)

arrow_upward
0
arrow_downward

После некоторых исследований и экспериментов оказалось, что это вообще не проблема потокобезопасности; это скорее проблема устаревших данных из другого запроса. Чтобы понять проблему, вы должны понять, как хранится материал 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) }

Упс.

Devin Mitchell 02.05.2016