Server not reachable after a few days

Help
21

The “context canceled” error when it happens in reverse_proxy, is often because the client (browser) canceled the request before it could finish.

What “context” means here, is in Go, there’s an object called the “Context” which is passed from high level code down into lower level code which is like a handle on the current operation (in this case the HTTP request) so that if at any point the operation needs to be canceled, it can be done gracefully (there’s some other benefits, but they’re off-topic).

What we do see though is that that last request took very long, 45 seconds. This makes me think that the upstream just hung/died while Caddy was waiting for a response back. But what actually canceled it was the browser canceling the request, i.e. signaling “nevermind you took too long, I’m done waiting”.

That’s all I can read from these logs.

1 Like
22

Yep, seconding this, it looks like the client is simply canceling the request.

If you want us to look into it further, we need a curl -v command like we’ve been asking for, with its output, and ideally a way to reproduce it as minimally as possible.

But so far, with the information given, looks like everything is working fine.

23

(to be clear, Matt means “everything is working fine” in Caddy, problem is likely elsewhere)

1 Like
24

I will have another look at this. I already pasted curl -v command output when it happens. I will monitor the upstream to look for errors. one thing which is not clear is once i restart the server all requests start working fine, There is no hang up. The calls are not api requests. Its a direct page load and i think the timeout will be more for url loading in browsers

25

Thanks for mentioning that, it looks like it was edited into a previous post instead of being appended as a new post, and I didn’t see the edit.

“empty reply from server” is interesting, maybe the proxied backend is doing something funky with the request stream (when proxying, there are more ways to cancel the context than just the client aborting the request).

26

proxied server is a vercel next js project

27

Hello again. So now, first time since I posted this thread, my website is down and unreachable. I will now keep it down to be able to debug. Usually I can do a docker stop caddy followed by a docker start caddy to get the site up again.

I’m able to log into my server through SSH and here I’ve tried a curl -v.

curl -v https://bonsy.se

*   Trying 64.225.66.142:443...
* TCP_NODELAY set
* Connected to bonsy.se (64.225.66.142) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: CN=bonsy.se
*  start date: Feb  4 10:55:59 2022 GMT
*  expire date: May  5 10:55:58 2022 GMT
*  subjectAltName: host "bonsy.se" matched cert's "bonsy.se"
*  issuer: C=US; O=Let's Encrypt; CN=R3
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x558a6690a880)
> GET / HTTP/2
> Host: bonsy.se
> user-agent: curl/7.68.0
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* Connection state changed (MAX_CONCURRENT_STREAMS == 250)!
< HTTP/2 502 
< server: Caddy
< content-length: 0
< date: Tue, 08 Feb 2022 10:10:57 GMT
< 
* Connection #0 to host bonsy.se left intact

Some debug logs from same time in Docker

{
   "level":"debug",
   "ts":1644314928.1362245,
   "logger":"tls.handshake",
   "msg":"choosing certificate",
   "identifier":"bonsy.se",
   "num_choices":1
}

{
   "level":"debug",
   "ts":1644314928.136262,
   "logger":"tls.handshake",
   "msg":"default certificate selection results",
   "identifier":"bonsy.se",
   "subjects":[
      "bonsy.se"
   ],
   "managed":true,
   "issuer_key":"acme-v02.api.letsencrypt.org-directory",
   "hash":"bee36bfe4698584977f2c81c8c4b4212a0a2a9ad767fdac937c044a0eae82928"
}

{
   "level":"debug",
   "ts":1644314928.1362693,
   "logger":"tls.handshake",
   "msg":"matched certificate in cache",
   "subjects":[
      "bonsy.se"
   ],
   "managed":true,
   "expiration":1651748158,
   "hash":"bee36bfe4698584977f2c81c8c4b4212a0a2a9ad767fdac937c044a0eae82928"
}

{
   "level":"debug",
   "ts":1644314928.1393726,
   "logger":"http.handlers.rewrite",
   "msg":"rewrote request",
   "request":{
      "remote_addr":"64.225.66.142:50098",
      "proto":"HTTP/2.0",
      "method":"GET",
      "host":"bonsy.se",
      "uri":"/",
      "headers":{
         "User-Agent":[
            "curl/7.68.0"
         ],
         "Accept":[
            "*/*"
         ]
      },
      "tls":{
         "resumed":false,
         "version":772,
         "cipher_suite":4865,
         "proto":"h2",
         "proto_mutual":true,
         "server_name":"bonsy.se"
      }
   },
   "method":"GET",
   "uri":"/index.php"
}

{
   "level":"debug",
   "ts":1644314928.1394913,
   "logger":"http.reverse_proxy.transport.fastcgi",
   "msg":"roundtrip",
   "request":{
      "remote_addr":"64.225.66.142:50098",
      "proto":"HTTP/2.0",
      "method":"GET",
      "host":"bonsy.se",
      "uri":"/index.php",
      "headers":{
         "X-Forwarded-For":[
            "64.225.66.142"
         ],
         "X-Forwarded-Proto":[
            "https"
         ],
         "User-Agent":[
            "curl/7.68.0"
         ],
         "Accept":[
            "*/*"
         ]
      },
      "tls":{
         "resumed":false,
         "version":772,
         "cipher_suite":4865,
         "proto":"h2",
         "proto_mutual":true,
         "server_name":"bonsy.se"
      }
   },
   "dial":"php:9000",
   "env":{
      "AUTH_TYPE":"",
      "CONTENT_LENGTH":"",
      "CONTENT_TYPE":"",
      "DOCUMENT_ROOT":"/var/www/public",
      "DOCUMENT_URI":"/index.php",
      "GATEWAY_INTERFACE":"CGI/1.1",
      "HTTPS":"on",
      "HTTP_ACCEPT":"*/*",
      "HTTP_HOST":"bonsy.se",
      "HTTP_USER_AGENT":"curl/7.68.0",
      "HTTP_X_FORWARDED_FOR":"64.225.66.142",
      "HTTP_X_FORWARDED_PROTO":"https",
      "PATH_INFO":"",
      "QUERY_STRING":"",
      "REMOTE_ADDR":"64.225.66.142",
      "REMOTE_HOST":"64.225.66.142",
      "REMOTE_IDENT":"",
      "REMOTE_PORT":"50098",
      "REMOTE_USER":"",
      "REQUEST_METHOD":"GET",
      "REQUEST_SCHEME":"https",
      "REQUEST_URI":"/",
      "SCRIPT_FILENAME":"/var/www/public/index.php",
      "SCRIPT_NAME":"/index.php",
      "SERVER_NAME":"bonsy.se",
      "SERVER_PROTOCOL":"HTTP/2.0",
      "SERVER_SOFTWARE":"Caddy/v2.4.6",
      "SSL_CIPHER":"TLS_AES_128_GCM_SHA256",
      "SSL_PROTOCOL":"TLSv1.3"
   }
}

{
   "level":"debug",
   "ts":1644315057.5020938,
   "logger":"http.handlers.reverse_proxy",
   "msg":"upstream roundtrip",
   "upstream":"php:9000",
   "duration":129.362634004,
   "request":{
      "remote_addr":"64.225.66.142:50098",
      "proto":"HTTP/2.0",
      "method":"GET",
      "host":"bonsy.se",
      "uri":"/index.php",
      "headers":{
         "User-Agent":[
            "curl/7.68.0"
         ],
         "Accept":[
            "*/*"
         ],
         "X-Forwarded-For":[
            "64.225.66.142"
         ],
         "X-Forwarded-Proto":[
            "https"
         ]
      },
      "tls":{
         "resumed":false,
         "version":772,
         "cipher_suite":4865,
         "proto":"h2",
         "proto_mutual":true,
         "server_name":"bonsy.se"
      }
   },
   "error":"dialing backend: dial tcp 172.19.0.3:9000: connect: connection timed out"
}

{
   "level":"error",
   "ts":1644315057.5021753,
   "logger":"http.log.error",
   "msg":"dialing backend: dial tcp 172.19.0.3:9000: connect: connection timed out",
   "request":{
      "remote_addr":"64.225.66.142:50098",
      "proto":"HTTP/2.0",
      "method":"GET",
      "host":"bonsy.se",
      "uri":"/",
      "headers":{
         "User-Agent":[
            "curl/7.68.0"
         ],
         "Accept":[
            "*/*"
         ]
      },
      "tls":{
         "resumed":false,
         "version":772,
         "cipher_suite":4865,
         "proto":"h2",
         "proto_mutual":true,
         "server_name":"bonsy.se"
      }
   },
   "duration":129.362957129,
   "status":502,
   "err_id":"yxibd6cuj",
   "err_trace":"reverseproxy.statusError (reverseproxy.go:886)"
}

I would really appreciate any guidens/help to continue debugging so I’m able to fix this issue.

I do seem to get the same result if I curl -v the IP-address as well.

PHP logs only show this: (which was yesterday when things stopped working):

php_1      | 172.19.0.4 -  07/Feb/2022:06:50:08 +0000 "POST /index.php" 200
php_1      | 172.19.0.4 -  07/Feb/2022:06:50:08 +0000 "POST /index.php" 200

I can verify that my PHP server is running

.....$ docker-compose exec php php -v
PHP 8.1.0 (cli) (built: Nov 30 2021 06:20:01) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.1.0, Copyright (c) Zend Technologies

IP-address inspection

# docker inspect -f '{{range.NetworkSettings.Networks}}{{.IPAddress}}{{end}}' bonsy_php
172.19.0.3
# docker inspect -f '{{range.NetworkSettings.Networks}}{{.IPAddress}}{{end}}' bonsy_caddy
172.19.0.4
28

That doesn’t prove that the container is working though. You’re ran PHP in CLI there, while the actual app is PHP-FPM which is another process. You should try to monitor PHP-FPM’s status. See Real-time PHP-FPM Status · GitHub for example.

I don’t see any evidence of a problem with Caddy itself here, it looks like a problem with PHP-FPM no longer accepting connections. You might need to tweak PHP-FPM’s settings to allow more connections, maybe. I dunno.

29

This topic was automatically closed after 30 days. New replies are no longer allowed.