Web разработчик
0,0
рейтинг
27 ноября 2015 в 00:22

Разработка → Долгий путь низкоуровневого дебага, чтобы найти закомментаренную строку кода, случайно ушедшую в продакшн

Поиск багов
«Здравствуйте. Меня зовут Вячеслав, мне 22 года и я пхп программист. Я сижу на PHP с 18 лет.»… (копирайт не знаю чей, я не Вячеслав и мне давно не 22 года).
Да, у нас проект на PHP и мы столкнулись с тем, что на MySQL сервере стало появляться большое количество коннектов в состоянии Sleep.
А виноват в этом оказался код, работаюший с кроликом (RabbitMQ).
Ну а как связаны MySQL, RabbitMQ и закомментаренная строка вы узнаете код катом.

Архитектура нашей системы достаточно стандартная. Основная часть данных в MySQL. Имеется масштабируемый пул worker'ов на NodeJS. PHP процессы через RabbitMQ ставят задачи этим worker'ам и из того же кролика получает назад результаты.
В какой-то момент у нас стали возникать проблемы с тем, что PHP процессы (у наc Nginx + php-fpm) иногда не могут подключиться к MySQL. Есть проблема — нужно ее решать!
Стали смотреть на MySQL. Из аномального заметили, что show processlist показывает чрезмерно большое количество коннектов в состоянии sleep.
mysql> show processlist;
+----------+--------------+---------------------+-----------------+-------------+--------+
| Id       | User         | Host                | db              | Command     | Time   |
+----------+--------------+---------------------+-----------------+-------------+--------+
...............
| 16941988 | new_search   | 172.16.10.214:59412 | parts_nm_new    | Sleep       |  19667 |
| 16941993 | new_search   | 172.16.10.213:58562 | parts_nm_new    | Sleep       |  19666 |
...............

Это только часть вывода команды. Подобных процессов мы обнаружили более 100 штук и их количество со временем росло. Причем по Time видно, что в Sleep процессы висят очень давно.

Такого раньше не было и быть не должно.
Хорошо, тут мы видим IP PHP серверов (а PHP серверов у нас порядка 10 штук), с которых висели подозрительные коннекты.
Выбираем для исследований сервер 172.16.10.214 и идем смотреть, что там творится.
pm.max_requests у нас имеет не самое большое значение и по логике вещей, мы должны найти php-fpm процесс, который стартовал достаточно давно, т.к. в штатном режиме php-fpm процессы регулярно рестартуются мастер процессом.
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
................
nginx     6627  3.6  2.6 961232 103940 ?       S    22:29   0:09 php-fpm: pool main_socket
nginx     8434  2.7  2.5 956224 99416 ?        D    22:30   0:07 php-fpm: pool main_socket
nginx     8449  2.9  2.0 958124 79312 ?        S    22:30   0:07 php-fpm: pool main_socket
nginx    10798  0.0  1.9 954268 75696 ?        S    16:59   0:06 php-fpm: pool main_socket
nginx    11412  0.0  2.6 961384 104128 ?       S    17:48   0:06 php-fpm: pool main_socket
nginx    12173  0.0  2.0 960452 79664 ?        S    17:48   0:06 php-fpm: pool main_socket
nginx    13260  0.0  2.6 955920 102360 ?       S    17:00   0:03 php-fpm: pool main_socket
nginx    13663  0.0  1.1 953040 44324 ?        S    17:01   0:00 php-fpm: pool main_socket
root     23213  0.0  0.1 939640  7768 ?        Ss   15:41   0:01 php-fpm: master process (/opt/php5/etc/php-fpm.main.conf)
................

И мы видим “залипший” процесс (на самом деле их несколько) по достаточно старому времени запуска (START). Например, процесс с PID 10798 висит уже несколько часов.
Нам конечно же интересно понять, чем он там занимается. Цепляемся к нему strace'ом и видим:

strace -p 10798
Process 10798 attached - interrupt to quit
recvfrom(10,


ну а дальше тишина. Процесс чего-то от кого-то ждет. Как по дескриптору 10 понять, с чем от связан (файл, сокет) я не знаю. Наверное как-то можно. Буду благодарен, если в комментах подскажете, как это сделать. В будущем пригодится.
Изучив еще несколько подозрительных процессов на других серверах было выявлено, что все они висят на recvfrom.
Копаем дальше. Смотрим, какие коннекты держит процесс с PID 10798:
netstat -ap|grep 10798
tcp        0      0 v-php-ws2:47736             mongodb01:27017             ESTABLISHED 10798/php-fpm
tcp        0      0 v-php-ws2:55686             memcached-vip:memcache      ESTABLISHED 10798/php-fpm
tcp        0      0 v-php-ws2:59412             mysql-master:mysql          ESTABLISHED 10798/php-fpm
tcp        0      0 v-php-ws2:54630             rabbitmq:amqp               ESTABLISHED 10798/php-fpm
tcp        0      0 v-php-ws2:58901             mongodb02:27017             ESTABLISHED 10798/php-fpm
udp        0      0 *:43387                     *:*                                     10798/php-fpm
unix  2      [ ]         STREAM     CONNECTED     20141894 10798/php-fpm       /var/run/php-fpm-main.socket


Что мы видим. Коннект с MySQL сервером ( mysql-master:mysql ) — это мы и так знаем. Именно этот коннект в состоянии Sleep мы видели на MySQL сервере.
Коннект к memcache сервером. Там у нас хранятся сессии пользователей.
Коннект с MongoDB — там у нас часть закешированных данных лежит. А два коннекта, т.к. кластер MongoDB из трех серверов, один из которых арбитр.
И коннект к кролику (RabbitMQ).
Исходя из логики приложения к кролику коннект происходит позже всего. И если бы мы зависли на другом соединении, то скорее всего до кролика дело бы не дошло. Поэтому основным подозреваемым стал коннект именно к кролику.
Идем на RabbitMQ и ищем подозреваемый коннект (54630 — это исходящий порт коннекта к кролику проблемного php-fpm, см. предыдущий вывод netstat):
netstat -anp|grep 54630
tcp        0      0 ::ffff:172.16.10.218:5672   ::ffff:172.16.10.214:54630  ESTABLISHED 2364/beam

Что-то умнее, чем пробовать этот коннект убить с помощью killcx.sourceforge.net в голову не приходит, т.к. tcpdump говорит, что данные в этом коннекте не ходят:
killcx 172.16.10.214:54630
killcx v1.0.3 - (c)2009-2011 Jerome Bruandet - http://killcx.sourceforge.net/

[PARENT] checking connection with [172.16.10.214:54630]
[PARENT] found connection with [172.16.10.218:5672] (ESTABLISHED)
[PARENT] forking child
[CHILD]  interface not defined, will use [eth1]
[CHILD]  setting up filter to sniff ACK on [eth1] for 5 seconds
[PARENT] sending spoofed SYN to [172.16.10.218:5672] with bogus SeqNum
[CHILD]  hooked ACK from [172.16.10.218:5672]
[CHILD]  found AckNum [2073273429] and SeqNum [1158333446]
[CHILD]  sending spoofed RST to [172.16.10.218:5672] with SeqNum [2073273429]
[CHILD]  sending RST to remote host as well with SeqNum [1158333446]
[CHILD]  all done, sending USR1 signal to parent [8658] and exiting
[PARENT] received child signal, checking results...
         => success : connection has been closed !


И тут случилось чудо, зависший php-fpm (по strace стало видно) весело побежал дальше работать и зависший коннект с MySQL сервером исчез!

Результат расследований выявил проблемный участок — почему-то PHP чего-то долго ждет (он же в recvfrom системной вызове висит) от кролика.
У нас логика приложения такая, что если от кролика нет ответа более 5 секунд, то ждать уже нет смысла. А тут зависания навечно.
Пошли смотреть в код и вот оно!!! Закомментированная строка, которая случайно ушла в продакшен:
       $cnn = new \AMQPConnection($conn);
//        $cnn->setReadTimeout(5);


Теперь мы знаем, как нам починиться. Но почему NodeJS иногда не отправляют в кролик результаты расчетов за 5 секунд? Нужно масштабироваться? Нет, там еще запас прочности гигантский.
И я знаю, почему NodeJS иногда не присылает результаты, но не знаю, из-за чего это происходит.
Если посмотреть логи RabbitMQ, то у нас там есть ошибки, которые мы давно не можем понять, из-за чего они происходят. Вот эти ошибки:
=ERROR REPORT==== 26-Nov-2015::06:03:11 ===
Error on AMQP connection <0.16535.3527> (172.16.10.95:44482 -> 172.16.10.218:5672, vhost: '/', user: 'php', state: running), channel 1:
{amqp_error,frame_error,
            "type 1, first 16 octets = <<0,60,0,40,0,0,28,80,97,114,116,75,111,109,77,97>>: {invalid_frame_end_marker,\n                                                                                2}",
            none}

=ERROR REPORT==== 26-Nov-2015::06:20:12 ===
Error on AMQP connection <0.18878.3534> (172.16.10.95:44683 -> 172.16.10.218:5672, vhost: '/', user: 'php', state: running), channel 512:
{amqp_error,frame_error,
            "type 206, all octets = <<>>: {frame_too_large,16777216,131064}",
            none}


Вот эти два типа ошибок иногда, примерно пару раз в час возникают при работе NodeJS c RabbitMQ. На NodeJS возникает Exception и результат в очередь не записывается. Ну и соответственно PHP его не дожидается. PHP ждет 5 сек и идет дальше. Мы можем себе позволить потерять ответ (это не банковские транзакции). Но мы пытаемся понять природу этих ошибок. К сожалению, пока безуспешно.

Мораль: зачем я это все написал?

Это не первый случай, когда мне приходится опускаться до уровня strace. И мне иногда кажется, что могут быть более высокоуровневые инструменты выявления подобных проблем. При тестировании проблема не воспроизводится. Ловится она только на продакшене. Как бы вы поступили в моей ситуации?
Ну и вторая причина. Вдруг кто-то уже сталкивался с подобной проблемой RabbitMQ (см. ошибки выше)? Если вы знаете природу этих ошибок, то дайте знать. Можно в личку.
Дмитрий Лабутин @Labutin
карма
113,0
рейтинг 0,0
Web разработчик

Похожие публикации

Реклама помогает поддерживать и развивать наши сервисы

Подробнее
Спецпроект

Самое читаемое Разработка

Комментарии (25)

  • +2
    А вы логируете, то что скидывается из node в rabbitmq? Возможно проблема в данных. Ну или в драйвере.
    Что у вас за пулл такой, который жрёт подключения бесконтрольно? Если в пуле 100 воркеров то и подключений должно быть 100 и не больше.
  • 0
    По поводу данных, которые от NodeJS к RabbitMQ идут — мы думали, что дело в них. Но проблема возникает какими-то набегами. Корреляцию с данными не обнаружили.
    А пул воркеров вы имеете в виду php-fpm? Как я написал, их у нас около 10 штук. На каждой ноде стоит максимальное кол-во php-fpm 50. Итого коннектов может максимум дорастать до 500, что для MySQL не так уж и много.
    Отдельная тема, почему у нас начали возникать проблемы с коннектами к MySQL еще до того, как мы дошли до порога 600:
    mysql> show variables like '%max_connections%';
    +-----------------------+-------+
    | Variable_name         | Value |
    +-----------------------+-------+
    | extra_max_connections | 1     |
    | max_connections       | 600   |
    +-----------------------+-------+
    

    Если выясню, может будет статья о другом расследовании.
    • 0
      У нас в rabbitmq складываются только ключи, а сами данные лежат в redis, удаляются после обработки задачи. Нам кажется что так понадежнее, хотя кто-то может сказать что добавили себе вторую точку отказа) Зато есть возможность восстановить очередь в случае чего.
  • +7
    Как по дескриптору 10 понять, с чем от связан (файл, сокет) я не знаю.
    ls /proc/$PID/fd/ -la
    • +5
      Лучше
      lsof -p $PID
      
  • 0
    gdb!
    • +1
      Там у меня старенькая статья, можете в профиле посмотреть. Тоже была похожая проблема — только на продакшене и через несколько дней все зависало. gdb позволяет увидеть php стектрейс где висим ну и соответственно понять почему. Я понимаю, что использовать gdb это вообще жесть, но ведь сработало =)
      • 0
        Действительно, в gdb же можно посмотреть стектрейс. Нужно будет освоить на будущее.
      • +1
        Я понимаю, что использовать gdb это вообще жесть
        Не убирайте дебаг-символы, а лучше вообще скомпилируйте из исходников и не удаляйте исходники, в таком случае, gdb вам даже строчку в исходнике покажет, которую он сейчас исполняет.
        • 0
          Да, я так и делал, компилил с -g вроде (--enable-debug или как там), не помню точно уже.
  • +6
    Вообще, конечно, это круто. Часто вижу девелоперов, которые сталкиваясь с такой сложной проблемой говорят «а фиг его знает» и вставляют подпорки типа ежечасного рестарта воркеров вместо того чтобы разобраться в сути проблемы.
  • +1
    В вашей компании недостаточно code review.
    • +1
      Совет конечно правильный и точно в цель.
      Но у всех на слуху одно мобильное приложение одной крупной компании, которое ушло в продакшн с дебаг кодом, что приводило к тому, что место на смартфонах быстро заканчивалось.
      Все мы люди и допускаем ошибки, торопимся. И иногда эти ошибки нужно находить и устранять.
      • 0
        Да, ошибаются все. Я вас не обвиняю, просто концентрирую ваше внимание на данном вопросе :)
  • 0
    По обоим ошибкам очень похоже на какие-то лимиты в RMQ. См. первые ссылки на SO по ним. Ваш кэп.
  • 0
    Читается как остросюжетный детектив!
    • –1
      Да какой тут детектив? Небось достаточно было по логу ближайших комитов, либо при сравнении раннней версии кода, когда таких проблем не было, увидеть что кто-то зачемто закомментировал строчку.
      • 0
        «В какой-то момент» вот именно тут надо было первым делом бежать в лог гита (или что у вас там) и смотреть крайние коммиты. И до стектрейса не дошло.
        • –1
          Да на самом деле, все проще — эти парни небось даже code review не делают. Да вот даже то самое банальное, перед комитом тупо посмотреть diff того чего комитишь.
          • –1
            эти парни небось даже code review не делают


            Хорошо ещё если VCS используется — про коммиты в статье ни слова:
            Закомментированная строка, которая случайно ушла в продакшен:

            Как именно она туда ушла — ни слова :)
            • +4
              Троль детектед :)
              Конечно же мы на сервер носим код на дискетках, а git или svn — это для нас какие-то странные три буквы, которых мы боимся!
              Знаете как прикольно с дискеткаки бегать между десятками серверов и релизить одновременно!
              Командир поднимает руку и командует — релиз!!! И разработчики одновременно на все сервера копируют новый код. Разве кто-то сейчас делает по-другому?
              • 0
                Еще через capistrano можно деплоить zip-архивы :)
              • 0
                Ну чутка он вас конечно тролит, но в целом он прав)
                При прочтении только названия статьи — сразу вопрос каким таким образом она вообще туда ушла.
                Ну и собственно мораль у вас не правильная получается.
                • +1
                  Честно говоря, не хотел продолжать эту ветку в комментариях. Но под вечер решил ответить.
                  1. Согласен, что лучше вообще не допускать ошибок в написании кода.
                  2. Согласен, что лучше устроить такой процесс code review, что просочившись через первый пункт ошибка будет выловлена другими членами команды.
                  Но я не видел еще ни одного «Гугла», «Яндекса», «Яблока» и т.п. которые бы даже при таком подходе в продакшн не отправляли бы код с ошибкой. И никакой CI тоже не помогает. Все это конечно устремляет вероятность ошибки к нулю, то пока код пишут люди, а не роботы — такого не будет.
                  А когда ошибка проявляется не сама по себе, а в следствии стечения обстоятельств других подсистем (в моем случае кролика и ноды), то и проявляться она начинает далеко не сразу.
                  Некоторые комментаторы сделали предположения, что коммит с закомментаренной строкой совпал с началом проблем. Но я про это даже близко не упоминал.
                  Я не спорю, можно было просмотреть логи коммитов нескольких месяцев назад и найти проблему без дебага. Но IMHO это заняло бы «чуток» больше времени.

                  И если непонятно, как строка ушла в продакшн, то лично я бы уточнил бы этот вопрос, а не сразу стал бы домысливать страшные картинки и делать тролеподобные выводы. Так можно напридумывать фантазий которые к реальной жизни не имеют никакого отношения.
  • 0
    "мы заметили, что в node.js временами залипают коннекты в ..."
    свежо, ага. у нас точно также непредсказуемо залипали http-коннекты. и просто чистые tcp-stream. задолбались ловить.

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