Nested Diagnostic Context, log4cpp и Boost asio

в 14:54, , рубрики: c++, Программирование, метки:

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

Автор: prograholic

Источник

* - обязательные к заполнению поля

Главная   |  Архив новостей  |   Android  |   Google  |   Apple  |   Microsoft  |   Информационная безопасность  |   Веб – разработка
Публикации RSS  |  Комментарии RSS
https://ajax.googleapis.com/ajax/libs/jquery/3.4.1/jquery.min.js