К вопросу об Апофении, Телегонии и Путешествиях во времени (и функции с _ в начале)

В 1958 году немецкий нейропсихолог Клаус Конрад ввел термин «апофения» (от лат. apophene — высказывать суждение, делать явным; термин восходит к текстам религиозных откровений, где означает знание, достигаемое вне процесса познания), подразумевая под ним свойство психики, заключающегося в способности видеть взаимосвязи в бессмысленных или случайных фактах или данных и находить смысл в совпадениях. Иллюзия осмысленной связи. Наш мозг постоянно ищет закономерности, но зачастую допускает ошибки и возникает иррациональное желание видеть закономерности там, где их нет. Своеобразное желание подчиняться совпадениям и случайностям. Это и называют апофенией. В математической статистике – это стандартная ошибка первого рода.
Непряхин Н. «Я манипулирую тобой»

Почему я вспомнил об этом термине, особенно на IT ресурсе? Потому что поиск взаимосвязей среди разрозненных фактов во время отладки программ — один из основных факторов, определяющих её успешность. Ряд случайных неточностей в работе, каждая из которых никак не показывает причины своего возникновения и не влияет на работу программы в целом может казаться хаотичным. Однако, если попытаться найти между ними взаимосвязь то можно решить сразу массу проблем одной строчкой кода… Или убедиться, что взаимосвязь — не что иное, как игры разума, порождение фантазии разработчика.

Глава 1. «Агент и координатор»

Всё началось во время разработки программы-агента, выполняющей ряд задач на удаленном сервере, получая список задач через клиент-серверный механизм. Агент поднимал сервер на порту 34002, к нему подключался локальный координатор, они проверяли авторизацию друг друга и если всё шло хорошо, то агент выполнял требуемые действия и отчитывался наверх.


Упрощенная схема программы

Очевидным шагом со стороны агента было создать собственный fork, в котором выполнить любую функцию из семейства exec, чтобы заместить процесс запускаемой программой. При этом агент получал pid процесса, что позволяло ожидать его завершения или завершить его принудительно. Всё шло хорошо, однако для того, чтобы координатор мог получить отчет о проделанной работе необходимо было вернуть выводы stdout и stderr.

Эту задачу можно решить несколькими методами — передать процессу новые (dup2) FD для stdout и stderr, а затем читать их в материнском процессе; перенаправить stderr в stdout и использовать popen; переопределить stdout- и stderr-дескрипторы как файлы и прочитать их по завершению. Мы избрали последний метод, поскольку чтение по первому методу требовало дополнительного кода и синхронизации (а если не читать постоянно, то по достижении 2 МБ запись остановится по исчерпанию буфера pipe), а по второму мы теряли разграниченность stdout и stderr. Поэтому был выбран самый простой метод — закрыть новому процессу stdout и stderr, а затем открыть через open файлы, в которые мы хотим переопределить наш вывод. Согласно документации на open он использует минимальный доступный индекс FD, по причине чего код будет прост и элегантен:

int pid = fork();
switch (pid) {
    case -1 :
        return BADFORK;
    case 0 :
        close(stdout);
        close(stderr);
        open(fileout, O_CREAT | O_WRONLY, 0777);
        open(fileerr, O_CREAT | O_WRONLY, 0777);
        execve(arguments[0], arguments, environ);
        exit(EXIT_FAILURE);
    default :
        return pid;
}

Упрощенно код выглядит вот так (проверки на ошибки убраны в целях читаемости).

Код запускался, успешно писал в файл вывод команд, завершался и был готов работать на «боевых» системах. Или нет? На этапе тестирования проявился маленький баг, «доказывающий» возможность путешествий во времени (или хотя бы телегонии).

Глава 2. «Телегония»

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

[2020-06-05 16:58:49]  Начало ожидания клиентов сервера :34002

Погодите-ка! Но ведь это строка из вывода самого агента — материнского процесса, вызвавшего fork()! Мало того, агент выводит эту строку спустя какое-то время после завершения вызываемой программы! Как может весь остальной вывод агента писаться в stdout, а одна из строк — попадать в файл, вся работа с которым у агента заключается в его чтении после завершения waitpid? Может быть ошибка при чтении файла дает побитую память?

static void _exec_readfile(struct frs_json * target, const char * filename) {
    FILE * fp;
    char linebuff[VEN_PIPE_READ_SIZE + 1] = { 0 };
    fp = fopen(filename, "r");
    if (!fp)
        frs_err("Файл \"%s\" не открыт для чтения", filename);
    else {
        while(fgets(linebuff, VEN_PIPE_READ_SIZE, fp))
            frs_json_string(target, NULL, bxi_strtrimr(linebuff));
    }
    fclose(fp);
}

Вроде бы ничего такого, что могло бы побить память (frs_* покрыты тестами). Так как же этот fp влияет на вывод агента, который происходит спустя несколько минут после выполнения этой функции? Натурально, телегония какая-то — потрогали файл на чтение, а спустя 9 месяцев получаем в нем строку от «первого партнера».


Мой FD трогала зебра

Valgrind не обнаружил проблем, что нас несколько огорчило. Ведь его всемогущие анализаторы не видели ошибку доступа к памяти, только зря потратили кучу времени на анализ. Или не зря? Если нет ошибки доступа к памяти, значит ошибка логическая. Но какая логическая ошибка могла привести к такому эффекту?

Глава 3. «Два сервера»

Тем временем был найден второй баг. Во время запуска под отладкой QtCreator (мы используем его как среду разработки, сам проект на C) успешно завершал все относящиеся к программе процессы и этот баг не появлялся. Однако стоило попытаться запустить программу напрямую, а затем завершить ее (законными методами), как она переставала запускаться второй раз.

^C[2020-06-05 16:58:46]  Получен сигнал "Interrupt", начинается прерывание работы
[2020-06-05 16:58:49]  Начало ожидания клиентов сервера :34002
[2020-06-05 16:58:49]  Закончено ожидание клиентов сервера :34002
[2020-06-05 16:58:49]  Остановлен сервер на порту :34002
[2020-06-05 16:58:49]  Сервер приема команд остановлен
[2020-06-05 16:58:50]  Нить отправки широковещательных сообщений остановлена

Впору было подумать о маленьких гремлинах, разрушающих механизм программы изнутри, ломая то одну часть программы, то другую. Но программистское чутье подсказывало, что между этими багами была взаимосвязь. Какая? Кто знает, но это ж-ж-ж-ж неспроста!

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

[2020-06-06 14:40:12] frs_socket_bind Порт :34002 уже используется ("Address already in use" (98))
[2020-06-06 14:40:12]  Остановлен сервер на порту :34002
[2020-06-06 14:40:12] ven_server_start Сервер не может быть запущен

Как так уже запущен? Кто запустил? Ты же завершилась минуту назад!

$ ps aux | grep vento
alex     14144  0.0  0.0 156780  7212 pts/0    Sl+  14:39   0:00 ./vento

Действительно запущена. Но может просто случайность?

kill -9 14144

И снова программа запускается, но после завершения программы остается процесс, который владеет портом 34002:

$ lsof -i | grep 34002
vento     14144 alex    3u  IPv4 12275384      0t0  TCP *:34002 (LISTEN)

А кто же тогда завершается?

Рассмотрим вывод lsof -i во время работы.

Запускаем:

$ lsof -i | grep 34002
vento     151640 alex    3u  IPv4 12275384      0t0  TCP *:34002 (LISTEN)

Ага, один сокет, один сервер, один Рейх.

$ lsof -i | grep 34002
_Postman  25078 alex  104u  IPv4 12885232      0t0  TCP localhost:46154->localhost:34002 (ESTABLISHED)
vento     27468 alex    3u  IPv4 12890254      0t0  TCP *:34002 (LISTEN)

Вот к нему подключился клиент и задает какую-то команду…

Но что это?

$ lsof -i | grep 34002
_Postman  25078 alex  104u  IPv4 12885232      0t0  TCP localhost:46154->localhost:34002 (ESTABLISHED)
vento     27468 alex    3u  IPv4 12890254      0t0  TCP *:34002 (LISTEN)
vento     27506 alex    3u  IPv4 12890254      0t0  TCP *:34002 (LISTEN)
vento     27506 alex    4u  IPv4 12890329      0t0  TCP localhost:34002->localhost:46154 (ESTABLISHED)

Забавный факт #197766: рано или поздно должна появиться отсылка к «Звездным войнам»

Два серверных порта? При том, что наш сервер не использует флаг REUSEPORT.

Глава 4. «CLOEXEC»

Хм… Возможно в реализации сервера пропущен флаг CLOEXEC?

Рассмотрим флаг поближе:

$man fork
       *  The child process is created  with  a  single  thread—the  one  that
          called  fork().   The  entire virtual address space of the parent is
          replicated in the child, including the states of mutexes,  condition
          variables,  and other pthreads objects; the use of pthread_atfork(3)
          may be helpful for dealing with problems that this can cause.

       *  The child inherits copies of the parent's set of open file  descrip‐
          tors.   Each  file  descriptor  in the child refers to the same open
          file description (see open(2)) as the corresponding file  descriptor
          in  the parent.  This means that the two file descriptors share open
          file status flags, file offset,  and  signal-driven  I/O  attributes
          (see the description of F_SETOWN and F_SETSIG in fcntl(2)).

Вызов функции fork() создаст копию текущей нити процесса и создаст копию каждого открытого дескриптора процесса (а так как в UNIX[-like] системах «всё есть файл» — то наравне с файловыми дескрипторами будут склонированы и сетевые)

$man exec
       The exec() family of functions replaces the current process image with a new process image.  The functions described in
       this manual page are front-ends for execve(2).  (See the manual page  for  execve(2)  for  further  details  about  the
       replacement of the current process image.)

$man execve
       *  By  default,  file  descriptors  remain open across an execve().  File descriptors that are marked close-on-exec are
          closed; see the description of FD_CLOEXEC in fcntl(2).  (If a file descriptor is closed, this will cause the release
          of  all record locks obtained on the underlying file by this process.  See fcntl(2) for details.)  POSIX.1 says that
          if file descriptors 0, 1, and 2 would otherwise be closed after a successful execve(), and the  process  would  gain
          privilege because the set-user-ID or set-group_ID mode bit was set on the executed file, then the system may open an
          unspecified file for each of these file descriptors.  As a general principle, no portable  program,  whether  privi‐
          leged or not, can assume that these three file descriptors will remain closed across an execve().

Если мы не хотим, чтобы вызываемый процесс получил копию дескриптора, то мы должны выставить ему флаг FD_CLOEXEC/SOCK_CLOEXEC.

Вообще, логичнее было бы, если бы помечались дескрипторы, которые НУЖНО скопировать, чтобы избежать утечек доступа в root-файлы, но флаг появился в POSIX-2001, так что теперь это наше наследие, хотя и спорное.

server->socket = socket(AF_INET, SOCK_STREAM | SOCK_CLOEXEC, 0);

fcntl(client, F_SETFD, FD_CLOEXEC);

Однако нет, наши флаги выставляются как надо.

Тогда что же происходит? Ядро игнорирует флаг? Кто-то его сбрасывает? И главное, почему после завершения приложения процесс, занимающий порт остается в системе?

Попробуем закрыть основной сервер и подключиться к оставшемуся процессу при помощи gdb:

$ sudo gdb -p 27506
GNU gdb (Ubuntu 8.1-0ubuntu3.2) 8.1.0.20180409-git
[...]
Reading symbols from /lib/x86_64-linux-gnu/libgcc_s.so.1...(no debugging symbols found)...done.
0x00007f503d50c9f3 in futex_wait_cancelable (private=[optimized out], expected=0, futex_word=0x55f485d383b8)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:88
88	../sysdeps/unix/sysv/linux/futex-internal.h: Нет такого файла или каталога.
(gdb) bt
#0  0x00007f503d50c9f3 in futex_wait_cancelable (private=[optimized out], expected=0, futex_word=0x55f485d383b8)
    at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1  __pthread_cond_wait_common (abstime=0x0, mutex=0x55f485d38368, cond=0x55f485d38390) at pthread_cond_wait.c:502
#2  __pthread_cond_wait (cond=0x55f485d38390, mutex=0x55f485d38368) at pthread_cond_wait.c:655
#3  0x00007f503d948097 in _frs_signal_wait (signal=0x55f485d38340, filename=0x7f503d7315c8 "fen_server.c", fileline=298)
    at ./projects/shared/libforseti/code/thread/frs_signal.c:250
#4  0x00007f503d728044 in _server_wait (server=0x55f485d38270) at ./projects/shared/libfenrir/code/server/fen_server.c:298
#5  0x00007f503d72822d in fen_server_free (server=0x55f485d38270) at ./projects/shared/libfenrir/code/server/fen_server.c:351

Стоп-стоп-стоп, какой server_free? Мы завершили не тот процесс? Ведь здесь должен быть запуск приложения echo!

Или не должен быть?

Глава 5. «Один символ»

Мы посылаем строку echo, но ведь в exec нужно помещать полный путь до приложения, поскольку мы запускаем его не в shell-среде в отличие от того же system. Поменяем на /bin/echo, и заметим, что проблема пропала. Но ведь тогда получается, что когда мы подаем неверную с точки зрения exec команду мы продолжаем работу в том же процессе и не замещаем его запускаемым приложением, а это значит, что…

        execve(arguments[0], arguments, environ);
        exit(EXIT_FAILURE);

Ну да, выполняется exit. Но как это заставляет закрываться сервер?

/*! \brief Деинициализатор модуля */
static void _free(void) __attribute__((destructor));
static void _free(void) {
    fen_server_free(g_server);
    frs_inf("Сервер приема команд остановлен");
}

Теперь всё стало на свои места. Эти два бага действительно были связаны между собой, и теперь даже можно сказать как именно:



Что ж, осталось починить неправильно работающую систему. А сделаем мы это как в анекдоте про телевизионного мастера и один удар молотком:

Добавим один символ «_» к слову exit:

int pid = fork();
switch (pid) {
    case -1 :
        return BADFORK;
    case 0 :
        close(stdout);
        close(stderr);
        open(fileout, O_CREAT | O_WRONLY, 0777);
        open(fileerr, O_CREAT | O_WRONLY, 0777);
        execve(arguments[0], arguments, environ);
        _exit(EXIT_FAILURE);
    default :
        return pid;
}

Что теперь происходит? Ничего особенного, кроме того, что теперь завершающийся процесс будет завершаться без вызова зарегистрированных через atexit функций. На старых реализациях glibc это будет вызов системного вызова _exit, на более новых вызов exit_group для более корректного завершения всех нитей программы.

Что ж, оба бага побеждены, а вы говорили «апофения», «тебе только чудится», «связи нет». Пойду передвину ящик на полке, а то человечество больше в космос не полетит.