envoyproxy/envoy

StreamInfo upstreaming timing values not set when backend retry occurs

Open

#16.684 geöffnet am 26. Mai 2021

Auf GitHub ansehen
 (4 Kommentare) (0 Reaktionen) (0 zugewiesene Personen)C++ (5.373 Forks)batch import
area/retrybughelp wantedquestion

Repository-Metriken

Stars
 (27.997 Stars)
PR-Merge-Metriken
 (Durchschn. Merge 8T) (378 gemergte PRs in 30 T)

Beschreibung

Description: We depend on StreamInfo to calculate how long each request spends in the proxy vs backend. To do this calculation, we rely on StreamInfo::firstUpstreamTxByteSent().

However, when a backend timeout occurs, both firstUpstreamTxByteSent() and lastUpstreamTxByteSent() have empty value.

We were expecting at least one of these variables to have a value. The request was sent to the upstream, just the response was never received back. Without these values, we cannot easily tell how long the request spent in the upstream before the timeout occurred.

Repro steps: We tested this by configuring timeouts per route and printing out the values of various variables in StreamInfo (in our custom filter).

[2021-05-26 15:13:48.541][438146][error][misc] [src/envoy/http/service_control/handler_utils.cc:187] !!! Response code detail: upstream_response_timeout
[2021-05-26 15:13:48.541][438146][error][misc] [src/envoy/http/service_control/handler_utils.cc:188] !!! Request complete? true
[2021-05-26 15:13:48.541][438146][error][misc] [src/envoy/http/service_control/handler_utils.cc:189] !!! firstUpstreamTxByteSent has value? false
[2021-05-26 15:13:48.541][438146][error][misc] [src/envoy/http/service_control/handler_utils.cc:190] !!! lastUpstreamTxByteSent has value? false
[2021-05-26 15:13:48.541][438146][error][misc] [src/envoy/http/service_control/handler_utils.cc:191] !!! firstUpstreamRxByteReceived has value? false
[2021-05-26 15:13:48.541][438146][error][misc] [src/envoy/http/service_control/handler_utils.cc:192] !!! lastUpstreamRxByteReceived has value? false

Investigation: I spent a few hours trying to debug why the variables are not set. Following the logic here, the variable is being set correctly. But it seems like some other component is resetting the variable further down. I cannot tell where that is happening.

Contributor Guide