Опасное логирование

Сейчас я постараюсь вас напугать :)
Упрощённо, функции логирования обычно выглядят следующим образом:

#include <stdio.h>

#ifdef _MSC_VER // workaround for MS VC
#define snprintf(b, bsz, f, ...)                \
        _snprintf_s(b, bsz, _TRUNCATE, f, __VA_ARGS__)
#endif
#define LOG_LEVEL 2
#define LOG(lvl, ...) do {                       \
    if (LOG_LEVEL < lvl) break;                  \
    char b[1024];                                \
    snprintf(b, sizeof(b) - 1, __VA_ARGS__);     \
    b[sizeof(b) - 1] = 0;                        \
    printf("%i! %s\n", (int)(lvl), b);           \
} while(0 == __LINE__)

Что позволяет их использовать вот так:

unsigned fp;
char *fname;
// ...
if (seekFailed)
{
    LOG(1, "Failed to seek to offset %u in file \"%s\"", fp, fname);
}

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

LOG(1, "Failed to open file \"%s\", error %i", fname);

В этом примере не передаётся значение кода ошибки. Неприятно, но относительно безобидно. В качестве кода ошибки будет использован мусор из стека и лог будет содержать недостоверную информацию. Бывает и хуже:

LOG(2, "Failed to rename \"%s\" to \"%s\"", oldName);

Этот пример почти такой же, как предыдущий, за исключением того, что мусор в стеке на этот раз будет использован в качестве указателя на вторую строку, что в большинстве случаев приведёт к падению программы с ошибкой доступа по адресу (access violation at address). Более интересный результат можно получить при неаккуратном добавлении поддержки больших файлов в код из самого первого примера, объявив переменную fp следующим образом:

long long fp;

и забыв заменить %u в:

LOG(1, "Failed to seek to offset %u in file \"%s\"", fp, fname);

на что-то более подходящее. Чтобы разобраться в ситуации, рассмотрим каким образом параметры передаются в функцию с переменным числом аргументов. В зависимости от соглашения вызова, которому подчиняется функция, принимающая переменное число аргументов, параметры кладутся один за другим в регистры процессора и в стек. В качестве обобщения соглашений вызова, далее будут рассматриваться абстрактные ячейки памяти одинакового размера, располагающиеся одна за другой. Так вот, когда компилятор генерирует код вызова функции с переменным числом аргументов, он ещё не знает, как эти аргументы будут использоваться. Всё что он знает, это тип и, соответственно, размер каждого параметра. Поэтому, особо не мудрствуя, компилятор берёт и кладёт все параметры в эти абстрактные ячейки памяти, вплотную, один за другим. Каждому параметру достаётся как минимум одна ячейка (т.е. в одну ячейку не может быть положено два или более параметров). Если одной ячейки для параметра мало, он "разбивается" и раскладывается по нескольким ячейкам. В некотором виде, эти ячейки передаются в вызываемую функцию, которая на этапе компиляции не знает, какие параметры и в каком порядке помещены в доставшиеся ей ячейки. Более того, она даже не знает сколько именно ячеек ей досталось. Поэтому разбор поступивших ячеек ей приходится делать основываясь на какой-то дополнительной информации. Наиболее популярным примером такой дополнительной информации служит строка формата в функциях семейства printf, которая указывает количество, тип и порядок переданных параметров. Таким образом, если дополнительная информация о переданных параметрах не верна, функция не правильно интерпретирует значения в ячейках, что обычно приводи к некорректному поведению всей программы. Строка "Failed to seek to offset %u in file \"%s\"" говорит, что в функцию будет передано два параметра - один типа int и второй типа char *. В реализациях компиляторов под архитектуру IA-32 (i386) оба этих параметра обычно занимают по одной 32-битной ячейке памяти. Что произойдёт, если функции подсунуть в качестве первого параметра переменную типа long long? Переменные типа long long в компиляторах под архитектуру IA-32 обычно имеют размер 64 бита. Такому параметру будет не достаточно одной 32-битной ячейки памяти, поэтому он займёт две соседние ячейки, а второй параметр (ожидаемый указатель на строку) будет положен в третью ячейку рядом. Таким образом, когда функция будет производить разбор переданных параметров, она использует одну 32-битную часть переменной fp в качестве первого параметра и другую 32-битную часть в качестве второго (указателя на строку). Что при этом произойдёт, зависит от самого значения параметра fp:

• если UINT_MAX >= fp, то вторая часть переменной fp будет нулевой (для представления чисел от 0 до UINT_MAX достаточно 32 бит) и функция логирования напечатает "(null)" вместо имени файла
• если UINT_MAX < fp, то вторая часть переменной fp будет не нулевой (при этом скорее всего не являясь правильным указателем на выделенную память) и программа упадёт с ошибкой обращения по недоступному адресу

Интересно заметить, что если описанный пример скомпилировать под архитектуру AMD64 (x86-64), то подобных проблем не возникнет, так как каждому из параметров достанется по своей 64-битной ячейке. Однако, на печать при этом будут выводиться только младшие 32 бита переменной fp так как формат %u предполагает наличие параметра типа int.

Вот такая вот страшилка на ночь получилась.