[Перевод] Отладка дедлока FUSE в ядре Linux

8b5f05a71b59f7e2280693a09c5f498c.jpeg

Наша команда вычислительных ресурсов 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», который пройдет уже сегодня вечером. Записаться можно здесь.

© Habrahabr.ru