Dalla vita con Kubernetes: Come il server HTTP degli spagnoli non aveva pietà

Un rappresentante del nostro cliente, il cui stack di applicazioni risiede nel cloud di Microsoft (Azure), ha segnalato un problema: da un po' di tempo alcune richieste da parte di clienti in Europa hanno iniziato a restituire un errore 400 (Richiesta non valida). Tutte le applicazioni sono scritte in .NET e sono distribuite su Kubernetes…

Una delle applicazioni è un'API, attraverso la quale transita tutto il traffico. Questo traffico è gestito dal server HTTP Kestrel, configurato dal cliente .NET e ospitato in un pod. Fortunatamente, nella fase di debug abbiamo avuto un utente specifico, il cui problema si riproduceva costantemente. Tuttavia, la situazione si complicava a causa della catena di traffico:

L'errore in Ingress si presentava 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":{}
}

Inoltre, Kestrel ha restituito:

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

Anche al massimo di verbosity, l'errore di Kestrel conteneva pochissime informazioni utili:

{
   "number_fields":{"ThreadId":76},
   "stream":"stdout",
   "string_fields":{
      "EventId":"{"Id"=>17, "Name"=>"ConnectionBadRequest"}",
      "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
      "ConnectionId":"0HLL2VJSST5KV",
      "@mt":"Dati della richiesta errata per l'id 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.<ProcessRequestsAsync>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":{}
}

Sembrerebbe che solo tcpdump possa risolvere questo problema… ma ripeto riguardo al flusso di traffico:

Indagine

È ovvio che ascoltare il traffico è meglio sul nodo specifico, dove Kubernetes ha distribuito il pod: la dimensione del dump sarà tale da poter trovare piuttosto rapidamente qualcosa. E in effetti, nella sua analisi è stato notato il seguente 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: it-IT,it;q=0.9,it-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

Esaminando attentamente il dump, è stata notata la parola Málaga. È facile intuire che non esiste una città chiamata M.laga in Spagna (ma esiste Málaga). Prendendo spunto da questa idea, abbiamo controllato le configurazioni di Ingress, dove abbiamo visto un 'innocuo' snippet inserito un mese fa (su richiesta del cliente) «innocuo» 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 all'applicazione stessa.)

Ora diamo un'occhiata al problema in modo più generale. È facile riprodurlo all'interno dell'applicazione, effettuando una richiesta telnet su 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

… restituisce 401 Unauthorized, come previsto. Ma 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

?

Restituisce 400 Bad request — nel log dell'applicazione otteniamo già l'errore a noi noto:

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

Risultati

Specificamente Kestrel può gestire correttamente gli header HTTP con i caratteri appropriati in UTF-8, presenti 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 nell'app. Tuttavia, i problemi in AspNetCore stesso (№4318, №7707) indicano che ciò non aiuterà…

In sintesi: questa nota non riguarda più problematiche specifiche di Kestrel o di UTF-8 (nel 2019?!), ma su come l'attenzione e lo studio coerente ogni passo durante la ricerca del problema porterà prima o poi dei risultati. Buona fortuna!

P.S.

Leggete anche nel nostro blog:

• «6 bug di sistema interessanti durante l'utilizzo di Kubernetes [e come risolverli]»;
• «Kubernetes tips & tricks: pagine di errore personalizzate in NGINX Ingress»;
• «Panoramica e confronto dei controller Ingress per Kubernetes»;
• «Monitoraggio dei ping tra i nodi Kubernetes — la nostra ricetta»;
• «3 casi particolari sul sottosistema di rete Linux».

Fonte: habr.com