Context deadline exceeded ошибка

Context Deadline Exceeded is an error occurring in Go when a context of an HTTP request has a deadline or a timeout set, i.e., the time after which the request should abort. This error is returned if the time of a server response is greater than the set timeout. Setting timeouts on requests is a good practice in a production environment to ensure that you always get a response (or error) in a finite time.

Context deadline exceeded example

    package main

    import (
        "context"
        "errors"
        "log"
        "net/http"
        "os"
        "time"
    )

    func slowServer(w http.ResponseWriter, r *http.Request) {
        time.Sleep(10 * time.Second)
        w.Write([]byte("Hello world!"))
    }

    func call() error {
        client := &http.Client{}
        req, err := http.NewRequest(http.MethodGet, "http://localhost:8080", nil)
        if err != nil {
            return err
        }
        ctx, cancel := context.WithTimeout(req.Context(), 1*time.Second)
        defer cancel()
        req = req.WithContext(ctx)
        _, err = client.Do(req)
        return err
    }

    func main() {
        // run slow server
        go func() {
            http.HandleFunc("/", slowServer)

            if err := http.ListenAndServe(":8080", nil); err != nil {
                log.Fatal(err)
            }
        }()

        time.Sleep(1 * time.Second) // wait for server to run

        // call server
        err := call()
        if errors.Is(err, context.DeadlineExceeded) {
            log.Println("ContextDeadlineExceeded: true")
        }
        if os.IsTimeout(err) {
            log.Println("IsTimeoutError: true")
        }
        if err != nil {
            log.Fatal(err)
        }
    }

Output:

2021/08/19 06:39:09 ContextDeadlineExceeded: true
2021/08/19 06:39:09 IsTimeoutError: true
2021/08/19 06:39:09 Get "http://localhost:8080": context deadline exceeded
exit status 1

In the example above, we:

• run our slow server, whose task is to return a response after 10 seconds
• create a new request in the call() function, which will be sent to the server
• set a timeout of 1 second on this request, i.e., the value of time after the waiting for the server response is interrupted
• send the request to the server

Since a timeout for this request is set to 1 second and the server responds after 10 seconds, the HTTP client returns an error.

Handle Context deadline exceeded error

An HTTP client returns the context.DeadlineExceeded error when the set timeout is exceeded. This error can also be handled with the more general os.IsTimeout() function that checks if the error is known to report that a timeout occurred.

The timeout can be set not only at the level of a single HTTP request but also at the level of the entire HTTP client. In this case, each request made by such a client has the same timeout value. See the example of a call() function using the client timeout option:

func call() error {
    client := &http.Client{Timeout: 1 * time.Second}
    _, err := client.Get("http://localhost:8080")
    return err
}

Output:

2021/08/19 07:35:14 IsTimeoutError: true
2021/08/19 07:35:14 Get "http://localhost:8080": context deadline exceeded (Client.Timeout exceeded while awaiting headers)
exit status 1

In this case, we get the context deadline exceeded (Client.Timeout exceeded while awaiting headers) error. Note that this is not an instance of context.DeadlineExceeded error.

Wondering how to resolve Kubernetes error “context deadline exceeded”? We can help you.

As part of our Server Management Services, we assist our customers with several Kubernetes queries.

Today, let us see how our Support techs proceed to resolve it.

How to resolve Kubernetes error “context deadline exceeded”?

The error ‘context deadline exceeded’ means that we ran into a situation where a given action was not completed in an expected timeframe.

Usually, issue occurs if Pods become stuck in Init status.

Typical error will look as shown below:

Warning FailedCreatePodSandBox 93s (x8 over 29m) kubelet, 97011e0a-f47c-4673-ace7-d6f74cde9934 Failed to create pod sandbox: rpc error: code = DeadlineExceeded desc = context deadline exceeded Normal SandboxChanged 92s (x8 over 29m) kubelet, 97011e0a-f47c-4673-ace7-d6f74cde9934 Pod sandbox changed, it will be killed and re-created.

You would see errors for containers from kubelet.stderr.log.

Example:

E0114 14:57:13.656196 9838 remote_runtime.go:128] StopPodSandbox "ca05be4d6453ae91f63fd3f240cbdf8b34377b3643883075a6f5e05001d3646b" from runtime service failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
...
E0114 14:57:13.656256 9838 kuberuntime_manager.go:901] Failed to stop sandbox {"docker" "ca05be4d6453ae91f63fd3f240cbdf8b34377b3643883075a6f5e05001d3646b"}
...
W0114 14:57:30.151650 9838 cni.go:331] CNI failed to retrieve network namespace path: cannot find network namespace for the terminated container "ca05be4d6453ae91f63fd3f240cbdf8b34377b3643883075a6f5e05001d3646b"

You can also validate the status of the node-agent-hyperbus by running the following nsxcli command from the node (as root):

sudo -i

/var/vcap/jobs/nsx-node-agent/bin/nsxcli

“at the nsx-cli prompt, enter”: get node-agent-hyperbus status

Expected output:

HyperBus status: Healthy

In this scenario you would see the following error instead:

% An internal error occurred

This causes a loop of DEL (delete) requests to the nsx-node-agent process

Today, let us see the simple steps followed by our Support techs to resolve it.

Restarting the nsx-node-agent process will workaround this issue:

— Use “bosh ssh” command to access the worker node

Then, run the below commands.

sudo -i

monit restart nsx-node-agent

— Wait for nsx-node-agent to restart: watch monit summary

This must resolve the issue.

[Stuck in between? We’d be glad to assist you]

Conclusion

In short, today we saw steps followed by our Support Techs resolve Kubernetes failed to start in docker desktop error.

Время на прочтение
5 мин

Количество просмотров 9.4K

Привет, меня зовут Иван, я занимаюсь бэкенд-разработкой в Ozon — пишу микросервисы для личного кабинета продавца. Сегодня я расскажу небольшую историю проблемы, вызванную неправильной настройкой пула соединений: что случилось, как мы это обнаружили и как исправлять такие проблемы в микросервисах на Go.

Проблема скрывалась внутри нашего API Gateway. Это сервис, который реализует паттерн “Фасад” и предоставляет единственное торчащее наружу окно к микросервисам.

В упрощенном виде его работу можно представить так:

1. Проверить аутентификацию и авторизацию с помощью HTTP-запроса в сервис аутентификации

2. Спроксировать запрос в нужный сервис, который определяем по пути и методу запроса пользователя

Конец декабря – время роста нагрузок и числа ошибок

Настал конец декабря. Вместе с ним к нам в поддержку стали приходить вот такие обращения:

При работе в ЛК возникают постоянные ошибки системные по 10-20 раз на дню и больше. Просьба исправить и наладить работу площадки.

Ошибки возникали на стороне API Gateway. Мы полезли в логи за подробностями и увидели ошибки, похожие на таймауты обращения к сервису аутентификацию:

{err_type: context.deadlineExceededError, err: context deadline exceeded}
{err_type: *errors.errorString, err: context canceled}

Трейсы в Jaeger показали ровно такую же картину — мы не дожидались ответа от сервиса аутентификации за 2 секунды. Поэтому между нами и разработчиками сервиса аутентификации произошёл примерно такой диалог:

— Ребята, кажется, вы таймаутите. Вот трейс, на котором видно, что мы не дождались от вас ответа за 2 секунды.

— Ничего подобного, у нас все норм — мы за 200 миллисекунд отвечаем в 99% запросов. А вот вы по какой-то причине часто преждевременно обрываете соединение.

В качестве подтверждения своей правоты, разработчики сервиса аутентификации скинули нам скриншот логов. На нём видно много ошибок об отмене запроса со стороны вызывающей стороны:

Итого, мы имеем:

1. Используемый нами сервис аутентификации стабильно отрабатывает за 200 миллисекунд.

2. Многие наши обращения к этому сервису таймаутят за 2 секунды.

Причина проблемы: дефолтные настройки в Go

В это время один из авторов нашего API Gateway отметил, что очень давно заметил аномалию: сервис открывает неожиданно много соединений к удаленным портам. При запуске команды из-под контейнера видно:

$ ss -natp state time-wait | awk '{print $4}' | sort -nr | uniq -c | sort -nr | head

1053 10.20.49.117:80
1030 10.20.49.92:80
1016 10.20.49.91:80
1014 10.20.54.129:80
1013 10.20.53.213:80
1008 10.20.53.173:80
969 10.20.53.172:80

Эта команда показывает количество TCP-сокетов в состоянии TIME_WAIT до разных удалённых портов. Если коротко, то состояние TIME_WAIT — это де-факто закрытое клиентом соединение. Linux по возможности предотвращает повторное использование этих пар на протяжении 60 секунд, чтобы защититься от того, что старые пакеты помешают вновь установленному TCP-соединению.

Но для нас важно другое. Само существование TCP-соединения означает, что соединение установилось и закрылось. Если такая ситуация происходит массово, то мы имеем дело с накладными расходами на DNS-резолвинг и установку соединения. В результате этого время HTTP-запроса может увеличиваться. Избежать эту проблему помогают пулы соединений. В Go для этой цели используется абстракция http.Transport.

Здесь мы вплотную приближаемся к истокам проблемы. Мы для всех клиентских запросов использовали http.DefaultTransport. Он обладает следующими параметрами:

var DefaultTransport RoundTripper = &Transport{
    Proxy: ProxyFromEnvironment,
    DialContext: (&net.Dialer{
        Timeout:   30 * time.Second,
        KeepAlive: 30 * time.Second,
    }).DialContext,
    ForceAttemptHTTP2:     true,
    MaxIdleConns:          100,
    IdleConnTimeout:       90 * time.Second,
    TLSHandshakeTimeout:   10 * time.Second,
    ExpectContinueTimeout: 1 * time.Second,
}

Среди перечисленных выше параметров к настройке пула соединений имеют отношения два:

• MaxIdleConns — число соединений, которое разрешается иметь в состоянии Idle (т.е. открытых TCP-соединений, которые в данный момент не используются);

• IdleConnTimeout — время, через которое закрываются такие неактивные соединения.

Однако в DefaultTransport совершенно не указан другой ключевой параметр — MaxIdleConnsPerHost. Он отвечает за то, сколько неактивных TCP-соединений допускается устанавливать на один хост. ​

При этом если MaxIdleConnsPerHost не указан, тогда используется значение по умолчанию:

const DefaultMaxIdleConnsPerHost = 2

Поскольку мы использовали именно http.DefaultTransport для всех запросов, мы получили следующую проблему.

Представим, что нам одновременно понадобилось установить 10 соединений до сервиса аутентификации. Тогда хотя бы для 8 из них будут открыты и вскоре тут же закрыты TCP-соединения, из-за ограничения MaxIdleConnsPerHost. Если такая ситуация будет повторяться часто, у нас будет больше накладных расходов на один HTTP-запрос, поскольку для него понадобится новое соединение. Из-за этого вероятность таймаутов возрастает.

Решение: отдельный транспорт с особенными настройками

Чтобы решить проблему, мы сделали следующее:

• Выделили отдельный транспорт под сервисы аутентификации и авторизации, чтобы транспорт под сервис аутентификации не вытеснял остальные сервисы.

• Утилизировали выделенный пул на полную — сделали так, чтобы значение MaxIdleConnsPerHost соответствовало значению MaxIdleConns:

func createOneHostTransport() *http.Transport {
    result := http.DefaultTransport.(*http.Transport).Clone()

    result.MaxIdleConnsPerHost = result.MaxIdleConns

    return result
}

Тут видно значительное уменьшение 0.99-квантиля по времени обращения графиков (голубой цвет) — с 2-3 секунд до менее 300 миллисекунд. Должен признать, даже после этого мы изредка видели таймауты при обращении к сервису аутентификации. Но теперь мы хотя бы видели эти же таймауты на графиках другого сервиса.

Но почему в Go такие настройки по умолчанию?

Возможно, у вас сейчас возник вопрос: зачем делать такие настройки, которые потом приходится исправлять? Неужели разработчики языка Go и библиотек к нему не подумали о том, как это будет использоваться на практике?

Я считаю так: настройки по умолчанию имеют смысл в том случае, когда мы имеем дело с множеством хостов и не очень большим числом запросов. В таком случае значение MaxIdleConnsPerHost предохраняет нас от того, чтобы в ситуации всплеска запросов один из хостов исчерпал оставшийся ресурс свободных соединений и не позволил другому сервису создать хотя бы одно долгоживущее соединение.

Если бы приложения могли говорить…

Чтобы лучше понять предназначение параметра MaxIdleConnsPerHost, представим, что компоненты системы научились говорить друг с другом. Тогда если бы мы выставили значение MaxIdleConnsPerHost равным MaxIdleConns, между нашим приложением и пулом соединений мог бы произойти такой диалог:

Приложение: http.Transport, привет! Нам тут сотня пользователей пришла одновременно и им всем вдруг срочно понадобилось посмотреть инфу о своём профиле. Установи, пожалуйста, сотню соединений к user-service ​​

http.Transport: Конечно, вот – получи сотню установленных соединений под запросы! Но я их не буду ещё полторы минуты закрывать, вдруг пригодятся ​.

Приложение: Всё сработало, спасибо! Только вот теперь им всем вдруг захотелось посмотреть информацию о товаре. Пожалуйста, установи соединение с product-service.

http.Transport: Да, не вопрос – держи. Но только я их у себя в пуле соединений хранить не буду, поскольку он уже полностью забит соединениями до user-service, которые тебе больше не нужны.

Приложение: ​​(┛ಠ_ಠ)┛彡┻━┻ ​

Разбираемся с непонятными таймаутами в Go: чеклист

Если вдруг вы сталкиваетесь с непонятными таймаутами, попробуйте следующее:

1. Проверьте метрики по скорости выполнения запросов к сторонним сервисам по HTTP. Если таких метрик нет, заведите – пригодятся.

2. Если видите расхождения в таймаутах клиента и сервера, проверьте количество соединений TIME_WAIT.

3. Если вы обнаружили много соединений в состоянии TIME_WAIT, это с высокой вероятностью означает, что пул соединений настроен неверно. Обратите внимание на то, что настройки по умолчанию в Go не очень хорошо подходят под большое количество запросов к ограниченному набору сервисов.

4. Для хоста с неоправданно большим числом запросов к нему рассмотрите вариант заведения отдельного транспорта.

Что ещё почитать по теме

• Gotchas in the Go Network Packages Defaults: какие ещё подводные камни есть в настройках сети в Golang;

• Coping with the TCP TIME-WAIT state on busy Linux servers: подробнее о TIME_WAIT и зачем оно нужно;

• демо на Github: наглядно об описанной проблеме в миниатюре