[Перевод] Отладка дедлока FUSE в ядре Linux
Наша команда вычислительных ресурсов Netflix (Compute team) отвечает за администрирование AWS, в том числе за автомасштабирование и развертывание контейнеризованных приложений, включая решение возникающих проблем. В мои обязанности входит разбор разного рода странных ошибок, о которых сообщают пользователи.
Проблема, описываемая далее, была связана с ndrive — внутренней файловой системой, реализованной с помощью FUSE. Я расскажу, как я копался в /proc в поисках причины, и узнал, как на самом деле работает wait в ядре.
Зависание Docker-контейнера при вызове kill и зомби-процесс
Мы столкнулись с зависанием при вызове API докера:
goroutine 146 [select, 8817 minutes]:
net/http.(*persistConn).roundTrip(0xc000658fc0, 0xc0003fc080, 0x0, 0x0, 0x0)
/usr/local/go/src/net/http/transport.go:2610 +0x765
net/http.(*Transport).roundTrip(0xc000420140, 0xc000966200, 0x30, 0x1366f20, 0x162)
/usr/local/go/src/net/http/transport.go:592 +0xacb
net/http.(*Transport).RoundTrip(0xc000420140, 0xc000966200, 0xc000420140, 0x0, 0x0)
/usr/local/go/src/net/http/roundtrip.go:17 +0x35
net/http.send(0xc000966200, 0x161eba0, 0xc000420140, 0x0, 0x0, 0x0, 0xc00000e050, 0x3, 0x1, 0x0)
/usr/local/go/src/net/http/client.go:251 +0x454
net/http.(*Client).send(0xc000438480, 0xc000966200, 0x0, 0x0, 0x0, 0xc00000e050, 0x0, 0x1, 0x10000168e)
/usr/local/go/src/net/http/client.go:175 +0xff
net/http.(*Client).do(0xc000438480, 0xc000966200, 0x0, 0x0, 0x0)
/usr/local/go/src/net/http/client.go:717 +0x45f
net/http.(*Client).Do(...)
/usr/local/go/src/net/http/client.go:585
golang.org/x/net/context/ctxhttp.Do(0x163bd48, 0xc000044090, 0xc000438480, 0xc000966100, 0x0, 0x0, 0x0)
/go/pkg/mod/golang.org/x/net@v0.0.0-20211209124913-491a49abca63/context/ctxhttp/ctxhttp.go:27 +0x10f
github.com/docker/docker/client.(*Client).doRequest(0xc0001a8200, 0x163bd48, 0xc000044090, 0xc000966100, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/go/pkg/mod/github.com/moby/moby@v0.0.0-20190408150954-50ebe4562dfc/client/request.go:132 +0xbe
github.com/docker/docker/client.(*Client).sendRequest(0xc0001a8200, 0x163bd48, 0xc000044090, 0x13d8643, 0x3, 0xc00079a720, 0x51, 0x0, 0x0, 0x0, ...)
/go/pkg/mod/github.com/moby/moby@v0.0.0-20190408150954-50ebe4562dfc/client/request.go:122 +0x156
github.com/docker/docker/client.(*Client).get(...)
/go/pkg/mod/github.com/moby/moby@v0.0.0-20190408150954-50ebe4562dfc/client/request.go:37
github.com/docker/docker/client.(*Client).ContainerInspect(0xc0001a8200, 0x163bd48, 0xc000044090, 0xc0006a01c0, 0x40, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
/go/pkg/mod/github.com/moby/moby@v0.0.0-20190408150954-50ebe4562dfc/client/container_inspect.go:18 +0x128
github.com/Netflix/titus-executor/executor/runtime/docker.(*DockerRuntime).Kill(0xc000215180, 0x163bdb8, 0xc000938600, 0x1, 0x0, 0x0)
/var/lib/buildkite-agent/builds/ip-192-168-1-90-1/netflix/titus-executor/executor/runtime/docker/docker.go:2835 +0x310
github.com/Netflix/titus-executor/executor/runner.(*Runner).doShutdown(0xc000432dc0, 0x163bd10, 0xc000938390, 0x1, 0xc000b821e0, 0x1d, 0xc0005e4710)
/var/lib/buildkite-agent/builds/ip-192-168-1-90-1/netflix/titus-executor/executor/runner/runner.go:326 +0x4f4
github.com/Netflix/titus-executor/executor/runner.(*Runner).startRunner(0xc000432dc0, 0x163bdb8, 0xc00071e0c0, 0xc0a502e28c08b488, 0x24572b8, 0x1df5980)
/var/lib/buildkite-agent/builds/ip-192-168-1-90-1/netflix/titus-executor/executor/runner/runner.go:122 +0x391
created by github.com/Netflix/titus-executor/executor/runner.StartTaskWithRuntime
/var/lib/buildkite-agent/builds/ip-192-168-1-90-1/netflix/titus-executor/executor/runner/runner.go:81 +0x411Здесь наш сервис (management engine) выполняет HTTP-вызов к unix-сокету Docker API с просьбой уничтожить (kill) контейнер. Наши контейнеры настроены на уничтожение через SIGKILL. Но kill (SIGKILL) должен быть фатальным, а здесь контейнер что-то еще продолжает делать?
$ docker exec -it 6643cd073492 bash
OCI runtime exec failed: exec failed: container_linux.go:380: starting container process caused: process_linux.go:130: executing setns process caused: exit status 1: unknownСтранно. Вроде бы контейнер еще жив, но setns(2) завершается ошибкой. Что же происходит? Если мы посмотрим на дерево процессов через ps awwfux, то увидим следующее:
\_ containerd-shim -namespace moby -workdir /var/lib/containerd/io.containerd.runtime.v1.linux/moby/6643cd073492ba9166100ed30dbe389ff1caef0dc3d35
| \_ [docker-init]
| \_ [ndrive] Итак, процесс init контейнера все еще жив, но у него есть один дочерний зомби. Чем может быть занят init процесс контейнера?
# cat /proc/1528591/stack
[<0>] do_wait+0x156/0x2f0
[<0>] kernel_wait4+0x8d/0x140
[<0>] zap_pid_ns_processes+0x104/0x180
[<0>] do_exit+0xa41/0xb80
[<0>] do_group_exit+0x3a/0xa0
[<0>] __x64_sys_exit_group+0x14/0x20
[<0>] do_syscall_64+0x37/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xaeОн находится в процессе завершения, но, похоже, завис, и единственный дочерний процесс ndrive — в состоянии Z («зомби»). Зомби — это процессы, которые успешно завершились и ожидают, когда родительский процесс считает их код завершения с помощью системного вызова wait(). Но как же ядро могло застрять в ожидании зомби?
# ls /proc/1544450/task
1544450 1544574Интересно. В группе потока есть два потока. Один из них зомби, а другой, возможно, нет:
# cat /proc/1544574/stack
[<0>] request_wait_answer+0x12f/0x210
[<0>] fuse_simple_request+0x109/0x2c0
[<0>] fuse_flush+0x16f/0x1b0
[<0>] filp_close+0x27/0x70
[<0>] put_files_struct+0x6b/0xc0
[<0>] do_exit+0x360/0xb80
[<0>] do_group_exit+0x3a/0xa0
[<0>] get_signal+0x140/0x870
[<0>] arch_do_signal_or_restart+0xae/0x7c0
[<0>] exit_to_user_mode_prepare+0x10f/0x1c0
[<0>] syscall_exit_to_user_mode+0x26/0x40
[<0>] do_syscall_64+0x46/0xb0
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xaeДействительно, второй — не зомби. Но он изо всех сил пытается им стать, и по какой-то причине, блокируется внутри FUSE. Чтобы выяснить причину, давайте взглянем на код функции zap_pid_ns_processes (), в которой и застряли:
/*
* Reap the EXIT_ZOMBIE children we had before we ignored SIGCHLD.
* kernel_wait4() will also block until our children traced from the
* parent namespace are detached and become EXIT_DEAD.
*/
do {
clear_thread_flag(TIF_SIGPENDING);
rc = kernel_wait4(-1, NULL, __WALL, NULL);
} while (rc != -ECHILD);Но перед этим выполняется:
/* Don't allow any more processes into the pid namespace */
disable_pid_allocation(pid_ns);Поэтому докер и не может выполнить setns(), так как пространство имен (namespace) — зомби. Хорошо, мы не можем выполнить setns(2), но почему мы застряли в kernel_wait4()? Чтобы найти причину, давайте посмотрим, что делал другой поток в методе request_wait_answer () FUSE:
/*
* Either request is already in userspace, or it was forced.
* Wait it out.
*/
wait_event(req->waitq, test_bit(FR_FINISHED, &req->flags));Здесь мы ждем события (в этом случае ответа из пользовательского пространства об обработке запроса сброса на диск (flush) от FUSE). Но zap_pid_ns_processes() отправил SIGKILL! Сигнал SIGKILL должен быть фатальным для процесса. Если мы посмотрим на процесс, то действительно увидим, что есть ожидающий (pending) сигнал SIGKILL:
# grep Pnd /proc/1544574/status
SigPnd: 0000000000000000
ShdPnd: 0000000000000100В ShdPnd можно увидеть 0×100 (т. е. установлен 9-й бит), что соответствует SIGKILL.
Ожидающие (pending) сигналы — это сигналы, сгенерированные ядром, но еще не доставленные в пользовательское пространство. Сигналы доставляются только в определенное время, например, при входе или выходе из системного вызова или при ожидании событий. Если ядро в данный момент чем-то занято, сигнал может находиться в ожидании (pending). Также сигналы могут быть заблокированы задачей, и они никогда не будут доставлены. Заблокированные сигналы будут отображаться в соответствующих наборах. Однако в man 7 signal сказано: «Сигналы SIGKILL и SIGSTOP не могут быть пойманы, блокированы или проигнорированы». Но здесь ядро говорит, что есть ожидающий сигнал SIGKILL, который игнорируется, даже во время ожидания задачи!
Ложный след: как работают сигналы?
Все это очень странно, учитывая, что wait (т. е. include/linux/wait.h) используется в ядре повсюду: семафоры, очереди ожидания, завершения и т. д. Разумеется, он знает о SIGKILL. Давайте разбираться, что же на самом деле делает wait_event()? Покопавшись в коде, я нашел следующее:
#define ___wait_event(wq_head, condition, state, exclusive, ret, cmd) \
({ \
__label__ __out; \
struct wait_queue_entry __wq_entry; \
long __ret = ret; /* explicit shadow */ \
\
init_wait_entry(&__wq_entry, exclusive ? WQ_FLAG_EXCLUSIVE : 0); \
for (;;) { \
long __int = prepare_to_wait_event(&wq_head, &__wq_entry, state);\
\
if (condition) \
break; \
\
if (___wait_is_interruptible(state) && __int) { \
__ret = __int; \
goto __out; \
} \
\
cmd; \
} \
finish_wait(&wq_head, &__wq_entry); \
__out: __ret; \
})В бесконечном цикле сначала выполняется prepare_to_wait_event(), потом проверяется condition, а после — проверка должны ли мы прерваться. После всех условий выполняется cmd, в данном случае schedule(), т.е. «займись чем-нибудь другим на некоторое время». Функция prepare_to_wait_event() выглядит следующим образом:
long prepare_to_wait_event(struct wait_queue_head *wq_head, struct wait_queue_entry *wq_entry, int state)
{
unsigned long flags;
long ret = 0;
spin_lock_irqsave(&wq_head->lock, flags);
if (signal_pending_state(state, current)) {
/*
* Exclusive waiter must not fail if it was selected by wakeup,
* it should "consume" the condition we were waiting for.
*
* The caller will recheck the condition and return success if
* we were already woken up, we can not miss the event because
* wakeup locks/unlocks the same wq_head->lock.
*
* But we need to ensure that set-condition + wakeup after that
* can't see us, it should wake up another exclusive waiter if
* we fail.
*/
list_del_init(&wq_entry->entry);
ret = -ERESTARTSYS;
} else {
if (list_empty(&wq_entry->entry)) {
if (wq_entry->flags & WQ_FLAG_EXCLUSIVE)
__add_wait_queue_entry_tail(wq_head, wq_entry);
else
__add_wait_queue(wq_head, wq_entry);
}
set_current_state(state);
}
spin_unlock_irqrestore(&wq_head->lock, flags);
return ret;
}
EXPORT_SYMBOL(prepare_to_wait_event);Похоже, что единственный выход из этой ситуации с ненулевым кодом возврата — если signal_pending_state() будет true. Поскольку данную функцию вызвали из wait_event(), мы знаем, что состояние здесь TASK_UNINTERRUPTIBLE. Определение signal_pending_state() выглядит следующим образом:
static inline int signal_pending_state(unsigned int state, struct task_struct *p)
{
if (!(state & (TASK_INTERRUPTIBLE | TASK_WAKEKILL)))
return 0;
if (!signal_pending(p))
return 0;
return (state & TASK_INTERRUPTIBLE) || __fatal_signal_pending(p);
}Наша задача непрерываемая, поэтому первый if не сработает. Однако у нашей задачи должен быть ожидающий сигнал, верно?
static inline int signal_pending(struct task_struct *p)
{
/*
* TIF_NOTIFY_SIGNAL isn't really a signal, but it requires the same
* behavior in terms of ensuring that we break out of wait loops
* so that notify signal callbacks can be processed.
*/
if (unlikely(test_tsk_thread_flag(p, TIF_NOTIFY_SIGNAL)))
return 1;
return task_sigpending(p);
}Как отмечено в комментарии, TIF_NOTIFY_SIGNAL здесь не важен несмотря на свое название. Давайте посмотрим на task_sigpending():
static inline int task_sigpending(struct task_struct *p)
{
return unlikely(test_tsk_thread_flag(p,TIF_SIGPENDING));
}Хм. Кажется, этот флаг должен быть установлен, верно? Чтобы убедиться, давайте посмотрим, как работает доставка сигналов. Когда мы закрываем пространство имен pid в zap_pid_ns_processes(), происходит следующее:
group_send_sig_info(SIGKILL, SEND_SIG_PRIV, task, PIDTYPE_MAX);Что в итоге приводит к функции __send_signal_locked(), в которой есть:
pending = (type != PIDTYPE_PID) ? &t->signal->shared_pending : &t->pending;
...
sigaddset(&pending->signal, sig);
...
complete_signal(sig, t, type);Использовать в качестве типа PIDTYPE_MAX немного странно, но, по сути, здесь говорится: «это очень привилегированная часть ядра, отправляющая данный сигнал, и вы должны обязательно его доставить». Здесь также есть небольшое неожиданное последствие, заключающееся в том, что __send_signal_locked() в итоге отправляет SIGKILL в общий набор (shared set), а не в набор конкретной задачи. И если мы посмотрим на код __fatal_signal_pending(), то увидим:
static inline int __fatal_signal_pending(struct task_struct *p)
{
return unlikely(sigismember(&p->pending.signal, SIGKILL));
}Это ложный след (но мне потребовалось время, чтобы понять это).
Как сигналы на самом деле доставляются процессу
Чтобы понять, что на самом деле здесь происходит, нужно взглянуть на функцию complete_signal(), поскольку она безусловно добавляет SIGKILL в набор ожидающих сигналов задачи (task«s pending set):
sigaddset(&t->pending.signal, SIGKILL);Но почему это не работает? В начале функции есть следующее:
/*
* Now find a thread we can wake up to take the signal off the queue.
*
* If the main thread wants the signal, it gets first crack.
* Probably the least surprising to the average bear.
*/
if (wants_signal(sig, p))
t = p;
else if ((type == PIDTYPE_PID) || thread_group_empty(p))
/*
* There is just one thread and it does not need to be woken.
* It will dequeue unblocked signals before it runs again.
*/
return;Как пояснил Эрик Бидерман (Eric Biederman), в принципе, каждый поток может обработать SIGKILL в любое время. Вот код wants_signal():
static inline bool wants_signal(int sig, struct task_struct *p)
{
if (sigismember(&p->blocked, sig))
return false;
if (p->flags & PF_EXITING)
return false;
if (sig == SIGKILL)
return true;
if (task_is_stopped_or_traced(p))
return false;
return task_curr(p) || !task_sigpending(p);
}Итак… если поток уже завершается (т. е. у него есть PF_EXITING), ему не нужно обрабатывать еще один сигнал завершения.
Давайте рассмотрим следующую последовательность событий:
1. Задача открывает файл, используя FUSE, не закрывает его, и завершает работу. Во время этого завершения ядро послушно вызывает функцию do_exit(), в которой выполняется:
exit_signals(tsk); /* sets PF_EXITING */2. do_exit() выполняется до exit_files(tsk), где сбрасываются (flush) все открытые файлы, в результате чего появляется приведенная выше трассировка стека.
3. Пространство имен pid завершает работу, вызывается zap_pid_ns_processes(), всем отправляется SIGKILL (который, как ожидается, будет фатальным), а дальше — ожидание завершения работы всех процессов.
4. Это убивает демона FUSE в pid ns, поэтому он уже не сможет ответить.
5. complete_signal() для задачи FUSE, которая уже завершилась, игнорирует сигнал, т.к. у него есть PF_EXITING.
6. Дедлок. Без ручного прерывания подключения к FUSE, все будет висеть бесконечно.
Решение: не ждите!
В этом случае нет смысла ждать сброса (flush): задача умирает, поэтому некому сообщить код возврата flush(). Эта ошибка может возникнуть и с другими файловыми системами, которые вызывают код wait ядра во flash(), т. е. практически со всеми, кто обращается к чему-то за пределами локального ядра.
Тем временем для некоторых файловых систем уже вышли патчи, например, здесь находится исправление для FUSE, которое включено в ядро Linux 6.3, выпущенное 23 апреля 2023 года.
В этой статье была речь о дедлоке FUSE, но определенно проблемы есть и в коде nfs и в других местах, с которыми мы еще не столкнулись в продакшене, но почти наверняка столкнемся. Также описанное поведение может быть симптомом других ошибок файловой системы. На это стоит обратить внимание, если у вас есть пространство имен pid, которое не завершается.
Это всего лишь один из примеров странных проблем, с которыми мы сталкиваемся в Netflix, активно используя контейнеры в больших масштабах.
В завершение приглашаем всех желающих на открытый урок OTUS «Инфраструктура как код, ansible, terraform», который пройдет уже сегодня вечером. Записаться можно здесь.
