Slow POST through proxy causes timeout after 5 seconds

[andre-perry-deidle]

When posting a large body over a slow internet connection the connection is cancelled after 5 seconds. I've tracked it down to the graceful wrapper but couldn't figure out why it was causing the issue.

I removed launching the proxy with graceful and it works now.

May 03 03:16:28 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:28Z" level=info msg="started handling request" method=POST remote=x.x.x.x request=/api/v1/item
May 03 03:16:28 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:28Z" level=info msg="Access request granted" access_url="https://api-server/api/v1/item" granted=true mode=policy reason="Rule requires policy-base
May 03 03:16:33 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:33Z" level=info msg="Round trip failed" error="read tcp 127.0.0.1:4455->127.0.0.1:38400: i/o timeout" url="http://localhost:3000/api/v1/item"
May 03 03:16:33 instance-1 oathkeeper[2170]: 2018/05/03 03:16:33 http: proxy error: read tcp 127.0.0.1:4455->127.0.0.1:38400: i/o timeout
May 03 03:16:33 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:33Z" level=info msg="completed handling request" measure#oathkeeper-proxy.latency=4999954714 method=POST remote=x.x.x.x request=/api/v1/item stat
May 03 03:16:47 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:47Z" level=info msg="started handling request" method=POST remote=x.x.x.x request=/api/v1/item
May 03 03:16:47 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:47Z" level=info msg="Access request granted" access_url="https://api-server/api/v1/item" granted=true mode=policy reason="Rule requires policy-base
May 03 03:16:52 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:52Z" level=info msg="Round trip failed" error="read tcp 127.0.0.1:4455->127.0.0.1:38410: i/o timeout" url="http://localhost:3000/api/v1/item"
May 03 03:16:52 instance-1 oathkeeper[2170]: 2018/05/03 03:16:52 http: proxy error: read tcp 127.0.0.1:4455->127.0.0.1:38410: i/o timeout
May 03 03:16:52 instance-1 oathkeeper[2170]: time="2018-05-03T03:16:52Z" level=info msg="completed handling request" measure#oathkeeper-proxy.latency=4999908503 method=POST remote=x.x.x.x request=/api/v1/item stat
May 03 03:17:51 instance-1 oathkeeper[2170]: time="2018-05-03T03:17:51Z" level=info msg="started handling request" method=POST remote=x.x.x.x request=/api/v1/item
May 03 03:17:51 instance-1 oathkeeper[2170]: time="2018-05-03T03:17:51Z" level=info msg="Access request granted" access_url="https://api-server/api/v1/item" granted=true mode=policy reason="Rule requires policy-base
May 03 03:17:56 instance-1 oathkeeper[2170]: time="2018-05-03T03:17:56Z" level=info msg="Round trip failed" error="read tcp 127.0.0.1:4455->127.0.0.1:38418: i/o timeout" url="http://localhost:3000/api/v1/item"
May 03 03:17:56 instance-1 oathkeeper[2170]: 2018/05/03 03:17:56 http: proxy error: read tcp 127.0.0.1:4455->127.0.0.1:38418: i/o timeout
May 03 03:17:56 instance-1 oathkeeper[2170]: time="2018-05-03T03:17:56Z" level=info msg="completed handling request" measure#oathkeeper-proxy.latency=4999861120 method=POST remote=x.x.x.x request=/api/v1/item stat
May 03 03:19:10 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:10Z" level=info msg="started handling request" method=POST remote=x.x.x.x request=/api/v1/item
May 03 03:19:10 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:10Z" level=info msg="Access request granted" access_url="https://api-server/api/v1/item" granted=true mode=policy reason="Rule requires policy-base
May 03 03:19:15 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:15Z" level=info msg="Round trip failed" error="context canceled" url="http://localhost:3000/api/v1/item"
May 03 03:19:15 instance-1 oathkeeper[2170]: 2018/05/03 03:19:15 http: proxy error: context canceled
May 03 03:19:15 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:15Z" level=info msg="completed handling request" measure#oathkeeper-proxy.latency=5000230223 method=POST remote=x.x.x.x request=/api/v1/item stat
May 03 03:19:33 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:33Z" level=info msg="started handling request" method=POST remote=x.x.x.x request=/api/v1/item
May 03 03:19:33 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:33Z" level=info msg="Access request granted" access_url="https://api-server/api/v1/item" granted=true mode=policy reason="Rule requires policy-base
May 03 03:19:38 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:38Z" level=info msg="Round trip failed" error="read tcp 127.0.0.1:4455->127.0.0.1:38436: i/o timeout" url="http://localhost:3000/api/v1/item"
May 03 03:19:38 instance-1 oathkeeper[2170]: 2018/05/03 03:19:38 http: proxy error: read tcp 127.0.0.1:4455->127.0.0.1:38436: i/o timeout
May 03 03:19:38 instance-1 oathkeeper[2170]: time="2018-05-03T03:19:38Z" level=info msg="completed handling request" measure#oathkeeper-proxy.latency=5000137768 method=POST remote=x.x.x.x request=/api/v1/item stat
May 03 03:22:07 instance-1 oathkeeper[2170]: time="2018-05-03T03:22:07Z" level=info msg="started handling request" method=POST remote=x.x.x.x request=/api/v1/item

[aeneasr]

That time out is there to protect the proxy from request stragglers and intentionally harmful clients. It would make sense though to have this configurable, which is possible!

[andre-perry-deidle]

I was mislead by the name graceful and though it was intended to handle only shutdown or restart of the process. I since found the http server settings applied in https://github.com/ory/graceful/blob/master/http_defaults.go#L55

I'm using this as a sidecar and there is an upstream proxy offloading TLS and handling timeouts. Perhaps oathkeeper could do with a similar method to hydra of trusting upstream for TLS via source IP and XFF headers and disabling timeouts.

[aeneasr]

I think we can keep this issue open, it's possible to configure the settings provided by graceful which would - I guess - make tons of sense in this scenario. The settings have been used for other projects whose APIs accept - at maximum - POST bodies of max 2kb. In the proxy scenario however, it makes much more sense to be able to configure the timeouts in order to support use cases such as yours.

[aeneasr]

Closed by #132