La vida con Kubernetes: Cómo el servidor HTTP de los españoles no fue bien recibido

Un representante de nuestro cliente, cuyo stack de aplicaciones está en la nube de Microsoft (Azure), se puso en contacto con un problema: desde hace poco tiempo, parte de las solicitudes de algunos clientes en Europa comenzaron a terminar con un error 400 (Solicitud Incorrecta). Todas las aplicaciones están escritas en .NET, desplegadas en Kubernetes…

Una de las aplicaciones es una API, a través de la cual finalmente llega todo el tráfico. Este tráfico es gestionado por el servidor HTTP Kestrel, configurado por el cliente en .NET y alojado en un pod. Tuvimos suerte con la depuración porque había un usuario específico que reproducía el problema de manera constante. Sin embargo, todo se complicaba debido a la cadena de tráfico:

El error en Ingress se veía de la siguiente manera:

{
   "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":{}
}

Mientras tanto, Kestrel respondía con:

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

Incluso con la máxima verbosidad, el error de Kestrel contenía muy poca información útil:

{
   "number_fields":{"ThreadId":76},
   "stream":"stdout",
   "string_fields":{
      "EventId":"{"Id"=>17, "Name"=>"ConnectionBadRequest"}",
      "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
      "ConnectionId":"0HLL2VJSST5KV",
      "@mt":"Datos de solicitud incorrecta para la conexión "{ConnectionId}": "{message}"",
      "@t":"2019-03-07T13:06:48.1449083Z",
      "@x":"Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Solicitud malformada: encabezados no válidos.n   en Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1Connection.TryParseRequest(ReadResult result, Boolean& endConnection)n   en Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.<ProcessRequestsAsync>d__185`1.MoveNext()",
      "message":"Solicitud malformada: encabezados no válidos."
   },
   "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":{}
}

Aparentemente, solo tcpdump puede ayudar a resolver este problema… pero permítanme repetir sobre la cadena de tráfico:

Investigación

Es obvio que es mejor escuchar el tráfico en ese nodo específico, donde Kubernetes desplegó el pod: la cantidad de volcado será tal que se podrá encontrar algo bastante rápido. Y de hecho, al examinarlo se notó este marco:

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: España
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: muchas_cookies_encriptadas; .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

Al examinar atentamente el volcado se notó la palabra M.laga. Es fácil adivinar que en España no hay ciudad llamada M.laga (pero sí hay Málaga). Tomando esta idea, revisamos las configuraciones de Ingress, donde vimos un snippet "inofensivo" añadido hace un mes (por solicitud del cliente) «sin significado»:

    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;

Al desactivar el reenvío de estos encabezados, ¡todo funcionó bien! (Pronto se descubrió que estos encabezados ya no eran necesarios para la aplicación misma).

Ahora veamos el problema de una manera más general. Es fácil reproducirlo dentro de la aplicación, si se realiza una solicitud telnet a 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

… se devuelve 401 Unauthorized, como se esperaba. ¿Y qué pasará si hacemos:

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

?

Se devolverá 400 Solicitud incorrecta — en el registro de la aplicación obtendremos el error que ya conocemos:

{
   "@t":"2019-03-31T12:59:54.3746446Z",
   "@mt":"Connection id "{ConnectionId}" datos de solicitud incorrectos: "{message}"",
   "@x":"Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Solicitud malformada: encabezados inválidos.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":"Solicitud malformada: encabezados inválidos.",
   "EventId":{
      "Id":17,
      "Name":"ConnectionBadRequest"
   },
   "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
   "ThreadId":71
}

Resultados

Específicamente Kestrel mejorar procesar correctamente los encabezados HTTP con caracteres válidos en UTF-8 que están presentes en los nombres de una cantidad bastante grande de ciudades.

Un factor adicional en nuestro caso es que el cliente no planea cambiar la implementación de Kestrel en este momento. Sin embargo, los problemas en AspNetCore (№4318, №7707) indican que eso no ayudará…

En resumen: la nota no trata más sobre problemas específicos de Kestrel o UTF-8 (¿en el año 2019?!), sino sobre que la atención y el estudio meticuloso de cada paso durante la búsqueda del problema, tarde o temprano, dará sus frutos. ¡Éxitos!

P.D.

También puedes leer en nuestro blog:

• «6 errores de sistema interesantes al operar Kubernetes [y sus soluciones]»;
• «Consejos y trucos de Kubernetes: páginas de error personalizadas en NGINX Ingress»;
• «Revisión y comparación de controladores Ingress para Kubernetes»;
• «La monitorización de pings entre nodos de Kubernetes es nuestra receta»;
• «3 casos inusuales sobre el subsistema de red de Linux».

Fuente: habr.com