healthcheck filter: min_length constraint on headers to match

Hi

We have observed in our internal tests a set of counters not increased after implementation of a graceful shutdown mechanism using /healthcheck/fail endpoint.

We followed suggestion from this comment and our solution looks good enough for our scenario.

But we noticed an unexpected side-effect when it comes to the Dynamic HTTP stats. None of them are increased.

Repro steps: We are using v1.13.0. We reproduced in a simpler setup with docker-compose, still happening. One envoy routing requests to service1 or service2 according to the header in the request.

1. Configure the http_filter for envoy.healthcheck.
2. Send an HTTP request towards a service.
3. Get stats.

expected behaviour -> upstream_rq_completed = upstream_rq_total = 1 for the service who got the request current behaviour --> upstream_rq_completed = 0 , upstream_rq_total=1

Removing the envoy.healthcheck filter behaviour is the expected one.

Conf:

envoy.config.txt

Our sample services are based on Docker image tiangolo/uwsgi-nginx-flask:python3.6-alpine3.7 running a python service.

Logs:

We added two traces in router.cc just to confirm problem was with stream_info.healthcheck() method:

L323 ENVOY_STREAM_LOG(debug, "sokaran - chargeUpstreamCode '{}'", *callbacks_, callbacks_->streamInfo().healthCheck());

L1307 ENVOY_STREAM_LOG(debug, "sokaran - onUpstreamComplete '{}'", *callbacks_, callbacks_->streamInfo().healthCheck());

We can see in both cases this is true:

[2020-04-01 22:18:20.008][18][debug][conn_handler] [source/server/connection_handler_impl.cc:353] [C2] new connection
[2020-04-01 22:18:20.008][18][debug][http] [source/common/http/conn_manager_impl.cc:263] [C2] new stream
[2020-04-01 22:18:20.008][18][debug][http] [source/common/http/conn_manager_impl.cc:731] [C2][S14309476495007524334] request headers complete (end_stream=true):
':authority', 'localhost:8000'
':path', '/service/2'
':method', 'GET'
'user-agent', 'curl/7.58.0'
'accept', '*/*'
'x-service', '1'

[2020-04-01 22:18:20.008][18][debug][http] [source/common/http/conn_manager_impl.cc:1276] [C2][S14309476495007524334] request end stream
[2020-04-01 22:18:20.008][18][debug][router] [source/common/router/router.cc:476] [C2][S14309476495007524334] cluster 'service1' match for URL '/service/2'
[2020-04-01 22:18:20.009][18][debug][router] [source/common/router/router.cc:616] [C2][S14309476495007524334] router decoding headers:
':authority', 'localhost:8000'
':path', '/service/2'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/7.58.0'
'accept', '*/*'
'x-service', '1'
'x-forwarded-proto', 'http'
'x-request-id', '6f80cca1-cbf4-4498-ada8-f7262fe6d85a'
'x-envoy-expected-rq-timeout-ms', '15000'

[2020-04-01 22:18:20.009][18][debug][pool] [source/common/http/http1/conn_pool.cc:95] creating a new connection
[2020-04-01 22:18:20.009][18][debug][client] [source/common/http/codec_client.cc:34] [C3] connecting
[2020-04-01 22:18:20.009][18][debug][connection] [source/common/network/connection_impl.cc:691] [C3] connecting to 172.18.0.5:8080
[2020-04-01 22:18:20.009][18][debug][connection] [source/common/network/connection_impl.cc:700] [C3] connection in progress
[2020-04-01 22:18:20.009][18][debug][pool] [source/common/http/conn_pool_base.cc:55] queueing request due to no available connections
[2020-04-01 22:18:20.009][18][debug][connection] [source/common/network/connection_impl.cc:563] [C3] connected
[2020-04-01 22:18:20.009][18][debug][client] [source/common/http/codec_client.cc:72] [C3] connected
[2020-04-01 22:18:20.009][18][debug][pool] [source/common/http/http1/conn_pool.cc:244] [C3] attaching to next request
[2020-04-01 22:18:20.009][18][debug][router] [source/common/router/router.cc:1715] [C2][S14309476495007524334] pool ready
[2020-04-01 22:18:20.010][18][debug][router] [source/common/router/router.cc:1117] [C2][S14309476495007524334] upstream headers complete: end_stream=false
[2020-04-01 22:18:20.010][18][debug][router] [source/common/router/router.cc:324] [C2][S14309476495007524334] sokaran - chargeUpstreamCode 'true'
[2020-04-01 22:18:20.010][18][debug][http] [source/common/http/conn_manager_impl.cc:1615] [C2][S14309476495007524334] encoding headers via codec (end_stream=false):
':status', '200'
'content-type', 'text/html; charset=utf-8'
'content-length', '93'
'server', 'envoy'
'date', 'Wed, 01 Apr 2020 22:18:19 GMT'
'x-envoy-upstream-service-time', '1'
'x-envoy-upstream-healthchecked-cluster', 'test'

[2020-04-01 22:18:20.010][18][debug][client] [source/common/http/codec_client.cc:104] [C3] response complete
[2020-04-01 22:18:20.010][18][debug][router] [source/common/router/router.cc:1308] [C2][S14309476495007524334] sokaran - onUpstreamComplete 'true'
[2020-04-01 22:18:20.010][18][debug][pool] [source/common/http/http1/conn_pool.cc:201] [C3] response complete
[2020-04-01 22:18:20.010][18][debug][pool] [source/common/http/http1/conn_pool.cc:206] [C3] saw upstream close connection
[2020-04-01 22:18:20.010][18][debug][connection] [source/common/network/connection_impl.cc:101] [C3] closing data_to_write=0 type=1
[2020-04-01 22:18:20.010][18][debug][connection] [source/common/network/connection_impl.cc:192] [C3] closing socket: 1
[2020-04-01 22:18:20.010][18][debug][client] [source/common/http/codec_client.cc:91] [C3] disconnect. resetting 0 pending requests
[2020-04-01 22:18:20.010][18][debug][pool] [source/common/http/http1/conn_pool.cc:136] [C3] client disconnected, failure reason:
[2020-04-01 22:18:20.010][18][debug][connection] [source/common/network/connection_impl.cc:531] [C3] remote close
[2020-04-01 22:18:20.011][18][debug][connection] [source/common/network/connection_impl.cc:531] [C2] remote close
[2020-04-01 22:18:20.011][18][debug][connection] [source/common/network/connection_impl.cc:192] [C2] closing socket: 0

stats:

cluster.service1.upstream_rq_active: 0
cluster.service1.upstream_rq_cancelled: 0
cluster.service1.upstream_rq_completed: 0
cluster.service1.upstream_rq_maintenance_mode: 0
cluster.service1.upstream_rq_pending_active: 0
cluster.service1.upstream_rq_pending_failure_eject: 0
cluster.service1.upstream_rq_pending_overflow: 0
cluster.service1.upstream_rq_pending_total: 2
cluster.service1.upstream_rq_per_try_timeout: 0
cluster.service1.upstream_rq_retry: 0
cluster.service1.upstream_rq_retry_overflow: 0
cluster.service1.upstream_rq_retry_success: 0
cluster.service1.upstream_rq_rx_reset: 0
cluster.service1.upstream_rq_timeout: 0
cluster.service1.upstream_rq_total: 2
cluster.service1.upstream_rq_tx_reset: 0

So, did we understand something wrong when we implemented this /healthcheck/fail endpoint? We have found several issues related with stats and healthchecks but I did not see any actual relation with our problem.

Any help it is very appreciated. Thank you so much.