Da vida com Kubernetes: como o servidor HTTP não favoreceu os espanhóis

Um representante do nosso cliente, cuja pilha de aplicações reside na nuvem da Microsoft (Azure), abordou um problema: recentemente, algumas solicitações de alguns clientes da Europa começaram a terminar com o erro 400 (Pedido ruim). Todas as aplicações são escritas em .NET, implantadas em Kubernetes...

Uma das aplicações é a API, por meio da qual chega todo o tráfego. Este tráfego é escutado pelo servidor HTTP Francelho, configurado pelo cliente .NET e hospedado em um pod. Com a depuração, tivemos sorte, pois havia um usuário específico que reproduzia o problema de forma consistente. Porém, tudo foi complicado pela cadeia de tráfego:

O erro no Ingress ficou assim:

{
   "number_fields":{
      "status":400,
      "request_time":0.001,
      "bytes_sent":465,
      "upstream_response_time":0,
      "upstream_retries":0,
      "bytes_received":2328
   },
   "stream":"stdout",
   "string_fields":{
      "ingress":"app",
      "protocol":"HTTP/1.1",
      "request_id":"f9ab8540407208a119463975afda90bc",
      "path":"/api/sign-in",
      "nginx_upstream_status":"400",
      "service":"app",
      "namespace":"production",
      "location":"/front",
      "scheme":"https",
      "method":"POST",
      "nginx_upstream_response_time":"0.000",
      "nginx_upstream_bytes_received":"120",
      "vhost":"api.app.example.com",
      "host":"api.app.example.com",
      "user":"",
      "address":"83.41.81.250",
      "nginx_upstream_addr":"10.240.0.110:80",
      "referrer":"https://api.app.example.com/auth/login?long_encrypted_header",
      "service_port":"http",
      "user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.121 Safari/537.36",
      "time":"2019-03-06T18:29:16+00:00",
      "content_kind":"cache-headers-not-present",
      "request_query":""
   },
   "timestamp":"2019-03-06 18:29:16",
   "labels":{
      "app":"nginx",
      "pod-template-generation":"6",
      "controller-revision-hash":"1682636041"
   },
   "namespace":"kube-nginx-ingress",
   "nsec":6726612,
   "source":"kubernetes",
   "host":"k8s-node-55555-0",
   "pod_name":"nginx-v2hcb",
   "container_name":"nginx",
   "boolean_fields":{}
}

Ao mesmo tempo, Kestrel deu:

HTTP/1.1 400 Bad Request
Connection: close
Date: Wed, 06 Mar 2019 12:34:20 GMT
Server: Kestrel
Content-Length: 0

Mesmo com verbosidade máxima, o erro Kestrel continha informações extremamente pouca informação útil:

{
   "number_fields":{"ThreadId":76},
   "stream":"stdout",
   "string_fields":{
      "EventId":"{"Id"=>17, "Name"=>"ConnectionBadRequest"}",
      "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
      "ConnectionId":"0HLL2VJSST5KV",
      "@mt":"Connection id "{ConnectionId}" bad request data: "{message}"",
      "@t":"2019-03-07T13:06:48.1449083Z",
      "@x":"Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Malformed request: invalid headers.n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1Connection.TryParseRequest(ReadResult result, Boolean& endConnection)n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.<ProcessRequestsAsync>d__185`1.MoveNext()",
      "message":"Malformed request: invalid headers."
   },
   "timestamp":"2019-03-07 13:06:48",
   "labels":{
      "pod-template-hash":"2368795483",
      "service":"app"
   },
   "namespace":"production",
   "nsec":145341848,
   "source":"kubernetes",
   "host":"k8s-node-55555-1",
   "pod_name":"app-67bdcf98d7-mhktx",
   "container_name":"app",
   "boolean_fields":{}
}

Parece que apenas o tcpdump ajudará a resolver este problema... mas vou repetir sobre a cadeia de tráfego:

Investigação

Obviamente, é melhor ouvir o trânsito naquele nó específico, onde o Kubernetes implantou um pod: o volume do dump será tal que será possível encontrar pelo menos algo rapidamente. E de fato, ao examiná-lo, percebeu-se o seguinte quadro:

GET /back/user HTTP/1.1
Host: api.app.example.com
X-Request-ID: 27ceb14972da8c21a8f92904b3eff1e5
X-Real-IP: 83.41.81.250
X-Forwarded-For: 83.41.81.250
X-Forwarded-Host: api.app.example.com
X-Forwarded-Port: 443
X-Forwarded-Proto: https
X-Original-URI: /front/back/user
X-Scheme: https
X-Original-Forwarded-For: 83.41.81.250
X-Nginx-Geo-Client-Country: Spain
X-Nginx-Geo-Client-City: M.laga
Accept-Encoding: gzip
CF-IPCountry: ES
CF-RAY: 4b345cfd1c4ac691-MAD
CF-Visitor: {"scheme":"https"}
pragma: no-cache
cache-control: no-cache
accept: application/json, text/plain, */*
origin: https://app.example.com
user-agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/72.0.3626.119 Safari/537.36
referer: https://app.example.com/auth/login
accept-language: en-US,en;q=0.9,en-GB;q=0.8,pl;q=0.7
cookie: many_encrypted_cookies; .AspNetCore.Identity.Application=something_encrypted; 
CF-Connecting-IP: 83.41.81.250
True-Client-IP: 83.41.81.250
CDN-Loop: cloudflare

HTTP/1.1 400 Bad Request
Connection: close
Date: Wed, 06 Mar 2019 12:34:20 GMT
Server: Kestrel
Content-Length: 0

Após uma inspeção mais detalhada do lixão, a palavra foi notada M.laga. É fácil adivinhar que não existe uma cidade M.laga em Espanha (mas existe Málaga). Aproveitando essa ideia, olhamos as configurações do Ingress, onde vimos aquela inserida há um mês (a pedido do cliente) trecho "inofensivo":

    ingress.kubernetes.io/configuration-snippet: |
      proxy_set_header X-Nginx-Geo-Client-Country $geoip_country_name;
      proxy_set_header X-Nginx-Geo-Client-City $geoip_city;

Depois de desabilitar o encaminhamento desses cabeçalhos, tudo ficou bem! (Logo ficou claro que o próprio aplicativo não precisava mais desses cabeçalhos.)

Agora vamos analisar o problema De forma geral. Ele pode ser facilmente reproduzido dentro do aplicativo fazendo uma solicitação telnet para localhost:80:

GET /back/user HTTP/1.1
Host: api.app.example.com
cache-control: no-cache
accept: application/json, text/plain, */*
origin: https://app.example.com
Cookie: test=Desiree

... retorna 401 Unauthorized, como esperado. O que acontece se fizermos:

GET /back/user HTTP/1.1
Host: api.app.example.com
cache-control: no-cache
accept: application/json, text/plain, */*
origin: https://app.example.com
Cookie: test=Désirée

?

Retornará 400 Bad request — no log do aplicativo receberemos um erro que já nos é familiar:

{
   "@t":"2019-03-31T12:59:54.3746446Z",
   "@mt":"Connection id "{ConnectionId}" bad request data: "{message}"",
   "@x":"Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Malformed request: invalid headers.n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1Connection.TryParseRequest(ReadResult result, Boolean& endConnection)n   at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.<ProcessRequestsAsync>d__185`1.MoveNext()",
   "ConnectionId":"0HLLLR1J974L9",
   "message":"Malformed request: invalid headers.",
   "EventId":{
      "Id":17,
      "Name":"ConnectionBadRequest"
   },
   "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
   "ThreadId":71
}

Resultados de

Especificamente Kestrel não pode processar corretamente os cabeçalhos HTTP com os caracteres corretos em UTF-8, que estão contidos nos nomes de um grande número de cidades.

Um fator adicional em nosso caso é que o cliente atualmente não planeja alterar a implementação do Kestrel na aplicação. No entanto, problemas no próprio AspNetCore (№ 4318, № 7707) eles dizem que isso não vai ajudar...

Resumindo: a nota não é mais sobre os problemas específicos do Kestrel ou do UTF-8 (em 2019?!), mas sobre o fato de que atenção plena e estudo consistente Cada passo que você dá na busca por problemas, mais cedo ou mais tarde, dará frutos. Boa sorte!

PS

Leia também em nosso blog:

• «6 bugs divertidos do sistema na operação do Kubernetes [e sua solução]";
• «Dicas e truques do Kubernetes: páginas de erro personalizadas no NGINX Ingress";
• «Visão geral e comparação dos controladores Ingress para Kubernetes";
• «Monitorando pings entre nós do Kubernetes – nossa receita";
• «3 casos incomuns sobre o subsistema de rede Linux".

Fonte: habr.com