2

シーンの設定

デフォルトの 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、リクエスト ID などです。

問題

問題は、ログ エントリが著しく間違っていることです。負荷がかかると、1 人のユーザーの ID が、まったく別のユーザーが API に対して行ったであろう要求と混ざり合っていることが常にわかります。

Log4r MDC はスレッドセーフで、Rails 4 はデフォルトでスレッドセーフであると言われていますが、明らかに何かが正しくありません。Rack が問題なのかどうかも疑問に思っていましたが、Rails のスレッド セーフ性 (完全に一言で言えば、Rails ではRack::Lockを削除するのに十分な自信があるようです) と思われますが、それも正しくないようです。

私は何が欠けていますか？すべての情報はスレッドセーフであると言っているようですが、そうであるとは確信していません。

フードの下

  • レール 4.1.10
  • Log4r 1.1.10
  • 乗客 4.0.59

参考文献

4

1 に答える 1

0

いくつかの調査と実験の後、これはスレッドセーフの問題ではないことが判明しました。それはむしろ、ぶらぶらしている別のリクエストからの古いデータの問題です。問題を理解するには、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) }

おっとっと。

于 2016-05-02T17:04:41.193 に答える