Поиск зависшего запроса на внешний адрес из php скрипта

Есть скрипт на php, и он куда-то стучится. И вот появляется “плавающий баг”, когда скрипт иногда зависает и больше ничего не происходит. Нет ни нагрузки на процессор, ни на диск, но время выполнения уже “давно пройдено”.

Получаем PID

Для начала было бы хорошо глянуть “в процесс” скрипта, что бы увидеть что там происходит. Для этого через удобный инструмент нужно получить PID. На примере ps:

1
2
3
4
ps -A -o pid,user,time,cmd | grep "crm\|PID"
    PID USER         TIME CMD
 144275 www-data 00:01:54 /usr/local/bin/php -f /path/to/crm/script.php
 148340 www-data 00:00:00 grep crm\|PID

Первый столбец это и есть нужный нам PID: 144275.

Alpine linux

Так получается, что для Alpine linux ps это всего лишь ссылка на busybox:

1
2
$ ls -al $(which ps)
lrwxrwxrwx    1 root     root            12 Jun 27 22:42 /bin/ps -> /bin/busybox

Установить полноценный ps можно так:

1
# apk add procps

Если нет возможности установить его, то модифицируем команду с поиском (а точнее упростим по сравнению с ps):

1
2
3
4
$ ps | grep "crm\|PID"
PID   USER     TIME  COMMAND
144275 www-data  1:54 /usr/local/bin/php -f /path/to/crm/script.php
148291 www-data  0:00 grep crm\|PID

Как видим PID тут точно такой же как и при использовании полноценного ps-а: 144275.

Процесс выполнения скрипта

Что бы понять действительно ли он завис, или просто выполняет долгую операцию достаточно выполнить strace по полученному ранее PID-у:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
# strace -p 144275
strace: Process 144275 attached
restart_syscall(<... resuming interrupted read ...>) = 0
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}, {fd=9, events=POLLIN}], 2, 1000) = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}, {fd=9, events=POLLIN}], 2, 1000) = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}, {fd=9, events=POLLIN}], 2, 1000) = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}, {fd=9, events=POLLIN}], 2, 1000) = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}, {fd=9, events=POLLIN}], 2, 1000) = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN|POLLPRI|POLLRDNORM|POLLRDBAND}], 1, 0) = 0 (Timeout)
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}, {fd=9, events=POLLIN}], 2, 1000) = 0 (Timeout)
rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, 8) = 0
rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f1b668ceea8}, NULL, 8) = 0
poll([{fd=11, events=POLLIN}, {fd=9, events=POLLIN}], 2, 1000^Cstrace: Process 144275 detached
 <detached ...>

Судя по зацикленному выводу poll, rt_sigaction, poll, rt_sigaction, rt_sigaction, poll, ... скрипт повис. Повис он на попытке выполнить poll каких-то данных. В вызове мы видим и идентификатор файлового дескриптора (fd), из которого и происходит попытка получения данных.

Ищем файловый дескриптор

Теперь у нас есть PID (144275) и номер файлового дескриптора (11). Узнать что же за ним скрывается можно через lsof с помощью такой команды:

1
2
3
$ lsof -a -d 11 -p 144275
COMMAND    PID     USER FD   TYPE    DEVICE SIZE/OFF NODE NAME
php     144275 www-data 11u  IPv4 718693431      0t0  TCP eec4ba68ed28:33780->84.252.130.113:https (ESTABLISHED)

Тут мы видим, что это TCP соединение со сторонним сервером. По ip адресу можно более менее понять куда происходит соединение и копать в эту сторону.

Alpine linux

Как и с ps, lsof тут по умолчанию ведет на busybox:

1
2
$ ls -al $(which lsof)
lrwxrwxrwx    1 root     root            12 Jun 27 22:23 /usr/bin/lsof -> /bin/busybox

Установить полноценный lsof можно так:

1
# apk add lsof

Если по какой-то причине установить не представляется возможным, то придется немного “модифицировать” запрос lsof. Сам он не отфильтрует результат (да и значения будут “сырыми”):

1
2
3
$ lsof -a -d 11 -p 144275 | grep 11
144275	/usr/local/bin/php	8	/tmp/13d4d7db110bc477e837391bb31997cb
144275	/usr/local/bin/php	11	socket:[718693431]

Тут номер дескриптора идет в третьем столбце. Значит нас интересует socket:[718693431], в обычном выводе это столбец DEVICE. Тут же придется поискать устройство “руками”. Ищем в /proc/net/tcp (благо мы уже знаем, что это tcp соединение):

1
2
3
$ grep "718693431\|inode" /proc/net/tcp
  sl  local_address rem_address   st tx_queue rx_queue tr tm->when retrnsmt   uid  timeout inode
  17: 0453E30A:83F4 7182FC54:01BB 01 00000000:00000000 00:00000000 00000000   101        0 718693431 1 0000000000000000 20 4 10 10 -1

Интересный момент, но адреса и порты тут записаны в шестнадцатеричном формате. Сам ip адрес отображен задом-на-перед. То есть декодируем:

Адреса tcp соединения	`local_address`	`rem_address`
Начальное значение	`0453E30A:83F4`	`7182FC54:01BB`
Добавляем точки	`04.53.E3.0A:83F4`	`71.82.FC.54:01BB`
Переводим в десятичную систему счисления	`4.83.227.10:33780`	`113.130.252.84:443`
Отображаем ip адрес	`10.227.83.4:33780`	`84.252.130.113:443`

Получается, повисшее соединение: 10.227.83.4:33780->84.252.130.113:443, что соответствует выводу полноценного lsof.

Получаем PID#

Alpine linux#

Процесс выполнения скрипта#

Ищем файловый дескриптор#

Alpine linux#

Получаем PID

Alpine linux

Процесс выполнения скрипта

Ищем файловый дескриптор

Alpine linux