Nested Diagnostic Context, log4cpp and Boost asio
In this article I want to show how you can use NDC in asynchronous operations using the example of log4cpp and boost.asio
Nested Diagnostic Context (NDC) - the context that is added to the log. This context can be used to further filter the log file. This is especially useful if several operations are performed, and these operations are interconnected, for example: sampling data from the database, processing, packing into a message, sending a message over the network to the client, etc. ... If there are many such operations and they occur in parallel (or asynchronously ), then the log is sometimes hard to restore the sequence of operations. This is what NDC is used for: we first create a unique (pseudo) identifier, and then we tag each logging operation in our chain with this identifier.
In theory, everything is fine: we generate a unique ID and transfer it to the logger, but in practice there are several problems:
')
The example implements a client and server that exchange messages.
The principle of the server:
Similarly, the client works:
In this example, I specifically made an arbitrary timeout to show how NDC is handled in asynchronous operations.
Also in the example, a primitive connection control management mechanism is implemented (for a correct shutdown, as well as for the correct generation of NDC). In principle, you can tell in detail about the client and server implementation itself, but this is beyond the scope of this article.
If we run the examples with the parameter simple, then we will see on the screen lines like this (for the client):
All operations are performed asynchronously, so in the log we will see first a bunch of read operations, then a bunch of start timeout operations, and then a bunch of write operations. Moreover, since the timeouts are different for us, then the operations will go in a different order.
First we enable NDC support in log4cpp. For this we use the class PatternLayout , using the setConversionPattern method , we generate the information visible to us. The % x parameter is responsible for the output of the NDC (see consts :: ndcLayoutPattern in the common.h file)
The following idea comes to mind: since asio accepts any CompletionHandler (which satisfies the signature ), we can make a wrapper over our CompletionHandler of the following form:
Naturally, we have to wrap func and ndc into another Handler, for example, using boost :: bind, or our function
With this code, we install the NDC before executing our Handler and remove it after executing.
A more canonical version, which is offered by the asio library - using the Handler Invocation mechanism
This mechanism allows you to write your function to perform (invoke) Handler.
In principle, for our needs, both options are about the same, but the version with the handler invocation is more flexible, allowing other possibilities to be realized, for example, deferred execution, priority execution
By default, this function is defined in boost / asio / handler_invoke_hook.hpp as follows:
This is a function that takes a variable number of arguments (but uses only the first argument). It is known that when searching for a function to call, a function with a variable number of arguments has the lowest priority, therefore such an implementation will be substituted if no other implementations are specified.
It is used in boost / asio / detail / handler_invoke_helpers.hpp approximately as follows (threw out macros):
In order for the function we need to be called, it is necessary that it be higher than the priority when choosing, and it can take two parameters, the first parameter is the Handler itself, and the second parameter is a certain context in which our Handler will be executed. In our case, function and context are the same (roughly speaking, asio takes a Handler and uses it both as a function and as a context). Thus, our task is to write a special kind of CompletionHandler and the function asio_handler_invoke
Let's start with the implementation of Handler:
Asio requires our Handler to satisfy the requirements, so it contains an implementation of the () operators.
This template is essentially a regular wrapper over a previously designed Handler, the only difference is that it also stores the NDC, which we will have to set before execution and removed after.
In order to use this Handler , we need to define the asio_handler_invoke function with this signature:
As we can see, the implementation is trivial: we install the NDC and call our Handler, it's simple.
Now we need to force asio to call exactly our function, because the usual Handler will still be called using the old function asio_handler_invoke .
Consider an example of starting an asynchronous read:
Here we create a Handler using boost :: bind. To set our context, we wrap the created Handler into our NdcDecorator using the decorate function:
As we see, the change is not significant - namely, the call of another function, but this function creates the context we need and sets the NDC:
The implementation is also quite trivial: the second parameter is set by the default value - equal to the current NDC value. The current value of the NDC can be set earlier (in our example, this happens immediately after the connection is created - when the first asynchronous operation is started).
Now we start with the ndc (server) parameter:
In the server log, we see that all operations are really mixed up, but now we can see it. Moreover, we can use, for example, grep to filter the operations we need:
References:
Nested Diagnostic Context (NDC) - the context that is added to the log. This context can be used to further filter the log file. This is especially useful if several operations are performed, and these operations are interconnected, for example: sampling data from the database, processing, packing into a message, sending a message over the network to the client, etc. ... If there are many such operations and they occur in parallel (or asynchronously ), then the log is sometimes hard to restore the sequence of operations. This is what NDC is used for: we first create a unique (pseudo) identifier, and then we tag each logging operation in our chain with this identifier.
In theory, everything is fine: we generate a unique ID and transfer it to the logger, but in practice there are several problems:
- The NDC implementation in the log4cpp library is based on the Thread Local Storage (Thread Specific Ptr) mechanism, so the NDC is stored for only one thread. Accordingly, the question arises of the transfer of NDC between threads.
- The following problem also emerges from the first item: asynchronous operations, for example, in boost :: asio :: io_service. Since asio allows you to perform many asynchronous operations in one (or several) threads, due to the peculiarities of log4cpp, we will not be able to see the correct NDC in the log. We need a special mechanism that will ensure the correctness of the NDC in asio asynchronous operations
')
Preparing to start
- CMake-2.8 as a build system
- boost-1.49 from the debian wheezy repository
- log4cpp - logging library
- gcc-4.7.1 with C ++ 11 support included (used by Variadic templates)
- The source code is on GitHub in the asio_log4cpp subdirectory .
Brief description of the example
The example implements a client and server that exchange messages.
The principle of the server:
- The server is waiting for a connection from any address on port 12345
- after connection, it generates an arbitrary number in the range from 0 to 1000 (for generation, the library is used boost.random, as a generator - the Mersenne Vortex )
- Sends the generated number to the client.
- Starts an asynchronous timer for the specified number of milliseconds.
- After the timer has run, it starts an asynchronous read, receives a message from the client, and terminates the session
Similarly, the client works:
- Runs 100 asynchronous connections to the address 127.0.0.1:12345
- after connecting, it reads a message from the server that contains a timeout
- Starts an asynchronous timer for the specified number of milliseconds.
- After the timer has run, it starts an asynchronous recording, sends a farewell message to the server.
In this example, I specifically made an arbitrary timeout to show how NDC is handled in asynchronous operations.
Also in the example, a primitive connection control management mechanism is implemented (for a correct shutdown, as well as for the correct generation of NDC). In principle, you can tell in detail about the client and server implementation itself, but this is beyond the scope of this article.
We start the client and the server without NDC
If we run the examples with the parameter simple, then we will see on the screen lines like this (for the client):
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 All operations are performed asynchronously, so in the log we will see first a bunch of read operations, then a bunch of start timeout operations, and then a bunch of write operations. Moreover, since the timeouts are different for us, then the operations will go in a different order.
Implementation details
First we enable NDC support in log4cpp. For this we use the class PatternLayout , using the setConversionPattern method , we generate the information visible to us. The % x parameter is responsible for the output of the NDC (see consts :: ndcLayoutPattern in the common.h file)
Option 1
The following idea comes to mind: since asio accepts any CompletionHandler (which satisfies the signature ), we can make a wrapper over our CompletionHandler of the following form:
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(); } Naturally, we have to wrap func and ndc into another Handler, for example, using boost :: bind, or our function
With this code, we install the NDC before executing our Handler and remove it after executing.
We are obliged to reset the NDC after the completion of our Handler, otherwise we may see messages with incorrect NDC in the logs.
Option # 2
A more canonical version, which is offered by the asio library - using the Handler Invocation mechanism
This mechanism allows you to write your function to perform (invoke) Handler.
In principle, for our needs, both options are about the same, but the version with the handler invocation is more flexible, allowing other possibilities to be realized, for example, deferred execution, priority execution
By default, this function is defined in boost / asio / handler_invoke_hook.hpp as follows:
template <typename Function> inline void asio_handler_invoke(Function function, ...) { function(); } This is a function that takes a variable number of arguments (but uses only the first argument). It is known that when searching for a function to call, a function with a variable number of arguments has the lowest priority, therefore such an implementation will be substituted if no other implementations are specified.
It is used in boost / asio / detail / handler_invoke_helpers.hpp approximately as follows (threw out macros):
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)); } In order for the function we need to be called, it is necessary that it be higher than the priority when choosing, and it can take two parameters, the first parameter is the Handler itself, and the second parameter is a certain context in which our Handler will be executed. In our case, function and context are the same (roughly speaking, asio takes a Handler and uses it both as a function and as a context). Thus, our task is to write a special kind of CompletionHandler and the function asio_handler_invoke
Let's start with the implementation of Handler:
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 requires our Handler to satisfy the requirements, so it contains an implementation of the () operators.
This template is essentially a regular wrapper over a previously designed Handler, the only difference is that it also stores the NDC, which we will have to set before execution and removed after.
In order to use this Handler , we need to define the asio_handler_invoke function with this signature:
template <typename FunctionT, typename HandlerT> void asio_handler_invoke(FunctionT func, NdcDecorator<HandlerT> * ndcHandler) { NdcHolder ndcHolder(ndcHandler->ndc()); func(); } As we can see, the implementation is trivial: we install the NDC and call our Handler, it's simple.
Now we need to force asio to call exactly our function, because the usual Handler will still be called using the old function asio_handler_invoke .
Consider an example of starting an asynchronous read:
mSocket->async_read_some(to_asio_buffer(mInputMsg), boost::bind(&server_connection::onRead, shared_from(this), placeholders::error, placeholders::bytes_transferred)); Here we create a Handler using boost :: bind. To set our context, we wrap the created Handler into our NdcDecorator using the decorate function:
mSocket->async_read_some(to_asio_buffer(mInputMsg), decorate( boost::bind(&server_connection::onRead, shared_from(this), placeholders::error, placeholders::bytes_transferred))); As we see, the change is not significant - namely, the call of another function, but this function creates the context we need and sets the NDC:
template <typename HandlerT> NdcDecorator<HandlerT> decorate(HandlerT handler, const std::string & ndc = log4cpp::NDC::get()) { return NdcDecorator<HandlerT>(handler, ndc); } The implementation is also quite trivial: the second parameter is set by the default value - equal to the current NDC value. The current value of the NDC can be set earlier (in our example, this happens immediately after the connection is created - when the first asynchronous operation is started).
We start the client and the server with NDC
Now we start with the ndc (server) parameter:
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> In the server log, we see that all operations are really mixed up, but now we can see it. Moreover, we can use, for example, grep to filter the operations we need:
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> References:
- Asio samples - I thought it necessary to add it, since it was this article that prompted me to solve this problem.
Source: https://habr.com/ru/post/157353/
All Articles