Der Vertreter unseres Kunden, dessen Anwendungsstapel von Microsoft (Azure) in der Cloud gespeichert ist, hatte ein Problem: Vor kurzem endete ein Teil der Anforderungen einiger Kunden aus Europa mit dem Fehler 400 (
Bad Request ). Alle Anwendungen sind in .NET geschrieben und in Kubernetes bereitgestellt ...
Eine Anwendung ist die API, über die letztendlich der gesamte Datenverkehr erfolgt. Dieser Datenverkehr wird vom
Kestrel- HTTP-Server überwacht, der vom .NET-Client konfiguriert und im Pod gehostet wird. Beim Debuggen hatten wir Glück in dem Sinne, dass es einen bestimmten Benutzer gab, der ein stabiles reproduziertes Problem hatte. Die Verkehrskette erschwerte jedoch alles:
Der Fehler in Ingress sah folgendermaßen aus:
{ "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":{} }
Zur gleichen Zeit gab Turmfalke:
HTTP/1.1 400 Bad Request Connection: close Date: Wed, 06 Mar 2019 12:34:20 GMT Server: Kestrel Content-Length: 0
Selbst bei maximaler Ausführlichkeit enthielt der Turmfalkenfehler äußerst
wenig nützliche Informationen :
{ "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":{} }
Es scheint, dass nur tcpdump bei der Lösung dieses Problems helfen wird ... aber ich werde über die Verkehrskette wiederholen:
Untersuchung
Offensichtlich ist es besser
, den Datenverkehr
auf dem bestimmten Knoten abzuhören,
auf dem Kubernetes den Pod bereitgestellt hat: Das Speicherauszugsvolumen ist so bemessen, dass zumindest schnell etwas gefunden werden kann. In der Tat wurde bei der Betrachtung ein solcher Rahmen bemerkt:
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
Bei sorgfältiger Untersuchung der Deponie wurde das Wort
M.laga bemerkt. Es ist leicht zu erraten, dass es in Spanien keine Stadt M.laga gibt (aber es gibt
Málaga ). Als wir diese Idee verstanden haben, haben wir uns Ingress-Konfigurationen angesehen, bei denen wir vor einem Monat (auf Kundenwunsch) einen
„harmlosen“ Ausschnitt eingefügt haben:
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;
Wenn Sie die Weiterleitung dieser Header deaktivieren, wurde alles gut! (Es wurde schnell klar, dass die Anwendung selbst diese Header nicht mehr benötigte.)
Betrachten wir das Problem nun
allgemeiner . Es kann problemlos in der Anwendung reproduziert werden, wenn Sie eine Telnet-Anfrage an
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
...
401 Unauthorized Rücksendungen wie erwartet. Und was passiert, wenn wir es tun:
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
?
400 Bad request zurückgegeben - im Anwendungsprotokoll erhalten wir den Fehler, den wir bereits kennen:
{ "@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 }
Zusammenfassung
Insbesondere kann Kestrel HTTP-Header mit den richtigen Zeichen in UTF-8, die in den Namen einer relativ großen Anzahl von Städten enthalten
sind, nicht korrekt verarbeiten.
Ein weiterer Faktor in unserem Fall ist, dass der Client derzeit nicht plant, die Implementierung von Kestrel in der Anwendung zu ändern. Probleme in AspNetCore selbst (
Nr. 4318 ,
Nr. 7707 ) besagen jedoch, dass dies nicht helfen wird ...
Zusammenfassend lässt sich sagen, dass es in der Notiz nicht mehr um die spezifischen Probleme von Turmfalke oder UTF-8 (im Jahr 2019, dem Jahr ?!) Geht, sondern dass die
Aufmerksamkeit und konsequente Untersuchung jedes Schritts während der Suche nach einem Problem früher oder später Früchte tragen wird. Viel Glück!
PS
Lesen Sie auch in unserem Blog: