envoyproxy/envoy

StreamInfo upstreaming timing values not set when backend retry occurs

Open

#16.684 aberto em 26 de mai. de 2021

Ver no GitHub
 (4 comments) (0 reactions) (0 assignees)C++ (5.373 forks)batch import
area/retrybughelp wantedquestion

Métricas do repositório

Stars
 (27.997 stars)
Métricas de merge de PR
 (Mesclagem média 8d) (378 fundiu PRs em 30d)

Description

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.

Guia do colaborador