GRPC. Не обрабатывается 5xx от upstream

Добрый день!
Какая то странная история, не могу настроить нормально балансировку на grpc, хотя вроде все, что есть в документации, опробовал.
Итак, простая схема, где балансировка работает. Работает - означает, если один из серверов на апстриме недоступен, он исключается из балансировки.
В качестве grpc-сервисов обычный example helloworld(grpc-go/examples/helloworld/greeter_server at master · grpc/grpc-go · GitHub), модифицированные так, чтобы при обращении отвечать “{ “message”: “hello_01” }” и “{ “message”: “hello_02” }” в зависимости от номера порта.
balancer-age - ВМ c установленным angie 1.8.1.
Вот его конфиг

upstream grpc_upstream {
  server        192.168.100.11:30001 max_fails=1 fail_timeout=15s;
  server        192.168.100.11:30002 max_fails=1 fail_timeout=15s;
}

server {
       listen                                 80;
       http2                                  on;
       server_name                            angie.home.local;
       gzip                                   off;
       charset                                utf-8;
       large_client_header_buffers            8 256k;

       location / {
         grpc_buffer_size       256k;
         grpc_next_upstream     error timeout invalid_header http_504 http_503 http_502 http_500;
         grpc_set_header        X-Real-IP $remote_addr;
         grpc_set_header        X-Forwarded-For $remote_addr;
         grpc_set_header        X-Forwarded-Host $host;
         grpc_intercept_errors on;
         grpc_pass_header       Set-Cookie;
         grpc_pass              grpc://grpc_upstream;
       }
}

Теперь, если мы отключим любой из двух сервисов, балансировка отработает как надо, и в /var/log/angie/error.log будет залоггировано событие недоступности апстрима.

2025/02/01 11:46:59 [error] 4166#4166: *108 connect() failed (111: Connection refused) while connecting to upstream, client: 192.168.100.11, server: angie.home.local, request: "POST /helloworld.Greeter/SayHello HTTP/2.0", upstream: "grpc://192.168.100.11:30001", host: "angie.home.local:80"
2025/02/01 11:46:59 [warn] 4166#4166: *108 upstream server temporarily disabled while connecting to upstream, client: 192.168.100.11, server: angie.home.local, request: "POST /helloworld.Greeter/SayHello HTTP/2.0", upstream: "grpc://192.168.100.11:30001", host: "angie.home.local:80"

При этом клиенту мы не покажем, что у нас сервис упал, весь трафик плавно уйдет на другой сервер из апстрима.
Усложним нашу простую схему.


Теперь перед grpc-svc-1 еще один прокси, на nginx.(представим, что это например ингресс контроллер)
Модифицируем конфиг balancer-angie

upstream grpc_upstream {
  server        192.168.100.30:8080 max_fails=1 fail_timeout=15s;
  #server        192.168.100.11:30001 max_fails=1 fail_timeout=15s;
  server        192.168.100.11:30002 max_fails=1 fail_timeout=15s;
}

server {
       listen                                 80;
       http2                                  on;
       server_name                            angie.home.local;
       gzip                                   off;
       charset                                utf-8;
       large_client_header_buffers            8 256k;


       location / {
         grpc_buffer_size       256k;
         grpc_next_upstream     error timeout invalid_header http_504 http_503 http_502 http_500;
         grpc_set_header        X-Real-IP $remote_addr;
         grpc_set_header        X-Forwarded-For $remote_addr;
         grpc_set_header        X-Forwarded-Host $host;
         grpc_pass_header       Set-Cookie;
         grpc_pass              grpc://grpc_upstream;
       }
}

Теперь, если мы выключаем grpc-svc-1, то nginx-proxy grpc-proxy-01 честно отдает 502(вот его логи, 502 как 502).

192.168.100.29 - - [01/Feb/2025:12:02:06 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" "grpcurl/v1.9.1 grpc-go/1.61.0"
192.168.100.29 - - [01/Feb/2025:12:02:08 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" "grpcurl/v1.9.1 grpc-go/1.61.0"
192.168.100.29 - - [01/Feb/2025:12:02:10 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" "grpcurl/v1.9.1 grpc-go/1.61.0"

Если верить документации gRPC, то директива “grpc_next_upstream error timeout invalid_header http_504 http_503 http_502 http_500;” должна перенаправлять запрос на оставшийся рабочий балансер, и исключать grpc-svc-1 из балансировки.
Но этого не происходит. Каждый второй запрос возвращает ошибку.

tail -f /var/log/angie/access.log
192.168.100.11 - - [01/Feb/2025:12:02:06 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" "grpcurl/v1.9.1 grpc-go/1.61.0" "-"
192.168.100.11 - - [01/Feb/2025:12:02:07 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 15 "-" "grpcurl/v1.9.1 grpc-go/1.61.0" "-"
192.168.100.11 - - [01/Feb/2025:12:02:08 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" "grpcurl/v1.9.1 grpc-go/1.61.0" "-"
192.168.100.11 - - [01/Feb/2025:12:02:09 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 15 "-" "grpcurl/v1.9.1 grpc-go/1.61.0" "-"
192.168.100.11 - - [01/Feb/2025:12:02:10 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" "grpcurl/v1.9.1 grpc-go/1.61.0" "-"
192.168.100.11 - - [01/Feb/2025:12:02:11 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 15 "-" "grpcurl/v1.9.1 grpc-go/1.61.0" "-"

В логах angie error.log следующее(тишина)

tail -f /var/log/angie/error.log
2025/02/01 11:54:39 [notice] 4191#4191: signal 17 (SIGCHLD) received from 4192
2025/02/01 11:54:39 [notice] 4191#4191: worker process 4192 exited with code 0
2025/02/01 11:54:39 [notice] 4191#4191: exit
2025/02/01 11:54:39 [notice] 4211#4211: using the "epoll" event method
2025/02/01 11:54:39 [notice] 4211#4211: Angie/1.8.1
2025/02/01 11:54:39 [notice] 4211#4211: OS: Linux 6.1.0-30-amd64
2025/02/01 11:54:39 [notice] 4211#4211: getrlimit(RLIMIT_NOFILE): 1024:524288
2025/02/01 11:54:39 [notice] 4213#4213: start worker processes
2025/02/01 11:54:39 [notice] 4213#4213: start worker process 4214
2025/02/01 11:54:39 [notice] 4213#4213: start worker process 4215

Собственно, grpccurl

grpcurl --plaintext --proto helloworld.proto angie.home.local:80 helloworld.Greeter/SayHello
ERROR:
  Code: Unavailable
  Message: unexpected HTTP status code received from server: 502 (Bad Gateway); transport: received unexpected content-type "text/html; charset=utf-8"

В логах access.log angie 502 отдается клиенту.
Вопрос - это я что то упускаю в настройке(вроде внимательно читал доку, но все возможно), или же это какое то незадокументированное поведение?

Если включить extended логгирование, то лог angie приобретет вид

tail -f /var/log/angie/access.log
192.168.100.11 - - [01/Feb/2025:13:25:40 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" rt="0.000" "grpcurl/v1.9.1 grpc-go/1.61.0" "-" h="angie.home.local" sn="angie.home.local" ru="/helloworld.Greeter/SayHello" u="/helloworld.Greeter/SayHello" ucs="-" ua="192.168.100.30:8080" us="502" uct="0.001" urt="0.001"
192.168.100.11 - - [01/Feb/2025:13:25:41 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 15 "-" rt="0.001" "grpcurl/v1.9.1 grpc-go/1.61.0" "-" h="angie.home.local" sn="angie.home.local" ru="/helloworld.Greeter/SayHello" u="/helloworld.Greeter/SayHello" ucs="-" ua="192.168.100.11:30002" us="200" uct="0.000" urt="0.000"
192.168.100.11 - - [01/Feb/2025:13:25:42 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" rt="0.001" "grpcurl/v1.9.1 grpc-go/1.61.0" "-" h="angie.home.local" sn="angie.home.local" ru="/helloworld.Greeter/SayHello" u="/helloworld.Greeter/SayHello" ucs="-" ua="192.168.100.30:8080" us="502" uct="0.000" urt="0.001"
192.168.100.11 - - [01/Feb/2025:13:25:43 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 15 "-" rt="0.001" "grpcurl/v1.9.1 grpc-go/1.61.0" "-" h="angie.home.local" sn="angie.home.local" ru="/helloworld.Greeter/SayHello" u="/helloworld.Greeter/SayHello" ucs="-" ua="192.168.100.11:30002" us="200" uct="0.000" urt="0.000"
192.168.100.11 - - [01/Feb/2025:13:25:44 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" rt="0.000" "grpcurl/v1.9.1 grpc-go/1.61.0" "-" h="angie.home.local" sn="angie.home.local" ru="/helloworld.Greeter/SayHello" u="/helloworld.Greeter/SayHello" ucs="-" ua="192.168.100.30:8080" us="502" uct="0.001" urt="0.001"
192.168.100.11 - - [01/Feb/2025:13:25:45 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 200 15 "-" rt="0.001" "grpcurl/v1.9.1 grpc-go/1.61.0" "-" h="angie.home.local" sn="angie.home.local" ru="/helloworld.Greeter/SayHello" u="/helloworld.Greeter/SayHello" ucs="-" ua="192.168.100.11:30002" us="200" uct="0.000" urt="0.000"
192.168.100.11 - - [01/Feb/2025:13:25:46 +0300] "POST /helloworld.Greeter/SayHello HTTP/2.0" 502 157 "-" rt="0.000" "grpcurl/v1.9.1 grpc-go/1.61.0" "-" h="angie.home.local" sn="angie.home.local" ru="/helloworld.Greeter/SayHello" u="/helloworld.Greeter/SayHello" ucs="-" ua="192.168.100.30:8080" us="502" uct="0.000" urt="0.001"

Также пробовал выставлять параметр non_idempotent для grpc_next_upstream, каких либо изменений не привнесло

Тут имеет место быть сразу две проблемы:

  1. Не происходит переключение на другой сервер и повторная попытка. В GRPC, если данные с телом были отправлены на бекенд и начато чтение ответа, то переключиться в принципе невозможно, т.к. протокол потоковый и из-за этого буферизация всего запроса отключена. Она невозможна, т.к. обычно неизвестен размер запроса и он в принципе может быть бесконечно длинным.

  2. Сервер не помечается как неработающий. Это известная проблема, которую, к сожалению, Angie унаследовал от nginx. В nginx про это есть открытый тикет, которому уже 4 года: #2060 (Nginx doesn't take case http_502 as unsuccessful attempt in ngx_http_grpc_module) – nginx

Спасибо за Ваш ответ, Валентин! Подскажите, пожалуйста, а в бэклоге нет планов по решению данной проблемы?

Рано или поздно мы это исправим. Но в ближайшее время вряд ли дойдут руки до этого. Быстрее всего попросить самого автора GRPC-модуля через список рассылки: freenginx: поддержка

Как workaround могу предложить на промежуточном nginx вместо отдачи 502 обрывать соединение. Для этого там нужно настроить grpc_intercept_errors и указать что-то вроде:

error_page 502 = @drop;

location @drop {
    return 444;
}
1 Like

Валентин, спасибо, workaround вполне рабочий. Топик можно закрывать.