envoyproxy / envoyproxy/envoy

healthcheck filter: min_length constraint on headers to match

Open
#10,618 4 comments 0 reactions 0 assignees View on GitHub
bug help wanted
Dominant language
C++
Stars
28.9k
Forks
5.6k
Avg merge
1d 20h
Merged PRs (30d)
437

Description

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 ](https://github.com/envoyproxy/envoy/issues/7841#issuecomment-518856436) 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](https://github.com/envoyproxy/envoy/files/4417954/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.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.