Skip to content

Proxies

Jump to bottom
Charlie edited this page Sep 21, 2022 · 4 revisions

General HTTP Notes

  • HTTP/1.0 defaults to short-lived connections. A TCP handshake happens before each HTTP request.
  • A TCP connection adapts to its load, becoming more efficient with more sustained (or warm) connections.
  • Sending a Connection header with a value other than close will change this model.
  • HTTP/1.1 defaults to persistent connections (Keep-Alive).

HTTP/1.0

When an Entity-Body is included with a message, the length of that body may be determined in one of two ways. If a Content-Length header field is present, its value in bytes represents the length of the Entity-Body. Otherwise, the body length is determined by the closing of the connection by the server.

Closing the connection cannot be used to indicate the end of a request body, since it leaves no possibility for the server to send back a response. Therefore, HTTP/1.0 requests containing an entity body must include a valid Content-Length header field.

https://datatracker.ietf.org/doc/html/rfc1945#section-7.2.2

Types of Proxies

  • A forward proxy sits in front of clients and facilities communications with servers (origins).
  • A reverse proxy sits in front of servers and facilities communications with clients.

Links

Envoy

Log Format

Docs

Default: "[%Y-%m-%d %T.%e][%t][%l][%n] [%g:%#] %v"

[Year-Month-Day ISO 8601 time.ms part] [Thread Id][Log Level][Logger name] [Source file:Source line]

HTTP/1.0 Delayed Connection Close

In HTTP/1.0, the request is framed / completed using an explicit Content-Length or by the connection closing. When an upstream does not provide this Content-Length header, the HTTP/1.0 downstream connection waits for connection closure to configure end-framing.

Envoy's delayed_close_timeout in the HTTP Connection Manager does not play nicely with this. In Envoy 1.21, this setting defaults to 1000ms is used to prevent a race condition in downstream clients.

When upstreams did not provide an explicit Content-Length header, this 1000ms delay was being added the end of HTTP/1.0 responses. This has been resolved in https://github.com/envoyproxy/envoy/pull/19863.

Interesting Links

An example request and debug logs:

$ curl -0 -v -i -w "%{time_total}\n" \
  --header 'Host: api.cloudoverflow.com' \
  --header 'Accept: application/vnd.pagerduty+json;version=2' \
  --header 'X-PD-Upstream: wcs-local' \
  http://localhost:10000/api/chunky-visitors

*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 10000 (#0)
> GET /api/chunky-visitors HTTP/1.0
> Host: api.cloudoverflow.com
> User-Agent: curl/7.64.1
> Accept: application/vnd.pagerduty+json;version=2
> X-PD-Upstream: wcs-local
>
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
HTTP/1.0 200 OK
< cache-control: max-age=0, private, must-revalidate
cache-control: max-age=0, private, must-revalidate
< content-type: text/html; charset=utf-8
content-type: text/html; charset=utf-8
< date: Fri, 18 Feb 2022 17:44:46 GMT
date: Fri, 18 Feb 2022 17:44:46 GMT
< server: envoy
server: envoy
< x-request-id: c2f1de20-5c40-41c0-b69e-7494e5c31953
x-request-id: c2f1de20-5c40-41c0-b69e-7494e5c31953
< x-envoy-upstream-service-time: 60
x-envoy-upstream-service-time: 60
< connection: close
connection: close

<
abc
* Closing connection 0
1.076107

Envoy receives HTTP/1.0 request, matches to a cluster and queues the stream:

[2022-02-18 17:44:47.460][27][debug][conn_handler] [source/server/active_tcp_listener.cc:332] [C0] new connection from 172.19.0.1:64414
[2022-02-18 17:44:47.468][27][debug][http] [source/common/http/conn_manager_impl.cc:274] [C0] new stream
[2022-02-18 17:44:47.469][27][debug][http] [source/common/http/conn_manager_impl.cc:858] [C0][S7749165874308896508] request headers complete (end_stream=true):
':authority', 'api.cloudoverflow.com'
':path', '/api/chunky-visitors'
':method', 'GET'
'user-agent', 'curl/7.64.1'
'accept', 'application/vnd.pagerduty+json;version=2'
'x-pd-upstream', 'wcs-local'

[2022-02-18 17:44:47.469][27][debug][http] [source/common/http/filter_manager.cc:825] [C0][S7749165874308896508] request end stream
[2022-02-18 17:44:47.469][27][debug][router] [source/common/router/router.cc:444] [C0][S7749165874308896508] cluster 'elixir' match for URL '/api/chunky-visitors'
[2022-02-18 17:44:47.469][27][debug][router] [source/common/router/router.cc:630] [C0][S7749165874308896508] router decoding headers:
':authority', 'api.cloudoverflow.com'
':path', '/api/chunky-visitors'
':method', 'GET'
':scheme', 'http'
'user-agent', 'curl/7.64.1'
'accept', 'application/vnd.pagerduty+json;version=2'
'x-pd-upstream', 'wcs-local'
'x-forwarded-proto', 'http'
'x-request-id', 'c2f1de20-5c40-41c0-b69e-7494e5c31953'
'x-envoy-expected-rq-timeout-ms', '15000'

[2022-02-18 17:44:47.469][27][debug][pool] [source/common/http/conn_pool_base.cc:74] queueing stream due to no available connections

Envoy creates a connection to upstream:

[2022-02-18 17:44:47.469][27][debug][pool] [source/common/conn_pool/conn_pool_base.cc:245] trying to create new connection
[2022-02-18 17:44:47.469][27][debug][pool] [source/common/conn_pool/conn_pool_base.cc:143] creating a new connection
[2022-02-18 17:44:47.469][27][debug][client] [source/common/http/codec_client.cc:60] [C1] connecting
[2022-02-18 17:44:47.469][27][debug][connection] [source/common/network/connection_impl.cc:864] [C1] connecting to 10.0.0.15:4000
[2022-02-18 17:44:47.469][27][debug][connection] [source/common/network/connection_impl.cc:880] [C1] connection in progress
[2022-02-18 17:44:47.470][27][debug][connection] [source/common/network/connection_impl.cc:669] [C1] connected
[2022-02-18 17:44:47.470][27][debug][client] [source/common/http/codec_client.cc:88] [C1] connected

Request is sent to upstream and response received:

[2022-02-18 17:44:47.470][27][debug][pool] [source/common/conn_pool/conn_pool_base.cc:289] [C1] attaching to next stream
[2022-02-18 17:44:47.470][27][debug][pool] [source/common/conn_pool/conn_pool_base.cc:175] [C1] creating stream
[2022-02-18 17:44:47.470][27][debug][router] [source/common/router/upstream_request.cc:386] [C0][S7749165874308896508] pool ready
[2022-02-18 17:44:47.530][27][debug][router] [source/common/router/router.cc:1230] [C0][S7749165874308896508] upstream headers complete: end_stream=false
[2022-02-18 17:44:47.530][27][debug][http] [source/common/http/conn_manager_impl.cc:1401] [C0][S7749165874308896508] closing connection due to connection close header
[2022-02-18 17:44:47.530][27][debug][http] [source/common/http/conn_manager_impl.cc:1456] [C0][S7749165874308896508] encoding headers via codec (end_stream=false):
':status', '200'
'cache-control', 'max-age=0, private, must-revalidate'
'content-type', 'text/html; charset=utf-8'
'date', 'Fri, 18 Feb 2022 17:44:46 GMT'
'server', 'envoy'
'x-request-id', 'c2f1de20-5c40-41c0-b69e-7494e5c31953'
'x-envoy-upstream-service-time', '60'
'connection', 'close'

[2022-02-18 17:44:47.530][27][debug][client] [source/common/http/codec_client.cc:130] [C1] response complete

The interesting part:

[2022-02-18 17:44:47.530][27][debug][connection] [source/common/network/connection_impl.cc:137] [C0] closing data_to_write=273 type=2
[2022-02-18 17:44:47.531][27][debug][connection] [source/common/network/connection_impl_base.cc:47] [C0] setting delayed close timer with timeout 1000 ms
[2022-02-18 17:44:47.531][27][debug][pool] [source/common/http/http1/conn_pool.cc:53] [C1] response complete
[2022-02-18 17:44:47.531][27][debug][pool] [source/common/conn_pool/conn_pool_base.cc:204] [C1] destroying stream: 0 remaining
[2022-02-18 17:44:47.532][27][debug][connection] [source/common/network/connection_impl.cc:699] [C0] write flush complete

DELAY

[2022-02-18 17:44:48.532][27][debug][connection] [source/common/network/connection_impl_base.cc:63] [C0] triggered delayed close
[2022-02-18 17:44:48.532][27][debug][connection] [source/common/network/connection_impl.cc:247] [C0] closing socket: 1
[2022-02-18 17:44:48.532][27][debug][conn_handler] [source/server/active_tcp_listener.cc:76] [C0] adding to cleanup list

Later (60s), the upstream connection is closed: [Remember, the upstream request is made with HTTP/1.1 which defaults to Keep-Alive.

[2022-02-18 17:45:47.473][27][debug][connection] [source/common/network/connection_impl.cc:637] [C1] remote close
[2022-02-18 17:45:47.473][27][debug][connection] [source/common/network/connection_impl.cc:247] [C1] closing socket: 0
[2022-02-18 17:45:47.473][27][debug][client] [source/common/http/codec_client.cc:107] [C1] disconnect. resetting 0 pending requests
[2022-02-18 17:45:47.473][27][debug][pool] [source/common/conn_pool/conn_pool_base.cc:407] [C1] client disconnected, failure reason:

NGINX

Resources

Clone this wiki locally