Dalla vita con Kubernetes: Come il server HTTP degli spagnoli non ha apprezzato

Il rappresentante del nostro cliente, il cui stack di applicazioni risiede nel cloud di Microsoft (Azure), ha segnalato un problema: da qualche tempo, alcune richieste di clienti in Europa si stanno concludendo con un errore 400 (Richiesta non valida). Tutte le applicazioni sono scritte in .NET e sono distribuite in Kubernetes…

Una delle applicazioni è un'API attraverso cui passa alla fine tutto il traffico. Questo traffico viene ascoltato dal server HTTP Kestrel, configurato dal cliente .NET e ospitato in un pod. Ci è andata bene con il debug, poiché c'era un utente specifico che riproduceva costantemente il problema. Tuttavia, tutto si complicava a causa della catena di traffico:

L'errore in Ingress appariva nel seguente modo:

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

Nel frattempo, Kestrel restituiva:

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

Anche con la massima verbosità, l'errore di Kestrel conteneva estremamente poche informazioni utili:

{
   "number_fields":{"ThreadId":76},
   "stream":"stdout",
   "string_fields":{
      "EventId":"{"Id"=>17, "Name"=>"ConnectionBadRequest"}",
      "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
      "ConnectionId":"0HLL2VJSST5KV",
      "@mt":"Dati di richiesta non valida per l'identificativo connessione "{ConnectionId}": "{message}"",
      "@t":"2019-03-07T13:06:48.1449083Z",
      "@x":"Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Richiesta malformata: intestazioni non valide.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.d__185`1.MoveNext()",
      "message":"Richiesta malformata: intestazioni non valide."
   },
   "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":{}
}

A prima vista, solo tcpdump può aiutare nella risoluzione di questo problema… ma ripeto riguardo al flusso di traffico:

Indagine

È ovvio che ascoltare il traffico è migliore sul nodo specifico, dove Kubernetes ha distribuito il pod: la quantità di dump sarà tale che sarà possibile trovare qualcosa piuttosto rapidamente. E in effetti, esaminandolo è stato notato questo frame:

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: Spagna
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 Richiesta Errata
Connection: close
Date: Wed, 06 Mar 2019 12:34:20 GMT
Server: Kestrel
Content-Length: 0

Esaminando attentamente il dump è stata notata la parola M.laga. È facile intuire che non c'è una città chiamata M.laga in Spagna (ma c'è Málaga). Afferrando questa idea, abbiamo esaminato le configurazioni di Ingress, dove abbiamo visto un "snippet" inserito un mese fa (su richiesta del cliente) «inoffensivo» snippet:

    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;

Disattivando il passaggio di queste intestazioni, tutto è andato bene! (Presto si è scoperto che queste intestazioni non erano più necessarie per l'applicazione stessa.)

Ora diamo un'occhiata al problema in una forma più generale. È facile riprodurlo all'interno dell'applicazione, se si effettua una richiesta 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

… viene restituito 401 Unauthorized, come previsto. E cosa succede se facciamo:

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

?

Tornerà 400 Bad request — nel log dell'applicazione avremo già l'errore che conosciamo:

{
   "@t":"2019-03-31T12:59:54.3746446Z",
   "@mt":"Connection id "{ConnectionId}" bad request data: "{message}"",
   "@x":"Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Richiesta malformata: intestazioni non valide.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":"Richiesta malformata: intestazioni non valide.",
   "EventId":{
      "Id":17,
      "Name":"ConnectionBadRequest"
   },
   "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
   "ThreadId":71
}

Conclusioni

In particolare Kestrel non può gestire correttamente le intestazioni HTTP con caratteri appropriati in UTF-8, che si trovano nei nomi di un numero piuttosto elevato di città.

Un ulteriore fattore nel nostro caso è che il cliente attualmente non prevede di modificare l'implementazione di Kestrel. Tuttavia, le questioni all'interno dello stesso AspNetCore (№4318, №7707) indicano che ciò non aiuterà nemmeno...

In sintesi: la nota non riguarda più problemi specifici di Kestrel o di UTF-8 (nel 2019, poi?!), ma riguarda il fatto che l'attenzione e lo studio sistematico di ogni passo durante la ricerca del problema prima o poi porteranno i loro frutti. Buona fortuna!

P.S.

Leggi anche nel nostro blog:

• «6 bug di sistema interessanti durante l'uso di Kubernetes [e le loro soluzioni]»;
• «Kubernetes tips & tricks: pagine di errore personalizzate in NGINX Ingress»;
• «Panoramica e confronto dei controller Ingress per Kubernetes»;
• «Il monitoraggio dei ping tra i nodi di Kubernetes è la nostra ricetta»;
• «3 casi insoliti sul sottosistema di rete Linux».

Fonte: habr.com