Ze života s Kubernetes: Jak HTTP server Španělů neměl rád

Zástupca nášho klienta, ktorého aplikačný stack sídli v cloude Microsoftu (Azure), sa obrátil na nás s problémom: od tej doby časť požiadaviek niektorých klientov z Európy začala končiť chybou 400 (Nesprávny požiadavok). Všetky aplikácie sú napísané v .NET, nasadené v Kubernetes…

Jedna z aplikácií — API, cez ktoré napokon prichádza celý prenos. Tento prenos spravuje HTTP server Kestrel, ktorý je nakonfigurovaný klientom .NET a umiestnený v pod-e. Pri ladení sme mali šťastie, že existoval konkrétny používateľ, u ktorého bola problematika stabilne reprodukovateľná. Avšak všetko sa komplikovalo reťazcovým prenosom:

Chyba v Ingress vyzerala nasledovne:

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

Kestrel pritom vracal:

HTTP/1.1 400 Nesprávny požiadavok
Pripojenie: zatvorené
Dátum: St, 06 Mar 2019 12:34:20 GMT
Server: Kestrel
Dĺžka obsahu: 0

Aj pri maximálnej verbóznosti obsahovala chyba Kestrel veľmi málo užitočných informácií:

{
   "number_fields":{"ThreadId":76},
   "stream":"stdout",
   "string_fields":{
      "EventId":"{"Id"=>17, "Name"=>"ConnectionBadRequest"}",
      "SourceContext":"Microsoft.AspNetCore.Server.Kestrel",
      "ConnectionId":"0HLL2VJSST5KV",
      "@mt":"Id pripojenia "{ConnectionId}" zlá požiadavka: "{message}"",
      "@t":"2019-03-07T13:06:48.1449083Z",
      "@x":"Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Nesprávny formát požiadavky: neplatné hlavičky.n   na Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1Connection.TryParseRequest(ReadResult result, Boolean& endConnection)n   na Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol.<ProcessRequestsAsync>d__185`1.MoveNext()",
      "message":"Nesprávny formát požiadavky: neplatné hlavičky."
   },
   "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":{}
}

Na prvý pohľad by len tcpdump mohol pomôcť pri riešení tejto problémy… ale opakujem o reťazci prevádzky:

Vyšetrovanie

Je jasné, že počúvať prevádzku je lepšie na tom konkrétnom uzle, kde Kubernetes nasadil pod: objem dumpu bude taký, že sa rýchlo nájde čokoľvek. A naozaj, pri jeho preskúmaní bol zaznamenaný taký rámec:

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: Španielsko
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: mnoho_šifrovaných_súborov_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

Pri podrobnom preskúmaní dumpu bolo zaznamenané slovo M.laga. Je jednoduché hádať, že v Španielsku nie je mesto M.laga (ale je tam Málaga). Chytajúc sa tejto myšlienky, sme si prezreli konfigurácie Ingress, kde sme našli vložený pred mesiacom (na požiadanie klienta) „neškodný“ 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;

Po vypnutí preposielania týchto hlavičiek všetko fungovalo! (Čoskoro sa ukázalo, že tieto hlavičky aplikácii už neboli potrebné.)

Teraz sa pozrime na problém vo všeobecnejšom slova zmysle. Ľahko ho vieme reprodukovať vo vnútri aplikácie, ak vykonáme telnet-žiadosti na 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

… vracia sa 401 Unauthorized, ako sa očakáva. A čo sa stane, ak urobíme:

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

?

Vráti sa 400 Bad request — v logu aplikácie dostaneme už známu chybu:

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

Zhrnutie

Konkrétne Kestrel nemôže správne spracovávať HTTP hlavičky s správnymi znakmi v UTF-8, ktoré sa nachádzajú v názvoch pomerne veľkého množstva miest.

Ďalší faktor v našom prípade — zmeniť implementáciu Kestrel v aplikácii klient momentálne neplánuje. Napriek tomu, problémy v samotnom AspNetCore (č. 4318, č. 7707) naznačujú, že to tiež nepomôže…

Zhrňme to: poznámka už nie je o špecifických problémoch Kestrel alebo UTF-8 (v roku 2019?!), ale o tom, že pozornosť a dôsledné štúdium každého kroku počas hľadania problému prinesie skôr či neskôr svoje ovocie. Veľa šťastia!

P.S.

Prečítajte si tiež na našom blogu:

• «6 zaujímavých systémových chýb pri prevádzke Kubernetes [a ich riešenie]»;
• «Kubernetes tipy a triky: personalizované stránky chýb v NGINX Ingress»;
• «Prehľad a porovnanie Ingress kontrolérov pre Kubernetes»;
• «Monitoring pingov medzi uzlami Kubernetes — náš recept»;
• «3 nezvyčajné prípady o sieťovom subsystéme Linux».

Zdroj: habr.com