Reverse proxy: EOFs logged and remote requests terminated, while proxied request handlers still run and eventually succeed

Help
1

1. The problem I’m having:

I have a dockerized caddy-based reverse proxy for a docker container
with gunicorn + uvicorn python asyncio application (8 gunicorn workers). The server handles only requests from Google Cloud Tasks. It handles ~100 concurrent connections with varying request handling times ~15-600secs.

Some of the requests (5-10 per minute, ~5%) fail on Caddy and Cloud Tasks sides with EOF error resulting in 502 and retry by Cloud Tasks later.

Strangely, these requests are not terminated on my app’s side, but continue and eventually log a successful 20x status there. The EOF usually happens after ~3secs, but does not seem related to dial_timeout (having 3s default), as I increased it to 15s already. Cloud Tasks have 30mins timeout configured.
No mention of any TLS issues. I understand Caddy reports this EOF occurred on proxied side, not on remote side, doesn’t it? The proxied server is both IO and CPU intensive. Can it happen that Caddy looses patience when asyncio loop of the worker process which accepted the request is blocked for ~1s by processing data of requests being already handled and did not ACK’ed something?

I’d appreciate any suggestions what other gauges I could finetune to reduce or nix these EOFs, or increase diagnostics even more to nail down the issue.

2. Error messages and/or full log output:

Attached the logs for the sample EOF error occurred at 2023-12-24T07:57:40.315906313Z, with some lead records.
There are unrelated lines (for other concurrent requests), but obeying the instructions to not redact.

2023-12-24T07:57:35.580111840Z {"level":"debug","ts":1703404655.5798361,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.2:8081","duration":22.96602745,"request":{"remote_ip":"35.187.131.9","remote_port":"55865","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1095cbd3-c4db-4279-99b5-e8829414a7a6","headers":{"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1095cbd3-c4db-4279-99b5-e8829414a7a6"],"Authorization":[],"Content-Length":["110"],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Tasketa":["1703383584.6642709"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Forwarded-For":["35.187.131.9"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"headers":{"Date":["Sun, 24 Dec 2023 07:57:08 GMT"],"Server":["uvicorn"],"Content-Length":["0"]},"status":200}
2023-12-24T07:57:35.580250924Z {"level":"info","ts":1703404655.5798984,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.9","remote_port":"55865","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1095cbd3-c4db-4279-99b5-e8829414a7a6","headers":{"Connection":["keep-alive"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1095cbd3-c4db-4279-99b5-e8829414a7a6"],"X-Cloudtasks-Tasketa":["1703383584.6642709"],"Content-Length":["110"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"Authorization":[]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":22.966231441,"size":0,"status":200,"resp_headers":{"Server":["Caddy","uvicorn"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Date":["Sun, 24 Dec 2023 07:57:08 GMT"],"Content-Length":["0"]}}
2023-12-24T07:57:35.589419689Z {"level":"debug","ts":1703404655.5889893,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.2:8081","duration":1.917438936,"request":{"remote_ip":"35.187.131.1","remote_port":"62867","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_inspiration_generated_fan_in/06713aea-ba1c-4c0d-b719-edc280c6ab03","headers":{"X-Forwarded-Host":["backend.tarmacs.app"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_inspiration_generated_fan_in-06713aea-ba1c-4c0d-b719-edc280c6ab03"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Tasketa":["1703383672.5422189"],"X-Forwarded-For":["35.187.131.1"],"X-Forwarded-Proto":["https"],"X-Taskname-Prefix":["prod8-"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"Authorization":[],"Content-Length":["110"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"headers":{"Date":["Sun, 24 Dec 2023 07:57:33 GMT"],"Server":["uvicorn"],"Content-Length":["184"],"Content-Type":["application/json"]},"status":202}
2023-12-24T07:57:35.614630934Z {"level":"debug","ts":1703404655.6143615,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.2:8081","total_upstreams":1}
2023-12-24T07:57:35.620688995Z {"level":"info","ts":1703404655.6205664,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.1","remote_port":"62867","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_inspiration_generated_fan_in/06713aea-ba1c-4c0d-b719-edc280c6ab03","headers":{"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_inspiration_generated_fan_in-06713aea-ba1c-4c0d-b719-edc280c6ab03"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"Authorization":[],"Connection":["keep-alive"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Tasketa":["1703383672.5422189"],"Content-Length":["110"],"User-Agent":["Google-Cloud-Tasks"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":1.949094137,"size":184,"status":202,"resp_headers":{"Date":["Sun, 24 Dec 2023 07:57:33 GMT"],"Server":["Caddy","uvicorn"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Content-Length":["184"],"Content-Type":["application/json"]}}
2023-12-24T07:57:36.643674100Z {"level":"debug","ts":1703404656.6431744,"logger":"events","msg":"event","name":"tls_get_certificate","id":"08a7d7d2-b41b-4cbb-b2c9-19affb666927","origin":"tls","data":{"client_hello":{"CipherSuites":[51914,4865,4866,4867,49195,49199,52393,52392,49196,49200,49161,49171,49162,49172,156,157,47,53,10],"ServerName":"backend.tarmacs.app","SupportedCurves":[14906,29,23,24],"SupportedPoints":"AA==","SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537,513],"SupportedProtos":null,"SupportedVersions":[31354,772,771,770,769],"Conn":{}}}}
2023-12-24T07:57:36.643788957Z {"level":"debug","ts":1703404656.6432571,"logger":"tls.handshake","msg":"choosing certificate","identifier":"backend.tarmacs.app","num_choices":1}
2023-12-24T07:57:36.643838497Z {"level":"debug","ts":1703404656.6432722,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"backend.tarmacs.app","subjects":["backend.tarmacs.app"],"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"0f3484f082178df97b7758ba12afcf7dd9f75d6d532047e9d995fdfb6d9c10e8"}
2023-12-24T07:57:36.643885205Z {"level":"debug","ts":1703404656.6432798,"logger":"tls.handshake","msg":"matched certificate in cache","remote_ip":"35.187.131.8","remote_port":"35063","subjects":["backend.tarmacs.app"],"managed":true,"expiration":1706886562,"hash":"0f3484f082178df97b7758ba12afcf7dd9f75d6d532047e9d995fdfb6d9c10e8"}
2023-12-24T07:57:36.673656092Z {"level":"debug","ts":1703404656.6735106,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.2:8081","total_upstreams":1}
2023-12-24T07:57:36.729454509Z {"level":"debug","ts":1703404656.7292001,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.2:8081","duration":9.115197967,"request":{"remote_ip":"35.187.131.9","remote_port":"43170","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_inspiration_generated_fan_in/066ec187-ad18-429a-bf5b-af6685b8dd19","headers":{"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Taskexecutioncount":["0"],"Authorization":[],"X-Cloudtasks-Taskretrycount":["0"],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Tasketa":["1703383651.80917"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-For":["35.187.131.9"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_inspiration_generated_fan_in-066ec187-ad18-429a-bf5b-af6685b8dd19"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"headers":{"Date":["Sun, 24 Dec 2023 07:57:23 GMT"],"Server":["uvicorn"],"Content-Length":["0"]},"status":200}
2023-12-24T07:57:36.729603994Z {"level":"info","ts":1703404656.729267,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.9","remote_port":"43170","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_inspiration_generated_fan_in/066ec187-ad18-429a-bf5b-af6685b8dd19","headers":{"Connection":["keep-alive"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_inspiration_generated_fan_in-066ec187-ad18-429a-bf5b-af6685b8dd19"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"Authorization":[],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Tasketa":["1703383651.80917"],"Content-Length":["110"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":9.115350554,"size":0,"status":200,"resp_headers":{"Server":["Caddy","uvicorn"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Date":["Sun, 24 Dec 2023 07:57:23 GMT"],"Content-Length":["0"]}}
2023-12-24T07:57:37.112585812Z {"level":"debug","ts":1703404657.112348,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.2:8081","duration":2.281625907,"request":{"remote_ip":"35.187.131.9","remote_port":"52424","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/GenerateInspiration/Locality/handlers.inspirations.handlers.on_generate_inspiration/3856777680-road-5","headers":{"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-GenerateInspiration-handlers-inspirations-handlers-on_generate_inspiration-3856777680-road-5"],"X-Cloudtasks-Taskexecutioncount":["0"],"Content-Length":["12494"],"X-Cloudtasks-Taskpreviousresponse":["502"],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Queuename":["route-inspirations"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Tasketa":["1703332393.008184"],"X-Cloudtasks-Taskretryreason":[""],"Authorization":[],"X-Forwarded-Host":["backend.tarmacs.app"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskretrycount":["1"],"X-Forwarded-For":["35.187.131.9"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"headers":{"Date":["Sun, 24 Dec 2023 07:57:33 GMT"],"Server":["uvicorn"],"Content-Length":["0"]},"status":200}
2023-12-24T07:57:37.112688894Z {"level":"info","ts":1703404657.1124117,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.9","remote_port":"52424","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/GenerateInspiration/Locality/handlers.inspirations.handlers.on_generate_inspiration/3856777680-road-5","headers":{"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Queuename":["route-inspirations"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskretrycount":["1"],"X-Cloudtasks-Tasketa":["1703332393.008184"],"X-Cloudtasks-Taskretryreason":[""],"Authorization":[],"Connection":["keep-alive"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskname":["prod8-GenerateInspiration-handlers-inspirations-handlers-on_generate_inspiration-3856777680-road-5"],"X-Cloudtasks-Taskexecutioncount":["0"],"Content-Length":["12494"],"X-Cloudtasks-Taskpreviousresponse":["502"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":12494,"user_id":"","duration":2.281838697,"size":0,"status":200,"resp_headers":{"Server":["Caddy","uvicorn"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Date":["Sun, 24 Dec 2023 07:57:33 GMT"],"Content-Length":["0"]}}
2023-12-24T07:57:37.178978586Z {"level":"debug","ts":1703404657.1784348,"logger":"events","msg":"event","name":"tls_get_certificate","id":"e7775e9a-4321-4601-824f-d1bcddecd2f0","origin":"tls","data":{"client_hello":{"CipherSuites":[6682,4865,4866,4867,49195,49199,52393,52392,49196,49200,49161,49171,49162,49172,156,157,47,53,10],"ServerName":"backend.tarmacs.app","SupportedCurves":[39578,29,23,24],"SupportedPoints":"AA==","SignatureSchemes":[1027,2052,1025,1283,2053,1281,2054,1537,513],"SupportedProtos":null,"SupportedVersions":[47802,772,771,770,769],"Conn":{}}}}
2023-12-24T07:57:37.179091355Z {"level":"debug","ts":1703404657.178518,"logger":"tls.handshake","msg":"choosing certificate","identifier":"backend.tarmacs.app","num_choices":1}
2023-12-24T07:57:37.179141573Z {"level":"debug","ts":1703404657.1785314,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"backend.tarmacs.app","subjects":["backend.tarmacs.app"],"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"0f3484f082178df97b7758ba12afcf7dd9f75d6d532047e9d995fdfb6d9c10e8"}
2023-12-24T07:57:37.179190686Z {"level":"debug","ts":1703404657.1785393,"logger":"tls.handshake","msg":"matched certificate in cache","remote_ip":"35.187.131.8","remote_port":"43639","subjects":["backend.tarmacs.app"],"managed":true,"expiration":1706886562,"hash":"0f3484f082178df97b7758ba12afcf7dd9f75d6d532047e9d995fdfb6d9c10e8"}
2023-12-24T07:57:37.208305396Z {"level":"debug","ts":1703404657.2079353,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.2:8081","total_upstreams":1}
2023-12-24T07:57:37.630784390Z {"level":"debug","ts":1703404657.6306586,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.2:8081","total_upstreams":1}
2023-12-24T07:57:37.834868855Z {"level":"debug","ts":1703404657.8347251,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.2:8081","duration":28.220474596,"request":{"remote_ip":"35.187.131.8","remote_port":"53865","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/4aa605b7-6f14-4ab8-9216-82692148c14e","headers":{"X-Cloudtasks-Tasketa":["1703383572.8690279"],"X-Forwarded-Host":["backend.tarmacs.app"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"Authorization":[],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-4aa605b7-6f14-4ab8-9216-82692148c14e"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-For":["35.187.131.8"],"X-Forwarded-Proto":["https"],"Content-Length":["110"],"X-Taskname-Prefix":["prod8-"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"headers":{"Date":["Sun, 24 Dec 2023 07:57:02 GMT"],"Server":["uvicorn"],"Content-Length":["0"]},"status":200}
2023-12-24T07:57:37.835010386Z {"level":"info","ts":1703404657.834787,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.8","remote_port":"53865","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/4aa605b7-6f14-4ab8-9216-82692148c14e","headers":{"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-4aa605b7-6f14-4ab8-9216-82692148c14e"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703383572.8690279"],"Authorization":[],"Content-Length":["110"],"X-Taskname-Prefix":["prod8-"],"Connection":["keep-alive"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Queuename":["route-inspirations-desc"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":28.22067303,"size":0,"status":200,"resp_headers":{"Server":["Caddy","uvicorn"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Date":["Sun, 24 Dec 2023 07:57:02 GMT"],"Content-Length":["0"]}}
2023-12-24T07:57:38.614146725Z {"level":"debug","ts":1703404658.6140144,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.2:8081","total_upstreams":1}
2023-12-24T07:57:39.614014156Z {"level":"debug","ts":1703404659.6137335,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.2:8081","total_upstreams":1}
2023-12-24T07:57:40.315768696Z {"level":"debug","ts":1703404660.315638,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.2:8081","duration":4.701212013,"request":{"remote_ip":"35.187.131.8","remote_port":"63167","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50","headers":{"X-Cloudtasks-Tasketa":["1703383677.515168"],"Authorization":[],"User-Agent":["Google-Cloud-Tasks"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-63e248ac-e9e1-487b-b8a7-dbf1fcedff50"],"X-Forwarded-For":["35.187.131.8"],"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"error":"EOF"}
2023-12-24T07:57:40.315906313Z {"level":"error","ts":1703404660.3157141,"logger":"http.log.error.log0","msg":"EOF","request":{"remote_ip":"35.187.131.8","remote_port":"63167","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50","headers":{"X-Cloudtasks-Tasketa":["1703383677.515168"],"Authorization":[],"Connection":["keep-alive"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-63e248ac-e9e1-487b-b8a7-dbf1fcedff50"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"Content-Length":["110"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"duration":4.701361831,"status":502,"err_id":"wbixzfjcw","err_trace":"reverseproxy.statusError (reverseproxy.go:1265)"}
2023-12-24T07:57:40.316037009Z {"level":"error","ts":1703404660.3157442,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.8","remote_port":"63167","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50","headers":{"Content-Length":["110"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-63e248ac-e9e1-487b-b8a7-dbf1fcedff50"],"X-Cloudtasks-Tasketa":["1703383677.515168"],"Authorization":[],"Connection":["keep-alive"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":4.701361831,"size":0,"status":502,"resp_headers":{"Server":["Caddy"],"Alt-Svc":["h3=\":443\"; ma=2592000"]}}
2023-12-24T07:57:40.614417250Z {"level":"debug","ts":1703404660.6138892,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.2:8081","total_upstreams":1}

Attached, for the big picture, combined, time-ordered logs for: Cloud Tasks (cloudtasks.googleapis.com%2Ftask_operations_log), Caddy(gcplogs-docker-driver) which seem to be related (filtered by request URL or port 63167) and the app (remaining two lines).

Cloud Tasks report “INTERNAL” status (=50x response) immediately after Caddy EOF, while the requests handler succeeds 26s later (and generates correct products).

2023-12-24T07:57:35.594097672Z	cloudtasks.googleapis.com%2Ftask_operations_log	INFO	attemptDispatchLog: {dispatchCount: "1", dispatchReason: "PUSH_QUEUE", maxAttempts: 0, responseCount: "0", scheduleTime: "2023-12-24T02:07:57.515168Z", targetAddress: "POST https://backend.tarmacs.app/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50", targetType: "HTTP"}
2023-12-24T07:57:35.694332Z	python	DEBUG	handlers:deferred - 71: Handling task: task_name='prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-63e248ac-e9e1-487b-b8a7-dbf1fcedff50'
2023-12-24T07:57:40.315768696Z	gcplogs-docker-driver		{"level":"debug","ts":1703404660.315638,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.2:8081","duration":4.701212013,"request":{"remote_ip":"35.187.131.8","remote_port":"63167","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50","headers":{"X-Cloudtasks-Tasketa":["1703383677.515168"],"Authorization":[],"User-Agent":["Google-Cloud-Tasks"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-63e248ac-e9e1-487b-b8a7-dbf1fcedff50"],"X-Forwarded-For":["35.187.131.8"],"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"error":"EOF"}
2023-12-24T07:57:40.315906313Z	gcplogs-docker-driver		{"level":"error","ts":1703404660.3157141,"logger":"http.log.error.log0","msg":"EOF","request":{"remote_ip":"35.187.131.8","remote_port":"63167","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50","headers":{"X-Cloudtasks-Tasketa":["1703383677.515168"],"Authorization":[],"Connection":["keep-alive"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-63e248ac-e9e1-487b-b8a7-dbf1fcedff50"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"Content-Length":["110"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"duration":4.701361831,"status":502,"err_id":"wbixzfjcw","err_trace":"reverseproxy.statusError (reverseproxy.go:1265)"}
2023-12-24T07:57:40.316037009Z	gcplogs-docker-driver		{"level":"error","ts":1703404660.3157442,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.8","remote_port":"63167","client_ip":"35.187.131.8","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50","headers":{"Content-Length":["110"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-63e248ac-e9e1-487b-b8a7-dbf1fcedff50"],"X-Cloudtasks-Tasketa":["1703383677.515168"],"Authorization":[],"Connection":["keep-alive"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":4.701361831,"size":0,"status":502,"resp_headers":{"Server":["Caddy"],"Alt-Svc":["h3=\":443\"; ma=2592000"]}}
2023-12-24T07:57:40.334090456Z	cloudtasks.googleapis.com%2Ftask_operations_log	ERROR	AttemptResponseLog: {attemptDuration: "4.739945s", dispatchCount: "1", maxAttempts: 0, responseCount: "0", retryTime: "2023-12-24T08:17:40.334032Z", scheduleTime: "2023-12-24T02:07:57.515168Z", status: "INTERNAL", targetAddress: "POST https://backend.tarmacs.app/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50", targetType: "HTTP"}
2023-12-24T07:58:06.641617Z	run.googleapis.com%2Frequests	INFO	35.187.131.8:0 - "POST /_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/63e248ac-e9e1-487b-b8a7-dbf1fcedff50 HTTP/1.1" 200 OK

There is no sign of anything related to this request in Caddy logs when gunicorn finishes at 2023-12-24T07:58:06.641617Z.

3. Caddy version:

docker-compose exec caddy caddy version reports
v2.7.5 h1:HoysvZkLcN2xJExEepaFHK92Qgs7xAiCFydN5x5Hs6Q=

Tried with the following container images, same result:

  • lucaslorentz/caddy-docker-proxy:2.8-alpine
  • lucaslorentz/caddy-docker-proxy:alpine
  • lucaslorentz/caddy-docker-proxy:ci-alpine

4. How I installed and ran Caddy:

Running with docker-compose up caddy for a docker container configured with compose file pasted below.

a. System environment:

Docker on Linux 5.15.0-88-generic #98-Ubuntu SMP Mon Oct 2 15:18:56 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Distributor ID:	Ubuntu
Description:	Ubuntu 22.04.3 LTS
Release:	22.04
Codename:	jammy

b. Command:

docker-compose up -d caddy

c. Service/unit/compose file:

  backend:
    image: tarmacs/tarmacs:backend
    cap_add:
      - SYS_PTRACE   # py-spy debugging.
    depends_on:
      - backend-db
    labels:
      caddy: backend.tarmacs.app
      caddy.reverse_proxy.to: "{{upstreams 8081}}"
      caddy.reverse_proxy.transport: "http"
      caddy.reverse_proxy.transport.dial_timeout: "15s"
      caddy.log.level: "DEBUG"
    networks:
      - nginx-proxy
      - backend-network
    links:
      - backend-db
    extra_hosts:
      - "host.docker.internal:host-gateway"
    restart: unless-stopped

  caddy:
    image: lucaslorentz/caddy-docker-proxy:2.8-alpine
    ports:
      - "80:80"
      - "443:443"
    environment:
      - CADDY_INGRESS_NETWORKS=nginx-proxy
    networks:
      - nginx-proxy
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
      - caddy_data:/data
    restart: unless-stopped
    labels:
      caddy.log: ""
      caddy.log.level: DEBUG
      caddy.debug: true

d. My complete Caddy config:

This is what I found in /config/caddy/Caddyfile.autosave. This is generated by the Docker container from docker-compose labels.

Note that I increased dial_timeout from default (being 3s) to 15s. I made that after noticing that EOFs usually occur after ~3s which seemed to be related.
This did not change neither frequency or time after request start when EOF occurs.

{
	debug true
	log {
		level DEBUG
	}
}
backend.tarmacs.app {
	log {
		level DEBUG
	}
	reverse_proxy {
		to 172.18.0.2:8081
		transport http {
			dial_timeout 15s
		}
	}
}

5. Links to relevant resources:

2

Please use Caddy v2.7.6. It’s possible your issue is fixed in that version. If not, we can dig deeper.

3

Thanks for the suggestion. Just pulled latest lucaslorentz/caddy-docker-proxy:ci-alpine image and restarted. Now the live container reports 2.7.6. No change unfortunately - still seeing these EOFs with similar frequency.

a72de27f7b3d   lucaslorentz/caddy-docker-proxy:ci-alpine   "/bin/caddy docker-p…"   2 minutes ago   Up 2 minutes

$ docker exec -it a72 caddy version
v2.7.6 h1:w0NymbG2m9PcvKWsrXO6EEkY9Ru4FJK8uQbYcev1p3A=
4

Add verbose_logs sub-directive inside the reverse_proxy directive for more detailed logs to share with us. The sub-directive does not take any values.

5

Added verbose_logs label, resulting in the following caddy config:

# cat /config/caddy/Caddyfile.autosave 
{
	debug true
	log {
		level DEBUG
	}
}
backend.tarmacs.app {
	log {
		level DEBUG
	}
	reverse_proxy {
		to 172.18.0.4:8081
		transport http {
			dial_timeout 15s
		}
		verbose_logs
	}
}

Below are the logs for the time range of sample EOF ocurrence, for the following request from Cloud Tasks, started 07:07:35, EOF 07:07:37; actually finished 07:07:50; some lines might be unrelated (other requests):

Request:

2023-12-27T07:07:35.092768951Z {"@type":"type.googleapis.com/google.cloud.tasks.logging.v1.TaskActivityLog", "attemptDispatchLog": {dispatchCount: "1",dispatchReason: "PUSH_QUEUE",maxAttempts: 0,responseCount: "0",scheduleTime: "2023-12-27T01:45:16.103635Z",targetAddress: "POST https://backend.tarmacs.app/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/cafc6930-ac6b-4df0-b359-4fc1b3961c5b",targetType: "HTTP"}, "task":"projects/tarmacs-app/locations/europe-west3/queues/route-inspirations-desc/tasks/prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-cafc6930-ac6b-4df0-b359-4fc1b3961c5b"}
2023-12-27T07:07:37.754040517Z {"@type":"type.googleapis.com/google.cloud.tasks.logging.v1.TaskActivityLog", "attemptResponseLog":{attemptDuration: "2.661203s",dispatchCount: "1",maxAttempts: 0,responseCount: "0",retryTime: "2023-12-27T07:27:37.75396Z",scheduleTime: "2023-12-27T01:45:16.103635Z",status: "INTERNAL",targetAddress: "POST https://backend.tarmacs.app/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/cafc6930-ac6b-4df0-b359-4fc1b3961c5b",targetType: "HTTP"}, "task":"projects/tarmacs-app/locations/europe-west3/queues/route-inspirations-desc/tasks/prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-cafc6930-ac6b-4df0-b359-4fc1b3961c5b"}
2023-12-27T07:07:50.237985Z 35.187.131.1:0 - "POST /_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/cafc6930-ac6b-4df0-b359-4fc1b3961c5b HTTP/1.1" 200 OK

Caddy:

tarmacs-caddy-1  | 2023-12-27T07:07:35.114710264Z {"level":"debug","ts":1703660855.1145988,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.4:8081","total_upstreams":1}
tarmacs-caddy-1  | 2023-12-27T07:07:37.092577192Z {"level":"debug","ts":1703660857.0924425,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.4:8081","duration":16.977512261,"request":{"remote_ip":"35.187.131.9","remote_port":"40789","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/eb01a466-207c-4a74-b584-9c01c61419aa","headers":{"X-Cloudtasks-Taskpreviousresponse":["502"],"Accept-Encoding":["gzip, deflate, br"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-eb01a466-207c-4a74-b584-9c01c61419aa"],"X-Cloudtasks-Taskretrycount":["1"],"Content-Length":["110"],"X-Forwarded-For":["35.187.131.9"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Host":["backend.tarmacs.app"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskretryreason":[""],"X-Taskname-Prefix":["prod8-"],"Authorization":[],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Tasketa":["1703641483.1247928"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"headers":{"Date":["Wed, 27 Dec 2023 07:07:19 GMT"],"Server":["uvicorn"],"Content-Length":["0"]},"status":200}
tarmacs-caddy-1  | 2023-12-27T07:07:37.092736783Z {"level":"debug","ts":1703660857.0924826,"logger":"http.handlers.reverse_proxy","msg":"wrote header","upstream":"172.18.0.4:8081","duration":16.977512261,"request":{"remote_ip":"35.187.131.9","remote_port":"40789","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/eb01a466-207c-4a74-b584-9c01c61419aa","headers":{"X-Cloudtasks-Taskpreviousresponse":["502"],"Accept-Encoding":["gzip, deflate, br"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-eb01a466-207c-4a74-b584-9c01c61419aa"],"X-Cloudtasks-Taskretrycount":["1"],"Content-Length":["110"],"X-Forwarded-For":["35.187.131.9"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Host":["backend.tarmacs.app"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskretryreason":[""],"X-Taskname-Prefix":["prod8-"],"Authorization":[],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Tasketa":["1703641483.1247928"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.092810208Z {"level":"debug","ts":1703660857.0925298,"logger":"http.handlers.reverse_proxy","msg":"waiting to read from upstream","upstream":"172.18.0.4:8081","duration":16.977512261,"request":{"remote_ip":"35.187.131.9","remote_port":"40789","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/eb01a466-207c-4a74-b584-9c01c61419aa","headers":{"X-Cloudtasks-Taskpreviousresponse":["502"],"Accept-Encoding":["gzip, deflate, br"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-eb01a466-207c-4a74-b584-9c01c61419aa"],"X-Cloudtasks-Taskretrycount":["1"],"Content-Length":["110"],"X-Forwarded-For":["35.187.131.9"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Host":["backend.tarmacs.app"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskretryreason":[""],"X-Taskname-Prefix":["prod8-"],"Authorization":[],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Tasketa":["1703641483.1247928"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.092885221Z {"level":"debug","ts":1703660857.0925415,"logger":"http.handlers.reverse_proxy","msg":"read from upstream","upstream":"172.18.0.4:8081","duration":16.977512261,"request":{"remote_ip":"35.187.131.9","remote_port":"40789","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/eb01a466-207c-4a74-b584-9c01c61419aa","headers":{"X-Cloudtasks-Taskpreviousresponse":["502"],"Accept-Encoding":["gzip, deflate, br"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-eb01a466-207c-4a74-b584-9c01c61419aa"],"X-Cloudtasks-Taskretrycount":["1"],"Content-Length":["110"],"X-Forwarded-For":["35.187.131.9"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Host":["backend.tarmacs.app"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskretryreason":[""],"X-Taskname-Prefix":["prod8-"],"Authorization":[],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Tasketa":["1703641483.1247928"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"read":0,"error":"EOF"}
tarmacs-caddy-1  | 2023-12-27T07:07:37.092957021Z {"level":"debug","ts":1703660857.0925536,"logger":"http.handlers.reverse_proxy","msg":"closed response body from upstream","upstream":"172.18.0.4:8081","duration":16.977512261,"request":{"remote_ip":"35.187.131.9","remote_port":"40789","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/eb01a466-207c-4a74-b584-9c01c61419aa","headers":{"X-Cloudtasks-Taskpreviousresponse":["502"],"Accept-Encoding":["gzip, deflate, br"],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-eb01a466-207c-4a74-b584-9c01c61419aa"],"X-Cloudtasks-Taskretrycount":["1"],"Content-Length":["110"],"X-Forwarded-For":["35.187.131.9"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Host":["backend.tarmacs.app"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskretryreason":[""],"X-Taskname-Prefix":["prod8-"],"Authorization":[],"X-Forwarded-Proto":["https"],"X-Cloudtasks-Tasketa":["1703641483.1247928"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.093111073Z {"level":"info","ts":1703660857.0925727,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.9","remote_port":"40789","client_ip":"35.187.131.9","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/eb01a466-207c-4a74-b584-9c01c61419aa","headers":{"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-eb01a466-207c-4a74-b584-9c01c61419aa"],"X-Cloudtasks-Taskretrycount":["1"],"X-Cloudtasks-Taskexecutioncount":["0"],"Content-Length":["110"],"Connection":["keep-alive"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskpreviousresponse":["502"],"Authorization":[],"X-Cloudtasks-Tasketa":["1703641483.1247928"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Taskretryreason":[""],"User-Agent":["Google-Cloud-Tasks"],"X-Taskname-Prefix":["prod8-"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":16.977719138,"size":0,"status":200,"resp_headers":{"Server":["Caddy","uvicorn"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Date":["Wed, 27 Dec 2023 07:07:19 GMT"],"Content-Length":["0"]}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.318843960Z {"level":"debug","ts":1703660857.318729,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.4:8081","duration":8.204542941,"request":{"remote_ip":"35.187.131.1","remote_port":"53197","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1ee23252-496f-4273-b647-ad1480870dac","headers":{"User-Agent":["Google-Cloud-Tasks"],"X-Forwarded-Proto":["https"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703641503.36343"],"Authorization":[],"X-Cloudtasks-Taskretrycount":["0"],"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1ee23252-496f-4273-b647-ad1480870dac"],"X-Forwarded-For":["35.187.131.1"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"headers":{"Date":["Wed, 27 Dec 2023 07:07:26 GMT"],"Server":["uvicorn"],"Content-Length":["0"]},"status":200}
tarmacs-caddy-1  | 2023-12-27T07:07:37.318972692Z {"level":"debug","ts":1703660857.3187656,"logger":"http.handlers.reverse_proxy","msg":"wrote header","upstream":"172.18.0.4:8081","duration":8.204542941,"request":{"remote_ip":"35.187.131.1","remote_port":"53197","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1ee23252-496f-4273-b647-ad1480870dac","headers":{"User-Agent":["Google-Cloud-Tasks"],"X-Forwarded-Proto":["https"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703641503.36343"],"Authorization":[],"X-Cloudtasks-Taskretrycount":["0"],"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1ee23252-496f-4273-b647-ad1480870dac"],"X-Forwarded-For":["35.187.131.1"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.319044201Z {"level":"debug","ts":1703660857.3187764,"logger":"http.handlers.reverse_proxy","msg":"waiting to read from upstream","upstream":"172.18.0.4:8081","duration":8.204542941,"request":{"remote_ip":"35.187.131.1","remote_port":"53197","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1ee23252-496f-4273-b647-ad1480870dac","headers":{"User-Agent":["Google-Cloud-Tasks"],"X-Forwarded-Proto":["https"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703641503.36343"],"Authorization":[],"X-Cloudtasks-Taskretrycount":["0"],"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1ee23252-496f-4273-b647-ad1480870dac"],"X-Forwarded-For":["35.187.131.1"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.319110259Z {"level":"debug","ts":1703660857.318782,"logger":"http.handlers.reverse_proxy","msg":"read from upstream","upstream":"172.18.0.4:8081","duration":8.204542941,"request":{"remote_ip":"35.187.131.1","remote_port":"53197","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1ee23252-496f-4273-b647-ad1480870dac","headers":{"User-Agent":["Google-Cloud-Tasks"],"X-Forwarded-Proto":["https"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703641503.36343"],"Authorization":[],"X-Cloudtasks-Taskretrycount":["0"],"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1ee23252-496f-4273-b647-ad1480870dac"],"X-Forwarded-For":["35.187.131.1"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"read":0,"error":"EOF"}
tarmacs-caddy-1  | 2023-12-27T07:07:37.319171702Z {"level":"debug","ts":1703660857.3187938,"logger":"http.handlers.reverse_proxy","msg":"closed response body from upstream","upstream":"172.18.0.4:8081","duration":8.204542941,"request":{"remote_ip":"35.187.131.1","remote_port":"53197","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1ee23252-496f-4273-b647-ad1480870dac","headers":{"User-Agent":["Google-Cloud-Tasks"],"X-Forwarded-Proto":["https"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703641503.36343"],"Authorization":[],"X-Cloudtasks-Taskretrycount":["0"],"Content-Length":["110"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1ee23252-496f-4273-b647-ad1480870dac"],"X-Forwarded-For":["35.187.131.1"],"X-Forwarded-Host":["backend.tarmacs.app"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.319233244Z {"level":"info","ts":1703660857.318813,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.1","remote_port":"53197","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/1ee23252-496f-4273-b647-ad1480870dac","headers":{"X-Cloudtasks-Tasketa":["1703641503.36343"],"Authorization":[],"Connection":["keep-alive"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskexecutioncount":["0"],"User-Agent":["Google-Cloud-Tasks"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-1ee23252-496f-4273-b647-ad1480870dac"],"X-Cloudtasks-Taskretrycount":["0"],"Content-Length":["110"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":8.204690635,"size":0,"status":200,"resp_headers":{"Server":["Caddy","uvicorn"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Date":["Wed, 27 Dec 2023 07:07:26 GMT"],"Content-Length":["0"]}}
tarmacs-caddy-1  | 2023-12-27T07:07:37.680345730Z {"level":"debug","ts":1703660857.680237,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"172.18.0.4:8081","total_upstreams":1}
tarmacs-caddy-1  | 2023-12-27T07:07:37.736557745Z {"level":"debug","ts":1703660857.7364273,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"172.18.0.4:8081","duration":2.621771958,"request":{"remote_ip":"35.187.131.1","remote_port":"53961","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/cafc6930-ac6b-4df0-b359-4fc1b3961c5b","headers":{"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Forwarded-Proto":["https"],"X-Forwarded-Host":["backend.tarmacs.app"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703641516.1036348"],"Authorization":[],"X-Forwarded-For":["35.187.131.1"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-cafc6930-ac6b-4df0-b359-4fc1b3961c5b"],"Content-Length":["110"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"error":"EOF"}
tarmacs-caddy-1  | 2023-12-27T07:07:37.736699212Z {"level":"error","ts":1703660857.7364874,"logger":"http.log.error.log0","msg":"EOF","request":{"remote_ip":"35.187.131.1","remote_port":"53961","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/cafc6930-ac6b-4df0-b359-4fc1b3961c5b","headers":{"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-cafc6930-ac6b-4df0-b359-4fc1b3961c5b"],"Content-Length":["110"],"Connection":["keep-alive"],"Accept-Encoding":["gzip, deflate, br"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Tasketa":["1703641516.1036348"],"Authorization":[],"User-Agent":["Google-Cloud-Tasks"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"duration":2.621887232,"status":502,"err_id":"hdcca84ms","err_trace":"reverseproxy.statusError (reverseproxy.go:1267)"}
tarmacs-caddy-1  | 2023-12-27T07:07:37.736781073Z {"level":"error","ts":1703660857.736507,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"35.187.131.1","remote_port":"53961","client_ip":"35.187.131.1","proto":"HTTP/1.1","method":"POST","host":"backend.tarmacs.app","uri":"/_ah/queue/deferred/RouteInspirationGenerated/RouteInspiration/handlers.inspirations.handlers.on_generate_inspiration_preview/cafc6930-ac6b-4df0-b359-4fc1b3961c5b","headers":{"X-Cloudtasks-Tasketa":["1703641516.1036348"],"Authorization":[],"User-Agent":["Google-Cloud-Tasks"],"X-Cloudtasks-Taskretrycount":["0"],"X-Cloudtasks-Taskexecutioncount":["0"],"X-Cloudtasks-Taskname":["prod8-RouteInspirationGenerated-handlers-inspirations-handlers-on_generate_inspiration_preview-cafc6930-ac6b-4df0-b359-4fc1b3961c5b"],"Content-Length":["110"],"Connection":["keep-alive"],"Accept-Encoding":["gzip, deflate, br"],"X-Taskname-Prefix":["prod8-"],"X-Cloudtasks-Queuename":["route-inspirations-desc"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","server_name":"backend.tarmacs.app"}},"bytes_read":110,"user_id":"","duration":2.621887232,"size":0,"status":502,"resp_headers":{"Server":["Caddy"],"Alt-Svc":["h3=\":443\"; ma=2592000"]}}
6

This line says the EOF is not Caddy itself giving up, rather our read attempt returns a signal for us that the connection has ended. The read attempt traces to these lines in the Go runtime, which basically means we’re not getting a successful response from the syscall. I wonder what is actually happening in these lines.

Are you sure Cloud Task returns a response when it receives a request, or does it just terminate the connection? (admittedly, the latter would be odd)

If possible, is it possible for you to POST a task using curl -v?

By the way, using debug true is incorrect. It should be just debug without arguments.

7

Can you show me your uvicorn and gunicorn configurations? I found there is an option called --timeout-keep-alive. And I found there is similar issue on github, though it’s with a very large request body, not the small ones like yours.

How many requests does your server handle per second? My guess is that there is a bug with uvicorn http keep-alive. The body is read and handled, but the connection is gone and the response is lost. Does unicorn have a way of detecting underlying connection issues? Like failed to write 200 response.

8

Thanks for the additional questions!

Are you sure Cloud Task returns a response when it receives a request, or does it just terminate the connection? (admittedly, the latter would be odd)

I am not able to debug that deeper, not having any introspection into what Cloud Tasks does.

And here is the gunicorn config:

gunicorn --workers=8 --worker-class=uvicorn.workers.UvicornWorker --bind=0.0.0.0:8081 --forwarded-allow-ips=* --timeout=1801 --max-requests=1000 --max-requests-jitter=100 --access-logfile=-