суббота, 12 марта 2011 г.

[prog.idiotic] Как не нужно логировать двоичные данные

Сегодняшний выходной был убит необходимостью разбирательства с жалобами важного клиента. Суть в том, что время от времени они вычитывают из TCP/IP сокета блок данных, который не могут разобрать. Соответственно к нам претензии – почему мусор в канал записываем. И в доказательство приводится фрагмент лога, якобы содержащий этот проблемный блок.

Все бы ничего, если бы не следующие особенности:

  • чтобы сформировать строку для лога используется MFC-шный аналог sprintf, что-то вроде: logLine.format(“size: %d, buf=[%s]”, len, buf). Где buf – это обычный C-шный массив с терминирующим 0-символом. Но, поскольку данные бинарные и могут иметь внутри 0-символы, то перед обращением к format содержимое buf модифицируется – все встретившиеся нули (кроме терминатора) заменяются пробелами;
  • блок бинарных данных помещается в лог-файл как есть, без каких-либо преобразований (например, хотя бы escape-нга непечатаемых символов);
  • лог-файл открывается как обычный текстовый файл, а поскольку работа идет под Windows, то символы \n (0x0a) при записи в него автоматически заменяются на \r\n (0x0d 0x0a). И, опять же, поскольку данные бинарные и не escape-тся, то находящиеся в них байты 0x0a превращаются в 0x0d 0x0a.

В результате с чем приходится разбираться – вместо нулей в блоке находятся пробелы, вместо 0x0a – 0x0d 0x0a. Повезло еще, что характер передаваемых данных таков, что пробелы в них редкость, поэтому можно было почти безопасно делать обратные преобразования.

В общем, не нужно так делать. Есть несколько намного более удобных для последующего разбирательства способов – сохранение проблемных фрагментов в отдельных бинарных файлах, сохранение в лог-файлах с применением escape-нга спецсимволов или же преобразованных к шестнадцатиричному представлению. Все лучше, чем гадать, стоит ли воспринимать 0x20 как 0x00 или как 0x20 :/

PS. Кстати, если у вас есть бинарный файл, который вы хотите пребразовать в текст с шестнадцатиричным представлением каждого байта исходного файла и не хочется ничего программировать, то можно воспользоваться Unix-овой утилитой od:

od –An –t x1 binary.dat > binary.txt

Под Windows ее можно найти в составе cygwin или в UnxUtils.

6 комментариев:

Unknown комментирует...

Да, не думал что такие уникумы еще встречаются, видимо жизнь меня разбаловала.
BTW, может я не правильно понял. Но вообще, чтобы не засорять логи, для подобного обычно используют специальные файлы протоколов обмена. Бинарные или заэскейпленные данные, с указанием направления и отметками времени.

eao197 комментирует...

@Easy:

>Да, не думал что такие уникумы еще встречаются, видимо жизнь меня разбаловала.

Это еще далеко не самый плохой вариант.

>Но вообще, чтобы не засорять логи, для подобного обычно используют специальные файлы протоколов обмена.

По хорошему, при возникновении подозрений на хождение битых данных по сети нужно использовать специальные инструменты для снятия трафика на обоих сторонах -- вроде Wireshark-а. Но это когда есть подозрения. А так, если программа обнаруживает плохой блок данных, то можно его и в лог записать. Важно только сделать это нормально.

Unknown комментирует...

А, плохой блок. Да, конечно в лог.

В моем случае битые данные более частая проблема, из-за сопряжения сети и последовательных портов (через которые много разных специфичных железок подключается). Во всяком случае во время настройки, тестирования и введения в эксплуатацию.
Когда клиентов много, и у каждого много железок работает одновременно, тогда интегрированное в систему собственное протоколирование значительно упрощает поддержку.

eao197 комментирует...

@Easy:

>тогда интегрированное в систему собственное протоколирование значительно упрощает поддержку.

Это точно. И в таких случаях лог-файлы, определенно, будут не лучшим вариантом. Лучше, имхо, чтобы сам софт мог вести отдельные подробные dump-файлы.

Unknown комментирует...

@Евгений

Не отбражать фрагменты битых посылок в логах, тоже нельзя.

Но отдельно от логов -- протоколы обмена (дата и время с милисекундами, и направление данных любой посылки).
Включается/выключается опцией конфига, которая на лету подхватывается системой.
Для каждой железки, свой файл протоколов, который еще и ротейтится по датам.

Наличие таких заескейпленных данных вообще упрощает жизнь.
Они легко читаются, просто картина маслом. Без них, по одним логам, я уже и проблем не выявляю: только логи и протоколы дают полную картину.

Бывает легко и удобно потом в REPL какого-нибудь скриптового языка их обрабатывать. Т.е. не весь файл протокола, а отдельные пакеты (фрагменты пакетов), в которых нужно выявлять суть проблемы.

А можно небольшой утилитой "проиграть" сценарий (или несколько) заново, со стоящим рядом сервером.

eao197 комментирует...

@Easy:

не могу не согласиться со всем вышесказанным.