- PVSM.RU - https://www.pvsm.ru -
В данной статье я хочу показать, как можно использовать NDC в асинхронных операциях на примере log4cpp и boost.asio
Nested Diagnostic Context (NDC) — контекст, который добавляется в лог. Этот контекст может использоваться для дальнейшей фильтрации лог файла. Особенно это полезно, если производится несколько операций, и эти операции связаны между собой, например: выборка данных из БД, обработка, упаковка в сообщение, передача сообщения по сети клиенту и т.д… Если таких операций много и происходят они параллельно (или асинхронно), то по логу иногда бывает тяжело восстановить последовательность операций. Для этого и используется NDC: вначале мы создаем уникальный(псевдо) идентификатор, и затем помечаем каждую операцию логгирования в нашей цепочке этим идентификатором.
В теории все хорошо: генерируем уникальный ID и передаем его в логгер, однако на практике возникает несколько проблем:
В примере реализован клиент и сервер, которые обмениваются сообщениями
Принцип работы сервера:
Аналогичным образом работает клиент:
В данном примере я специально сделал произвольный таймаут, чтобы показать как обрабатываются 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
Все операции выполняются асинхронно, поэтому в логе мы увидим сначала кучу операций чтения, потом кучу операций старта таймаута, и затем кучу операций записи. Причем, так как таймауты у нас различны, то и операции будут идти в разном порядке.
Сначала включаем поддержку NDC в log4cpp. Для этого используем класс PatternLayout, с помощью метода setConversionPattern мы формируем видимую нам информацию. За вывод NDC отвечает параметр %x (смотри consts::ndcLayoutPattern в файле common.h)
На ум приходит следующая идея: так как asio принимает любой CompletionHandler (который удовлетворяет сигнатуре [3]), то мы можем сделать обертку над нашими 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();
}
Естественно, мы должны завернуть func и ndc в еще один Handler, например, с помощью boost::bind, или своей функции
С помощью данного кода мы устанавливаем NDC перед выполнением нашего Handler и убираем его после выполнения.
Мы обязаны сбросить NDC после завершения работы нашего Handler, иначе мы можем увидеть в логах сообщения с неверным NDC
Более каноничный вариант, который предлагается библиотекой asio — использование механизма Handler Invocation [4]
Данный механизм позволяет написать свою функцию для выполнения (invoke) Handler.
В принципе, для наших нужд оба варианта примерно одинаковы, но вариант с handler invocation более гибкий, позволяет реализовать другие возможности, например, отложенное исполнение, исполнение по приоритету [5]
По умолчанию данная функция определена в 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));
}
Для того чтобы вызывалась нужная нам функция, необходимо чтобы она была выше приоритетом при выборе, и могла принимать два параметра, первый параметр — сам Handler, и второй параметр — некий контекст, в котором будет исполняться наш Handler. В нашем случае function и context совпадают (грубо говоря, asio берет Handler и использует его и как функцию, и как контекст). Таким образом, наша задача сводится к тому, чтобы написать специального вида CompletionHandler и функцию asio_handler_invoke
Начнем с реализации 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 требует, чтобы наш Handler удовлетворял требованиям, поэтому в нем присутствует реализация операторов ().
Данный шаблон по сути является обычной оберткой над ранее сконструированным Handler, единственное отличие — это то, что он дополнительно хранит 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, все просто.
Теперь нам необходимо заставить asio вызывать именно нашу функцию, потому что обычный Handler по-прежнему будет вызываться с помощью старой функции asio_handler_invoke.
Рассмотрим пример запуска асинхронного чтения:
mSocket->async_read_some(to_asio_buffer(mInputMsg),
boost::bind(&server_connection::onRead,
shared_from(this),
placeholders::error,
placeholders::bytes_transferred));
Здесь мы создаем Handler с помощью boost::bind. Для того чтобы задать наш контекст — обернем созданный Handler в наш NdcDecorator с помощью функции decorate:
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);
}
Реализация получается тоже достаточно тривиальна: второй параметр задан значением по умолчанию — равным текущему значению 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>
Список использованной литературы:
Автор: prograholic
Источник [7]
Сайт-источник PVSM.RU: https://www.pvsm.ru
Путь до страницы источника: https://www.pvsm.ru/programmirovanie/18891
Ссылки в тексте:
[1] на GitHub: https://github.com/prograholic/blog
[2] Вихрь Мерсенна: http://ru.wikipedia.org/wiki/%D0%92%D0%B8%D1%85%D1%80%D1%8C_%D0%9C%D0%B5%D1%80%D1%81%D0%B5%D0%BD%D0%BD%D0%B0
[3] CompletionHandler (который удовлетворяет сигнатуре: http://www.boost.org/doc/libs/1_51_0/doc/html/boost_asio/reference/CompletionHandler.html
[4] Handler Invocation: http://www.boost.org/doc/libs/1_51_0/doc/html/boost_asio/reference/asio_handler_invoke.html
[5] исполнение по приоритету: http://www.boost.org/doc/libs/1_51_0/doc/html/boost_asio/example/invocation/prioritised_handlers.cpp
[6] Asio samples: http://asio-samples.blogspot.ru/2011/06/design-journeys-with-asio.html
[7] Источник: http://habrahabr.ru/post/157353/
Нажмите здесь для печати.