Маємо API-сервіс в Kubernetes, який періодично видає 502, 503, 504 помилки.
Почав його дебажити, і виявив дивну штуку – в логах не було повідомлень про отриманий SIGTERM, а тому спочатку пішов розбиратись з Kubernetes – чому він його не відправляє?
Зміст
The Issue
Отже, як це виглядає.
Маємо Kubernetes Pod:
$ kk get pod NAME READY STATUS RESTARTS AGE fastapi-app-89d8c77bc-8qwl7 1/1 Running 0 38m
Читаємо його логи:
$ ktail fastapi-app-59554cddc5-lgj42 ==> Attached to container [fastapi-app-59554cddc5-lgj42:fastapi-app]
Вбиваємо його:
$ kk delete pod -l app=fastapi-app pod "fastapi-app-6cb6b46c4b-pffs2" deleted
І що ми бачимо в його логах? А нічого!
... fastapi-app-6cb6b46c4b-9wqpf:fastapi-app [2024-06-22 11:13:27 +0000] [9] [INFO] Application startup complete. ==> Container left (terminated) [fastapi-app-6cb6b46c4b-pffs2:fastapi-app] ==> New container [fastapi-app-6cb6b46c4b-9qtvb:fastapi-app] ==> New container [fastapi-app-6cb6b46c4b-9qtvb:fastapi-app] fastapi-app-6cb6b46c4b-9qtvb:fastapi-app [2024-06-22 11:14:15 +0000] [8] [INFO] Starting gunicorn 22.0.0 ... fastapi-app-6cb6b46c4b-9qtvb:fastapi-app [2024-06-22 11:14:16 +0000] [9] [INFO] Application startup complete.
Тут:
- сервіс запустився – “Application startup complete“
- под вмер – “Container left“
- новий под запустився – “New container” і “Starting gunicorn“
А ось, як це має виглядати в нормальному випадку:
... fastapi-app-59554cddc5-v7xq9:fastapi-app [2024-06-22 11:09:54 +0000] [8] [INFO] Waiting for application shutdown. fastapi-app-59554cddc5-v7xq9:fastapi-app [2024-06-22 11:09:54 +0000] [8] [INFO] Application shutdown complete. fastapi-app-59554cddc5-v7xq9:fastapi-app [2024-06-22 11:09:54 +0000] [8] [INFO] Finished server process [8] fastapi-app-59554cddc5-v7xq9:fastapi-app [2024-06-22 11:09:54 +0000] [1] [ERROR] Worker (pid:8) was sent SIGTERM! fastapi-app-59554cddc5-v7xq9:fastapi-app [2024-06-22 11:09:54 +0000] [1] [INFO] Shutting down: Master ==> Container left (terminated) [fastapi-app-59554cddc5-v7xq9:fastapi-app]
Тобто тут Gunicorn отримує SIGTERM, і коректно завершує свою роботу.
Якого біса?
Давайте розбиратись.
Kubernetes та процес Pod termination
Як відбувається процес зупинки подів?
Детальніше писав у Kubernetes: NGINX/PHP-FPM graceful shutdown – избавляемся от 502 ошибок, тут дуже коротко:
- виконуємо
kubectl delete pod kubeletна відповідній WorkerNode отримує від API-серверу команду на зупинку подуkubeletвідправляє контейнеру сигналSIGTERM– до процесу з PID 1, тобто першому процесу, який запущено при створенні контейнеру- якщо контейнер не зупинився протягом
terminationGracePeriodSeconds– то відправляєтьсяSIGKILL
Тобто наш процес Gunicorn має отримати SIGTERM, записати це в лог, і почати запиняти свої воркери.
Натомість він не отримує нічого і просто вмирає.
А чому?
PID 1 та SIGTERM в контейнерах
Глянемо, що у нас з процесами в цьому поді :
root@fastapi-app-6cb6b46c4b-9qtvb:/app# ps aux USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND root 1 0.0 0.0 2576 948 ? Ss 11:14 0:00 /bin/sh -c gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app root 8 0.0 1.3 31360 27192 ? S 11:14 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app root 9 0.2 2.4 287668 49208 ? Sl 11:14 0:04 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
І бачимо, що у нас тут PID 1 – це процес /bin/sh, який через -c запускає gunicorn.
Тепер давайте в поді запустимо strace, і подивимось які сигнали він отримує:
root@fastapi-app-6cb6b46c4b-9pd7r:/app# strace -p 1 strace: Process 1 attached wait4(-1,
Виконуємо kubect delete pod – але додамо time, аби заміряти час на виконання команди:
$ time kk delete pod fastapi-app-6cb6b46c4b-9pd7r pod "fastapi-app-6cb6b46c4b-9pd7r" deleted real 0m32.222s
32 секунди…
А що в strace?
root@fastapi-app-6cb6b46c4b-9pd7r:/app# strace -p 1
strace: Process 1 attached
wait4(-1, 0x7ffe7a390a3c, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
--- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=0, si_uid=0} ---
wait4(-1, <unfinished ...>) = ?
command terminated with exit code 137
Отже, що тут відбувалось:
kubeletвідправив сигналSIGTERMпроцесу з PID 1 – SIGTERM {si_signo=SIGTERM} – і PID 1 мав би передати цей процес своїм дочірнім процесам, зупинити їх, а потім завершитись сам- але процес не завершився – і
kubeletпочекав дефолтні 30 секунд, аби под коректно завершив свою роботу – див. Pod phase - після чого вбив контейнер, і процес завершився з “terminated with exit code 137“
Зазвичай код 137 – це про OutOfMemory Killer, коли процес вбивається з SIGKILL, але в нашому випадку OOMKill не було – а просто відбувся SIGKILL через те, що процеси в поді не завершились вчасно.
Добре – а куди подівся наш SIGTERM?
Давайте виконаємо сигнали напряму з контейнеру – спочатку kill -s 15, SIGTERM, потім kill -s 9, SIGKILL:
root@fastapi-app-6cb6b46c4b-r9fnq:/app# kill -s 15 1 root@fastapi-app-6cb6b46c4b-r9fnq:/app# ps aux USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND root 1 0.0 0.0 2576 920 ? Ss 12:02 0:00 /bin/sh -c gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app root 7 0.0 1.4 31852 27644 ? S 12:02 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app ... root@fastapi-app-6cb6b46c4b-r9fnq:/app# kill -s 9 1 root@fastapi-app-6cb6b46c4b-r9fnq:/app# ps aux USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND root 1 0.0 0.0 2576 920 ? Ss 12:02 0:00 /bin/sh -c gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app root 7 0.0 1.4 31852 27644 ? S 12:02 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
Шо? Як?
Чому ігнорується SIGTERM? А тим більш SIGKILL, який має бути “non ignorant signal” – див. man signal:
The signals SIGKILL and SIGSTOP cannot be caught, blocked, or ignored.
Linux kill() та PID 1
Бо PID 1 в Linux є особливим процесом, бо це перший процес, який запускається системою, і він має бути “захищений” від “випадкового вбивства”.
Якщо ми глянемо на man kill, то там це явно вказано, а також сказано про хендлери сигналів до процесу:
The only signals that can be sent to process ID 1, the init process, are those for which init has explicitly installed signal handlers. This is done to assure the system is not brought down accidentally
Перевірити які хендлери є у нашого процесу – тобто, які сигнали наш процес може перехопити і обробити – можна з файлу /proc/1/status:
root@fastapi-app-6cb6b46c4b-r9fnq:/app# cat /proc/1/status | grep SigCgt SigCgt: 0000000000010002
SigCgt – це сигнали, які процес може перехопити і обробити сам. Решта будуть або проігноровані, або опрацьовані з SIG_DFL handler, а SIG_DFL handler ігнорує сигнали для PID 1, у якого нема власного хендлера.
Спитаємо ChatGPT які саме це сигнали:
(взагалі можна і самому перевести, якщо цікаво – див. наприклад How can I check what signals a process is listening to? або How to read bitmask for the signals)
Отже, що ми маємо:
- процес
/bin/shз PID 1 - PID 1 є спеціальним процесом
- перевірка PID 1 вказує нам, що він “розпізнає” тільки сигнали
SIGHUPіSIGCHLD SIGTERMтаSIGKILLбудуть ним проігноровані
Але як жеж тоді зупиняється контейнер?
Docker stop та сигнали
Процес зупинки контейнера в Docker (або Containerd) не відрізняється від того, як це в Kubernetes, бо по факту kubelet просто передає команди на container runtime. В AWS Kubernetes це зараз containerd.
Але задля простоти давайте виконаємо це локально з Docker.
Отже, запускаємо контейнер з того самого образу, який тестили в Kubernetes:
$ docker run --name test-app 492***148.dkr.ecr.us-east-1.amazonaws.com/fastapi-app-test:entry-2 [2024-06-22 14:15:03 +0000] [7] [INFO] Starting gunicorn 22.0.0 [2024-06-22 14:15:03 +0000] [7] [INFO] Listening at: http://0.0.0.0:80 (7) [2024-06-22 14:15:03 +0000] [7] [INFO] Using worker: uvicorn.workers.UvicornWorker [2024-06-22 14:15:03 +0000] [8] [INFO] Booting worker with pid: 8 [2024-06-22 14:15:03 +0000] [8] [INFO] Started server process [8] [2024-06-22 14:15:03 +0000] [8] [INFO] Waiting for application startup. [2024-06-22 14:15:03 +0000] [8] [INFO] Application startup complete.
Пробуємо його зупинити через відправку SIGKILL до PID 1 – нічого не змінилося, він ігнорує сигнал:
$ docker exec -ti test-app sh -c "kill -9 1" $ docker ps CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES 99bae6d55be2 492***148.dkr.ecr.us-east-1.amazonaws.com/fastapi-app-test:entry-2 "/bin/sh -c 'gunicor…" About a minute ago Up About a minute test-app
Пробуємо зупинити з docker stop – і знов дивимось на час:
$ time docker stop test-app test-app real 0m10.234s
І статус контейнера:
$ docker ps -a CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES cab29916f6ba 492***148.dkr.ecr.us-east-1.amazonaws.com/fastapi-app-test:entry-2 "/bin/sh -c 'gunicor…" About a minute ago Exited (137) 52 seconds ago
Той жеж код 137, тобто контейнер зупинився з SIGKILL.
Але як, якщо сигнал відправляється до PID 1, котрий його ігнорує?
Я не знайшов цього в документації до docker kill, але ми можемо вбити процеси контейнеру двома шляхами:
- вбити всі дочірні процеси в самому контейнері – і тоді parent (PID 1) вмре сам
- вбити всю групу процесів на хості через їхній SID (Session ID) – що знову-таки призведе до того, що PID 1 проігнорує сигнал, але вмре сам, бо померли всі його дочірні процеси
Ще раз глянемо на процеси в контейнері:
root@cddcaa561e1d:/app# ps aux
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
root 1 0.0 0.0 2576 1408 ? Ss 15:58 0:00 /bin/sh -c gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
root 7 0.1 0.0 31356 26388 ? S 15:58 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
root 8 0.5 0.1 59628 47452 ? S 15:58 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
root@cddcaa561e1d:/app# pstree -a
sh -c gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
└─gunicorn /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
└─gunicorn /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
Вбити PID 1 ми не можемо, бо він нас ігнорує – але ми можемо вбити PID 7!
Тоді він за собою вб’є PID 8, бо це його дочірній процес, а коли PID 1 виявить, що більше нема його дочірніх процесів – то він вмре сам, і контейнер зупиниться:
root@cddcaa561e1d:/app# kill 7
І логи контейнеру:
... [2024-06-22 16:02:54 +0000] [7] [INFO] Handling signal: term [2024-06-22 16:02:54 +0000] [8] [INFO] Shutting down [2024-06-22 16:02:54 +0000] [8] [INFO] Error while closing socket [Errno 9] Bad file descriptor [2024-06-22 16:02:54 +0000] [8] [INFO] Waiting for application shutdown. [2024-06-22 16:02:54 +0000] [8] [INFO] Application shutdown complete. [2024-06-22 16:02:54 +0000] [8] [INFO] Finished server process [8] [2024-06-22 16:02:54 +0000] [7] [ERROR] Worker (pid:8) was sent SIGTERM! [2024-06-22 16:02:54 +0000] [7] [INFO] Shutting down: Master
Але так як поди/контейнери вмирають з кодом 137, то вони були вбиті з SIGKILL, бо коли Docker або інший container runtime не може зупинити процес з PID 1 з SIGKILL – то він відправляє SIGKILL всім процесам в контейнері.
Тобто:
- спочатку відправляється
SIGTEMдо PID 1 - через 10 секунд відправляється
SIGKILLдо PID 1 - якщо і це не допомогло – то
SIGKILLвідправляється всім процесам в контейнері
Наприклад, це можна зробити передавши Session ID (SID) команді kill.
Знаходимо основний процес контейнеру:
$ docker inspect --format '{{ .State.Pid }}' test-app
629353
Виконуємо ps j -A:
$ ps j -A PPID PID PGID SID TTY TPGID STAT UID TIME COMMAND ... 629333 629353 629353 629353 ? -1 Ss 0 0:00 /bin/sh -c gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app 629353 629374 629353 629353 ? -1 S 0 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app 629374 629375 629353 629353 ? -1 S 0 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
Бачимо наш SID – 629353.
І вбиваємо всю групу:
$ sudo kill -9 -- -629353
Окей.
Це все добре і дуже цікаво.
Але можна обійтися без цих костилів?
“Правильний” запуск процесів в контейнері
Врешті-решт, давайте глянемо на наш Dockerfile:
FROM python:3.9-slim WORKDIR /app COPY requirements.txt . RUN pip install --no-cache-dir -r requirements.txt COPY . . ENTRYPOINT gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
Дивимось документацію Docker – Shell and exec form:
INSTRUCTION [“executable”,”param1″,”param2″] (exec form)
INSTRUCTION command param1 param2 (shell form)
Отже, в нашому випадку використовується як раз shell form – і в результаті в ролі PID 1 маємо саме /bin/sh, який через -c викликає Gunicorn.
Якщо ж ми перепишемо в exec form:
FROM python:3.9-slim WORKDIR /app COPY requirements.txt . RUN pip install --no-cache-dir -r requirements.txt COPY . . ENTRYPOINT ["gunicorn", "-w", "1", "-k", "uvicorn.workers.UvicornWorker", "--bind", "0.0.0.0:80", "app:app"]
І запустимо контейнер з такого образу, то будемо мати тільки Gunicorn процеси:
root@e6087d52350d:/app# ps aux USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND root 1 0.6 0.0 31852 27104 ? Ss 16:13 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app root 7 2.4 0.1 59636 47556 ? S 16:13 0:00 /usr/local/bin/python /usr/local/bin/gunicorn -w 1 -k uvicorn.workers.UvicornWorker --bind 0.0.0.0:80 app:app
Які вже нормально хендлять сигнали SIGTERM:
root@e6087d52350d:/app# cat /proc/1/status | grep SigCgt SigCgt: 0000000008314a07
І тепер, якщо ми відправимо SIGTERM до PID 1 – то контейнер нормально завершить свою роботу:
root@e6087d52350d:/app# kill 1
І його логи:
... [2024-06-22 16:17:20 +0000] [1] [INFO] Handling signal: term [2024-06-22 16:17:20 +0000] [7] [INFO] Shutting down [2024-06-22 16:17:20 +0000] [7] [INFO] Error while closing socket [Errno 9] Bad file descriptor [2024-06-22 16:17:20 +0000] [7] [INFO] Waiting for application shutdown. [2024-06-22 16:17:20 +0000] [7] [INFO] Application shutdown complete. [2024-06-22 16:17:20 +0000] [7] [INFO] Finished server process [7] [2024-06-22 16:17:20 +0000] [1] [ERROR] Worker (pid:7) was sent SIGTERM! [2024-06-22 16:17:21 +0000] [1] [INFO] Shutting down: Master
Ну і поди в Kubernetes тепер будуть зупинятись нормально – і швидко, бо не будуть чекати grace period.
Корисні посилання
- Why Sometimes the PID 1 Process Cannot Be Killed in a Container – чудовий пост про те, як SIGKILL опрацьовується для PID 1 в самому ядрі Linux
- How Signal Works inside the Kernel – і ще трохи про ядро і сигнали
- Why do you need an init process inside your Docker container (PID 1)
- Killing a process and all of its descendants
