Довгий шлях низькорівневого дебага, щоб знайти закомментаренную рядок коду, випадково пішла в продакшн

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

Архітектура нашої системи досить стандартна. Основна частина даних в MySQL. Є масштабований пул worker'ів на NodeJS. PHP процеси через RabbitMQ ставлять завдання цим worker'ам і з того ж кролика отримує назад результати.
У якийсь момент у нас стали виникати проблеми з тим, що PHP процеси (у нас 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 - ©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] породження 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 (див. помилки вище)? Якщо ви знаєте природу цих помилок, то дайте знати. Можна в лічку.

Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.