Nested Diagnostic Context (NDC) — контекст, который добавляется в лог. Этот контекст может использоваться для дальнейшей фильтрации лог файла. Особенно это полезно, если производится несколько операций, и эти операции связаны между собой, например: выборка данных из БД, обработка, упаковка в сообщение, передача сообщения по сети клиенту и т.д… Если таких операций много и происходят они параллельно (или асинхронно), то по логу иногда бывает тяжело восстановить последовательность операций. Для этого и используется NDC: вначале мы создаем уникальный(псевдо) идентификатор, и затем помечаем каждую операцию логгирования в нашей цепочке этим идентификатором.
В теории все хорошо: генерируем уникальный ID и передаем его в логгер, однако на практике возникает несколько проблем:
- Реализация NDC в библиотеке log4cpp основана на механизме Thread Local Storage (Thread Specific Ptr), таким образом NDC хранится только для одного потока. Соответственно встает вопрос передачи NDC между потоками
- Из первого пункта также вытекает следующая проблема: асинхронные операции, например в boost::asio::io_service. Так как asio позволяет в одном (или нескольких) потоках выполнять множество асинхронных операций, то из-за особенностей log4cpp мы не сможем увидеть в логе правильный NDC. Нужен специальный механизм, который обеспечит корректность NDC в асинхронных операциях asio
Подготовка к старту
- CMake-2.8 в качестве системы сборки
- boost-1.49 из репозитория debian wheezy
- log4cpp — библиотека логгирования
- gcc-4.7.1 с включенной поддержкой C++11 (использовались Variadic templates)
- Исходный код находится на GitHub в поддиректории asio_log4cpp
Краткое описание примера
В примере реализован клиент и сервер, которые обмениваются сообщениями
Принцип работы сервера:
- Сервер ожидает подключения с любого адреса на порту 12345
- после подключения он генерирует произвольное число в диапазоне от 0 до 1000 (для генерации используется библиотека boost.random, в качестве генератора — Вихрь Мерсенна)
- Отправляет сгенерированное число клиенту
- Запускает асинхронный таймер на указанное число миллисекунд
- После того как таймер отработал, запускает асинхронное чтение, получает сообщение от клиента и завершает сессию
Аналогичным образом работает клиент:
- Запускает 100 асинхронных коннектов на адрес 127.0.0.1:12345
- после подключения он вычитывает от сервера сообщение, в котором содержится таймаут
- Запускает асинхронный таймер на указанное число миллисекунд
- После того как таймер отработал, запускает асинхронную запись, послыает серверу прощальное сообщение.
В данном примере я специально сделал произвольный таймаут, чтобы показать как обрабатываются 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Все операции выполняются асинхронно, поэтому в логе мы увидим сначала кучу операций чтения, потом кучу операций старта таймаута, и затем кучу операций записи. Причем, так как таймауты у нас различны, то и операции будут идти в разном порядке.
Детали реализации
Сначала включаем поддержку NDC в log4cpp. Для этого используем класс PatternLayout, с помощью метода setConversionPattern мы формируем видимую нам информацию. За вывод NDC отвечает параметр %x (смотри consts::ndcLayoutPattern в файле common.h)
Вариант #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(); } Естественно, мы должны завернуть func и ndc в еще один Handler, например, с помощью boost::bind, или своей функции
С помощью данного кода мы устанавливаем NDC перед выполнением нашего Handler и убираем его после выполнения.
Мы обязаны сбросить NDC после завершения работы нашего Handler, иначе мы можем увидеть в логах сообщения с неверным NDC
Вариант #2
Более каноничный вариант, который предлагается библиотекой asio — использование механизма Handler Invocation
Данный механизм позволяет написать свою функцию для выполнения (invoke) Handler.
В принципе, для наших нужд оба варианта примерно одинаковы, но вариант с 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)); }Для того чтобы вызывалась нужная нам функция, необходимо чтобы она была выше приоритетом при выборе, и могла принимать два параметра, первый параметр — сам 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
Запускаем теперь с параметром 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>Список использованной литературы:
- Asio samples — посчитал нужным добавить, так как именно эта статья натолкнула меня на решение этой задачи
ссылка на оригинал статьи http://habrahabr.ru/post/157353/
Добавить комментарий