ネストされた診断コンテキスト、log4cppおよびBoost asio

この記事では、log4cppとboost.asioの例を使用して、非同期操作でNDCを使用する方法を示します。



ネストされた診断コンテキスト(NDC)-ログに追加されるコンテキスト。 このコンテキストを使用して、ログファイルをさらにフィルタリングできます。 これは、複数の操作が実行され、これらの操作が相互接続されている場合に特に役立ちます。たとえば、データベースからのデータの取得、処理、メッセージへのパッキング、ネットワークを介したクライアントへのメッセージ送信など。 )、ログによっては、操作のシーケンスを復元することが困難な場合があります。 これがNDCの使用目的です。最初に一意の(擬似)識別子を作成し、次にこの識別子でチェーン内の各ログ操作をマークします。



理論的には、すべて問題ありません。一意のIDを生成してロガーに渡しますが、実際にはいくつかの問題が発生します。









準備を始める






例の簡単な説明


この例では、メッセージを交換するクライアントとサーバーを実装します



サーバー操作の原則:





クライアントは同じように機能します。





この例では、非同期操作でNDCがどのように処理されるかを示すために、特に任意のタイムアウトを作成しました。



この例では、接続を管理するためのプリミティブ制御メカニズムも実装しています(正しい停止のため、およびNDCの正しい生成のため)。 原則として、クライアントとサーバーの実際の実装について詳しく話すことができますが、これはこの記事の範囲外です。



NDCなしでクライアントとサーバーを起動します


simpleパラメーターを使用して例を実行すると、画面上におよそ次の内容の行が表示されます(クライアント用):

17 INFO connection status: system:0, message: Success 17 INFO starting asynchronous reading... ... 33 INFO answer from server readed: [552] 33 INFO starting asynchronous timeout 00:00:00.552000 ... ... 141 INFO timer status: system:0, message: Success 141 INFO starting asynchronous write... 141 INFO write status: system:0, message: Success, bytes written: 8
      
      





すべての操作は非同期で実行されるため、ログには、最初に一連の読み取り操作、次に一連の開始タイムアウト操作、次に一連の書き込み操作が表示されます。 さらに、タイムアウトは異なるため、操作の順序は異なります。



実装の詳細


まず、log4cppでNDCサポートを有効にします。 これを行うには、 setConversionPatternメソッドを使用してPatternLayoutクラスを使用し、表示可能な情報を生成します。 %xパラメーターは、NDCの出力を担当します(common.hファイルのconsts :: ndcLayoutPatternを参照)



オプション#1


次のアイデアが思い浮かびます。asioはCompletionHandler(署名を満たす受け入れるため、CompletionHandlerを次のようにラップできます。

 struct NdcHolder : private boost::noncopyable { NdcHolder(const std::string & ndc) { log4cpp::NDC::push(ndc); } ~NdcHolder() { log4cpp::NDC::pop(); } }; //... template <typename Oldhandler> void newHandler(OldHandler func, const std::string & ndc) { NdcHolder ndcHolder(ndc); func(); }
      
      





当然、たとえばboost :: bindまたは関数を使用して、funcとndcを別のハンドラーでラップする必要があります



このコードを使用して、ハンドラーを実行する前にNDCをインストールし、実行後に削除します。

ハンドラーの完了後にNDCをリセットする必要があります。そうしないと、ログに無効なNDCのメッセージが表示される場合があります




オプション#2


asioライブラリが提供するより標準的なバージョンは、 Handler Invocationメカニズムの使用です。

このメカニズムにより、ハンドラーを実行(呼び出し)する独自の関数を作成できます。



原則として、私たちのニーズのために両方のオプションはほぼ同じですが、ハンドラー呼び出しのオプションはより柔軟であり、遅延実行、 優先実行などの他の機能を実装できます



デフォルトでは、この関数はboost / asio / handler_invoke_hook.hppで次のように定義されています。

 template <typename Function> inline void asio_handler_invoke(Function function, ...) { function(); }
      
      





これは、可変数の引数を取る関数です(ただし、最初の引数のみを使用します)。 呼び出す関数を検索するとき、可変数の引数を持つ関数の優先順位が最も低いことが知られているため、他の実装が指定されていない場合、そのような実装は置き換えられます。



boost / asio / detail / handler_invoke_helpers.hppで次のように使用されます(マクロを投げた):

 template <typename Function, typename Context> inline void invoke(Function& function, Context& context) { using boost::asio::asio_handler_invoke; asio_handler_invoke(function, boost::addressof(context)); }
      
      







必要な関数を呼び出すためには、選択時に優先順位を高くし、2つのパラメーターを受け入れることができる必要があります。最初のパラメーターはハンドラー自体であり、2番目のパラメーターはハンドラーが実行される特定のコンテキストです。 この場合、 関数コンテキストは同じです(大まかに言うと、asioはHandlerを取り、それを関数とコンテキストの両方として使用します)。 したがって、私たちのタスクは、特別な種類のCompletionHandlerと関数asio_handler_invokeを記述することです。



ハンドラーの実装から始めましょう。

 template <typename HandlerT> class NdcDecorator { public: explicit NdcDecorator(HandlerT handler, const std::string & ndc) : mHandler(handler), mNdc(ndc) {} void operator()() { mHandler(); } template <typename Arg1> void operator() (Arg1 arg1) { mHandler(arg1); } template <typename Arg1, typename Arg2> void operator() (Arg1 arg1, Arg2 arg2) { mHandler(arg1, arg2); } const std::string & ndc() const { return mNdc; } private: HandlerT mHandler; std::string mNdc; };
      
      





Asioでは、ハンドラーが要件を満たす必要があるため、operator()の実装があります。



このテンプレートは、基本的に以前に設計されたハンドラーの通常のラッパーです。唯一の違いは、実行前に設定して削除後にNDCを追加で保存することです。



このHandlerを使用するには、このシグネチャでasio_handler_invoke関数を定義する必要があります。

 template <typename FunctionT, typename HandlerT> void asio_handler_invoke(FunctionT func, NdcDecorator<HandlerT> * ndcHandler) { NdcHolder ndcHolder(ndcHandler->ndc()); func(); }
      
      





ご覧のとおり、実装は簡単です。NDCをインストールし、Handlerを呼び出します。すべてが簡単です。



ここで、通常のHandlerが古いasio_handler_invoke関数を使用して呼び出されるため、asioに関数を呼び出させる必要があります。

非同期読み取りを開始する例を考えてみましょう。

 mSocket->async_read_some(to_asio_buffer(mInputMsg), boost::bind(&server_connection::onRead, shared_from(this), placeholders::error, placeholders::bytes_transferred));
      
      





ここで、boost :: bindを使用してハンドラーを作成します。 コンテキストを設定するには、decorate関数を使用して、作成したHandlerをNdcDecoratorにラップします。

 mSocket->async_read_some(to_asio_buffer(mInputMsg), decorate( boost::bind(&server_connection::onRead, shared_from(this), placeholders::error, placeholders::bytes_transferred)));
      
      





ご覧のとおり、変更は重要ではありません。つまり、別の関数を呼び出しますが、この関数は必要なコンテキストを作成し、NDCを設定します。

 template <typename HandlerT> NdcDecorator<HandlerT> decorate(HandlerT handler, const std::string & ndc = log4cpp::NDC::get()) { return NdcDecorator<HandlerT>(handler, ndc); }
      
      





実装も非常に簡単です。2番目のパラメーターはデフォルトで設定されます-NDCの現在の値に等しくなります。 現在のNDC値は以前に設定できます(この例では、これは接続が作成された直後に-最初の非同期操作が開始されたときに発生します)。



NDCでクライアントとサーバーを起動します


ndc(サーバー)パラメーターから開始します。

 9179 INFO starting asynchronous write... <SID=1> 9179 INFO starting asynchronous accept... 9179 INFO write status: system:0, message: Success, bytes written: 4 <SID=1> 9179 INFO starting asynchronous timeout 00:00:00.765000 ... <SID=1> ... 9595 INFO read status: system:0, message: Success <SID=3> 9595 INFO answer from client readed: [GOODBYE] <SID=3> 9595 INFO timer status: system:0, message: Success <SID=65> 9595 INFO starting asynchronous read... <SID=65> 9598 INFO read status: system:0, message: Success <SID=12> 9598 INFO answer from client readed: [GOODBYE] <SID=12>
      
      







サーバーログでは、すべての操作が実際に混同されていることがわかりますが、今では見ることができます。 さらに、必要な操作を除外するために、たとえばgrepを使用できます。

 cat ndc_server.log | grep "<SID=50>" > 50.log
      
      





 9199 INFO starting asynchronous write... <SID=50> 9199 INFO write status: system:0, message: Success, bytes written: 4 <SID=50> 9199 INFO starting asynchronous timeout 00:00:00.879000 ... <SID=50> 10079 INFO timer status: system:0, message: Success <SID=50> 10079 INFO starting asynchronous read... <SID=50> 10100 INFO read status: system:0, message: Success <SID=50> 10100 INFO answer from client readed: [GOODBYE] <SID=50>
      
      







使用された文献のリスト:




All Articles