В данной статье я хочу показать, как можно использовать NDC в асинхронных операциях на примере log4cpp и boost.asio

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 — посчитал нужным добавить, так как именно эта статья натолкнула меня на решение этой задачи