[prog] Вроде бы простая штука – напечатать timestamp в сообщении в log-файле

Вроде бы простая штука – при записи сообщения в log, получить в строке log-файла нормальный timestamp сообщения. Однако, в некоторых реализациях, все это оказывается очень интересным и неожиданно сложным делом. Например, в упомянутой вчера мной библиотеке ACE.

Нормальные библиотеки для логирования должны состоять из двух составляющих: front-end-а (тот API, который пользователь дергает для отправки сообщений в лог) и back-end-а (не видимая обычно пользователю часть, которая помещает сообщения в файлы, в EventLog, в syslog и еще куда-нибудь). Аналогичным образом устроено логирование и в библиотеке ACE. Front-end-ом служат макросы ACE_ERROR, ACE_DEBUG и т.д. В качестве back-end-ов используются наследники класса ACE_Log_Msg_Backend.

Логирование в ACE выполняется следующим образом:

• при обращении к макросу ACE_ERROR/ACE_DEBUG… управление передается в ACE_Log_Msg::log(). Нужно сказать, что сообщения для логирования в ACE оформляются так же, как и вывод при помощи функций printf: есть форматная строка и есть список параметров. Так вот, в методе ACE_Log_Msg::log() сначала строится текст результирующего сообщения посредством обработки форматной строки и параметров. А уже потом…
• сформированное в ACE_Log_Msg::log() сообщение попадает в ACE_Log_Msg_Backend::log(). Где готовое сообщение без каких-либо преобразований записывается туда, куда положено.

Теперь можно вернуться к timestamp-у. Сам ACE не добавляет timestamp к помещаемому в лог сообщению. Если пользователь хочет видеть timestamp в своих сообщениях (интересно, а в каких случаях timestamp видеть не нужно?), то должен добавить в форматную строку своего сообщения ключ %D или %T. И тут-то начинается самое интересное – как и в какой момент этот timestamp появляется. Для этого придется заглянуть в потроха ACE_Log_Msg.

В начале метода ACE_Log_Msg::log() берется текущее время и сохраняется в объекте ACE_Log_Record (туда же затем будет помещено и результирующее сообщение, а затем этот объект пойдет в ACE_Log_Msg_Backend::log). Отлично, вроде бы, взяли время, зафиксировали. Тут есть один тонкий момент – зачем в ACE_Log_Record вообще метка времени, но к этому я вернусь чуть позже.

Далее ACE_Log_Msg::log() производит разбор аргументов форматной строки. И, внимание, если находит ключ %D или %T, то снова берет текущее время! Зачем, спрашивается? Ведь у нас уже есть сохраненная в ACE_Log_Record метка.

Ответа на этот вопрос я не знаю. Одно из предположений такое: в форматной строке можно указать ключ %r, который говорит, что пользователь в качестве аргумента передает указатель на функцию (вроде бы с прототипом void(void)) и эту функцию нужно вызвать и ACE_Log_Msg::log вызывает эту функцию по указателю прямо посреди разбора форматной строки. Зачем такое нужно я не представляю. Но зато это может приводить к следующим эффектам: указываем форматную строку “%D%r%D”, даем указатель на функцию, которая работает 5 секунд, и получаем строку в которой первый timestamp на 5 секунд меньше второго. Что, собственно, говоря, правильно.

Теперь можно вернуться к вопросу о том, зачем в ACE_Log_Record хранится метка времени. Предполагаю, что она там нужна для того, чтобы back-end мог вести суточные/часовые/пятнадцатиминутные файлы. Приходит в back-end очередной ACE_Log_Record, смотрит back-end на метку времени и решает, нужно ли менять log-файл или нет.

Но тут вот какая штука получается. Допустим, back-end ведет суточные логи. В 23:59:59.990 приложение обращается к ACE_Log_Msg. В ACE_Log_Record попадает именно это время. Но затем, по мере разбора форматной строки и обработки ключей %D, %T время уже изменилось и стало, допустим, 00:00:00.050. Именно это значение будет сохранено в строке-сообщении. Далее ACE_Log_Record передается back-end-у, тот смотрит на метку времени, видит там 23:59:59.990 и решает записать сообщение в старый суточный файл. Но в самом файле окажется строка с меткой времени 00:00:00.050. Вероятность этого, конечно, не сильно большая. Но вполне реальная (особенно для приложений, обрабатывающих сотни транзакций в секунду).

К чему я все это веду? А к тому, если front-end системы логирования занимается форматированием сообщения и делает это без синхронизации с другими потоками, то может происходить интересная штука. Нить A обращается к logging front-end, front-end успевает получить метку времени, после чего нить A снимают с процессора. Управление переходит к нити B, которая так же обращается к logging front-end. Но для нити B успевает выполниться вся цепочка действий (взятие текущего времени, форматирование сообщения, запись его через back-end). Т.о. запись от нити B попадет в log раньше записи нити A. Но ведь у нити B метка времени окажется большей, чем у нити A. Т.е. может получиться, что в логе сначала будет идти запись, например, от 15:17:59.890, а следом – запись от 15:17:59.770.

Посему я для себя делаю следующие выводы (на случай, если придется изобретать собственную систему логирования):

• пользователь не должен управлять взятием/не взятием метки времени для сообщений лога. По крайней мере для отдельных сообщений. За метки времени должна отвечать подсистема логирования;
• подсистеме логирования не нужно поддерживать такие извраты, как вызов произвольной функции по указателю на нее;
• подсистема логирования должна добавлять к сообщению метку времени и отправлять сообщение в back-end под общим mutex-ом, чтобы обеспечить строгую сериализацию всех сообщений.