caddy icon indicating copy to clipboard operation
caddy copied to clipboard

Published 20 hours ago • verified publisher icon caddyserver

ERR_HTTP2_PROTOCOL_ERROR

Open anoo2niem opened this issue 1 year ago • 11 comments

Hi,

First of all, i would like to mention i'm a total noob in this field. I've observed an issue with the latest version (2.7.6), in my specific usecase. That being said, i'm not sure this is an issue with caddy itself.

My enviroment where i have this issue:

I have a vm on lubuntu where i run a pagermon server and client (https://github.com/pagermon/pagermon). This lets me acces captured pocsag messages from a web interface.

In the past i've succesfully used caddy to implement an easy way for a reverse proxy with a self-signed certificate. This way, the pagermon client is accesible from https://pagermon.home locally and from tailscale.

After updating to 2.7.6, i've got ERR_HTTP2_PROTOCOL_ERROR on every browser i wanted to acces https://pagermon.home. I've downgraded caddy to 2.7.4, and i can again acces https://pagermon.home.

This is my very simple caddyfile;

https://pagermon.home {
  tls internal
  reverse_proxy localhost:3000
}

Once again, i'm a total noob at this, and i guess this probably isn't an issue with caddy itself, but rather with something outdated on the webserver side.

Is there any way i can make this work on the latest version of caddy?

anoo2niem avatar Jan 29 '24 09:01 anoo2niem

We have a bug report template that you could fill out, but before doing that let's start with: what is the output of a request using curl -v? (with latest Caddy version)

mholt avatar Jan 29 '24 16:01 mholt

Hi mholt, apologies for not filling out the template.

This is the output of curl -v -k https://pagermon.home on caddy version 2.7.6;

*   Trying 192.168.1.171:443...
* Connected to pagermon.home (192.168.1.171) port 443 (#0)
* ALPN: offers h2,http/1.1
* 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_CHACHA20_POLY1305_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: [NONE]
*  start date: Jan 30 02:15:47 2024 GMT
*  expire date: Jan 30 14:15:47 2024 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* using HTTP/2
* h2h3 [:method: GET]
* h2h3 [:path: /]
* h2h3 [:scheme: https]
* h2h3 [:authority: pagermon.home]
* h2h3 [user-agent: curl/7.88.1]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x563bde68fc80)
> GET / HTTP/2
> Host: pagermon.home
> user-agent: curl/7.88.1
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)
* Connection #0 to host pagermon.home left intact

This is the output on caddy version 2.7.4 (Working);

*   Trying 192.168.1.171:443...
* Connected to pagermon.home (192.168.1.171) port 443 (#0)
* ALPN: offers h2,http/1.1
* 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_CHACHA20_POLY1305_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: [NONE]
*  start date: Jan 30 02:15:47 2024 GMT
*  expire date: Jan 30 14:15:47 2024 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* using HTTP/2
* h2h3 [:method: GET]
* h2h3 [:path: /]
* h2h3 [:scheme: https]
* h2h3 [:authority: pagermon.home]
* h2h3 [user-agent: curl/7.88.1]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x556999972c80)
> GET / HTTP/2
> Host: pagermon.home
> user-agent: curl/7.88.1
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
< HTTP/2 302 
< alt-svc: h3=":443"; ma=2592000
< content-type: text/plain; charset=utf-8
< date: Tue, 30 Jan 2024 09:00:47 GMT
< location: /auth/login
< server: Caddy
< set-cookie: connect.sid=s%3AqapzTtmY5Mvxl7hTPKo8cr7TWexyU89e.sdiG8geFuEBOT2yLAe2uCR0ZmsTAbZWHcceLAhcJDy8; Path=/; Expires=Tue, 06 Feb 2024 09:00:47 GMT; HttpOnly
< vary: Accept, Accept-Encoding
< x-powered-by: Express
< content-length: 33
< 
* HTTP/2 stream 1 was not closed cleanly: PROTOCOL_ERROR (err 1)
* Connection #0 to host pagermon.home left intact

Once again, i have basicly 0 knowledge on this matter, and i'm aware this possibly has nothing to do with caddy itself. The reason i posted this issue, was because it was working on all versions and stopped working on 2.7.6. To be honest, i'm not sure of the underlying reason, hence the post. If it hasn't anything to do with caddy itself, apologies, and u can close this issue.

If u would like some more information, please tell me which and how to obtain it.

Anyway, thanks for this wonderful tool which makes it 'easy' for a noob like me to issue a self-signed certificate.

anoo2niem avatar Jan 30 '24 09:01 anoo2niem

No worries about the issue template -- we don't actually present it to people unless it's needed, so while I'd normally do that in this case I figured all we need from it right now is to see the output of curl -v.

That is very interesting though. Does the error happen if you don't reverse proxy? (Maybe replace with a respond directive instead, or just a static file server.)

If you're really savvy, we could benefit from doing a git bisect to find the commit that broke this config. :thinking:

mholt avatar Jan 31 '24 04:01 mholt

Hi,

The error only occurs on my end with the combination of pagermon and the latest version (2.7.6) of caddy. When i reverse proxy from this vm for example to my pihole (with version 2.7.6), everything is working.

I just tested the combination of version 2.7.5 with pagermon, and can confirm this is working aswell. So it is only the combination of version 2.7.6 and pagermon which makes this error appearing.

I have some info logs from caddy when accessing https://pagermon.home with version 2.7.5 and 2.7.6, in the hopes they could bring some insight;

This is the info log while using caddy 2.7.5 (Working):

{"level":"info","ts":1706693217.020334,"logger":"http.log.access.log0","msg":"handled request","request":{"remote_ip":"192.168.1.17","remote_port":"62366","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/templates/auth/login.html","headers":{"Cookie":[],"Sec-Fetch-Mode":["cors"],"Accept":["application/json, text/plain, */*"],"Dnt":["1"],"If-Modified-Since":["Tue, 22 Aug 2023 16:04:56 GMT"],"If-None-Match":["W/\"54d-18a1dfdf2ef\""],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Accept-Language":["en-US,en;q=0.5"],"Alt-Used":["pagermon.home"],"Sec-Fetch-Site":["same-origin"],"Accept-Encoding":["gzip, deflate, br"],"Sec-Fetch-Dest":["empty"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"bytes_read":0,"user_id":"","duration":0.012292902,"size":0,"status":304,"resp_headers":{"Server":["Caddy"],"Accept-Ranges":["bytes"],"Cache-Control":["public, max-age=0"],"Last-Modified":["Tue, 22 Aug 2023 16:04:56 GMT"],"Etag":["W/\"54d-18a1dfdf2ef\""],"Date":["Wed, 31 Jan 2024 09:26:57 GMT"],"X-Powered-By":["Express"]}}

This is the info log while using caddy 2.7.6 (ERR_HTTP2_PROTOCOL_ERROR):

2024/01/31 09:31:25.695 INFO http.log.access.log0 handled request {"request": {"remote_ip": "192.168.1.17", "remote_port": "65153", "client_ip": "192.168.1.17", "proto": "HTTP/3.0", "method": "GET", "host": "pagermon.home", "uri": "/", "headers": {"Sec-Fetch-Dest": ["document"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"], "Accept-Language": ["en-US,en;q=0.5"], "Accept-Encoding": ["gzip, deflate, br"], "Cookie": [], "Priority": ["u=1"], "Upgrade-Insecure-Requests": ["1"], "Sec-Fetch-Mode": ["navigate"], "Sec-Fetch-Site": ["none"], "Dnt": ["1"], "Alt-Used": ["pagermon.home"], "Sec-Fetch-User": ["?1"], "User-Agent": ["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"]}, "tls": {"resumed": false, "version": 772, "cipher_suite": 4867, "proto": "h3", "server_name": "pagermon.home"}}, "bytes_read": 0, "user_id": "", "duration": 0, "size": 65, "status": 302, "resp_headers": {"X-Powered-By": ["Express"], "Location": ["/auth/login"], "Vary": ["Accept, Accept-Encoding"], "Set-Cookie": [], "Date": ["Wed, 31 Jan 2024 09:31:25 GMT"], "Content-Type": ["text/html; charset=utf-8"], "Content-Length": ["66"], "Server": ["Caddy"]}}

Some other interesting observation i made, on all previous versions of caddy, while accessing https://pagermon.home, i get automatically redirected to https://pagermon.home/auth/login and i'm presented with the login portal.

While on 2.7.6, accessing https://pagermon.home doesn't redirect me automatically. If i actually append /auth/login to the url manually, it seems to be working on 2.7.6.

curl -v -k https://pagermon.home on 2.7.6:

*   Trying 192.168.1.171:443...
* Connected to pagermon.home (192.168.1.171) port 443 (#0)
* ALPN: offers h2,http/1.1
* 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_CHACHA20_POLY1305_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: [NONE]
*  start date: Jan 31 02:40:28 2024 GMT
*  expire date: Jan 31 14:40:28 2024 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* using HTTP/2
* h2h3 [:method: GET]
* h2h3 [:path: /]
* h2h3 [:scheme: https]
* h2h3 [:authority: pagermon.home]
* h2h3 [user-agent: curl/7.88.1]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x5654d84a6c80)
> GET / HTTP/2
> Host: pagermon.home
> user-agent: curl/7.88.1
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)
* Connection #0 to host pagermon.home left intact
curl: (92) HTTP/2 stream 1 was not closed cleanly: INTERNAL_ERROR (err 2)

curl -v -k https://pagermon.home/auth/login on 2.7.6

*   Trying 192.168.1.171:443...
* Connected to pagermon.home (192.168.1.171) port 443 (#0)
* ALPN: offers h2,http/1.1
* 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_CHACHA20_POLY1305_SHA256
* ALPN: server accepted h2
* Server certificate:
*  subject: [NONE]
*  start date: Jan 31 02:40:28 2024 GMT
*  expire date: Jan 31 14:40:28 2024 GMT
*  issuer: CN=Caddy Local Authority - ECC Intermediate
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* using HTTP/2
* h2h3 [:method: GET]
* h2h3 [:path: /auth/login]
* h2h3 [:scheme: https]
* h2h3 [:authority: pagermon.home]
* h2h3 [user-agent: curl/7.88.1]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x55fc7f79fc80)
> GET /auth/login HTTP/2
> Host: pagermon.home
> user-agent: curl/7.88.1
> accept: */*
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
< HTTP/2 200 
< alt-svc: h3=":443"; ma=2592000
< content-type: text/html; charset=utf-8
< date: Wed, 31 Jan 2024 09:59:38 GMT
< etag: W/"1be3-u6nhq9gtG+0w9h1R3cR7s6zq0Ts"
< server: Caddy
< set-cookie: connect.sid=s%3Ab0AeJH9TAY7vtmjzYttVIvuc6hk9u51r.m5ByHwRt61XCtuq%2BsZTb4I5buWVirITW9fDJ8AMejjQ; Path=/; Expires=Wed, 07 Feb 2024 09:59:38 GMT; HttpOnly
< vary: Accept-Encoding
< x-powered-by: Express
< 
<!DOCTYPE html>
...

anoo2niem avatar Jan 31 '24 10:01 anoo2niem

Thanks for the additional info! Very weird.

I did notice that the request on 2.7.5 (working) is to the URI of /templates/auth/login.html, but the request for 2.7.6 (not working) is to /. Would that difference be relevant?

If you enable debug mode:

{
    debug
}

what is the full log output for the request that works and doesn't work, respectively?

Thanks!

mholt avatar Jan 31 '24 15:01 mholt

Log output of 2.7.6 (ERR_HTTP2_PROTOCOL_ERROR):

Jan 31 21:58:09 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"debug","ts":1706734689.9989781,"logger":"events","msg":"event","name":"tls_get_certificate","id":"46a30f98-bd00-437f-b8ff-18c83e88d812","origin":"tls","data":{"client_hello":{"CipherSuites":[4865,4867,4866],"ServerName":"pagermon.home","SupportedCurves":[29,23,24,25,256,257,258,259,260],"SupportedPoints":null,"SignatureSchemes":[1027,1283,1539,515,2052,2053,2054,1025,1281,1537,513],"SupportedProtos":["h3"],"SupportedVersions":[772],"RemoteAddr":{"IP":"192.168.1.17","Port":54339,"Zone":""},"LocalAddr":{"IP":"192.168.1.171","Port":443,"Zone":""}}}}
Jan 31 21:58:09 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"debug","ts":1706734689.9990916,"logger":"tls.handshake","msg":"choosing certificate","identifier":"pagermon.home","num_choices":1}
Jan 31 21:58:09 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"debug","ts":1706734689.9991052,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"pagermon.home","subjects":["pagermon.home"],"managed":true,"issuer_key":"local","hash":"30f89b2cfa041c19edb65f1facf746afb3e2127014b6bbd4d8fe8ef2a79cbeb3"}
Jan 31 21:58:09 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"debug","ts":1706734689.9991124,"logger":"tls.handshake","msg":"matched certificate in cache","remote_ip":"192.168.1.17","remote_port":"54339","subjects":["pagermon.home"],"managed":true,"expiration":1706770247,"hash":"30f89b2cfa041c19edb65f1facf746afb3e2127014b6bbd4d8fe8ef2a79cbeb3"}
Jan 31 21:58:10 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"debug","ts":1706734690.0016031,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:58:10 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"debug","ts":1706734690.0251415,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.023494054,"request":{"remote_ip":"192.168.1.17","remote_port":"54339","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/","headers":{"Accept-Encoding":["gzip, deflate, br"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"],"Priority":["u=1"],"Accept-Language":["en-US,en;q=0.5"],"Alt-Used":["pagermon.home"],"Sec-Fetch-Site":["none"],"X-Forwarded-For":["192.168.1.17"],"X-Forwarded-Host":["pagermon.home"],"Cookie":[],"X-Forwarded-Proto":["https"],"Upgrade-Insecure-Requests":["1"],"Sec-Fetch-User":["?1"],"Sec-Fetch-Mode":["navigate"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Dnt":["1"],"Sec-Fetch-Dest":["document"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"Date":["Wed, 31 Jan 2024 20:58:10 GMT"],"Vary":["Accept, Accept-Encoding"],"Content-Type":["text/html; charset=utf-8"],"Content-Length":["66"],"Set-Cookie":[],"Connection":["keep-alive"],"Keep-Alive":["timeout=5"],"X-Powered-By":["Express"],"Location":["/auth/login"]},"status":302}
Jan 31 21:58:10 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"error","ts":1706734690.0314465,"logger":"http.handlers.reverse_proxy","msg":"reading from backend","error":"unexpected EOF"}
Jan 31 21:58:10 anoo-standardpci440fxpiix1996 caddy[39848]: {"level":"error","ts":1706734690.031591,"logger":"http.handlers.reverse_proxy","msg":"aborting with incomplete response","upstream":"localhost:3000","duration":0.023494054,"request":{"remote_ip":"192.168.1.17","remote_port":"54339","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/","headers":{"Accept-Encoding":["gzip, deflate, br"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"],"Priority":["u=1"],"Accept-Language":["en-US,en;q=0.5"],"Alt-Used":["pagermon.home"],"Sec-Fetch-Site":["none"],"X-Forwarded-For":["192.168.1.17"],"X-Forwarded-Host":["pagermon.home"],"Cookie":[],"X-Forwarded-Proto":["https"],"Upgrade-Insecure-Requests":["1"],"Sec-Fetch-User":["?1"],"Sec-Fetch-Mode":["navigate"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Dnt":["1"],"Sec-Fetch-Dest":["document"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"error":"reading: unexpected EOF"}

Log output of 2.7.5 (Working):

Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.238849,"logger":"events","msg":"event","name":"tls_get_certificate","id":"5d71333f-c67a-47a1-b297-f9bf44887cdf","origin":"tls","data":{"client_hello":{"CipherSuites":[4865,4867,4866],"ServerName":"pagermon.home","SupportedCurves":[29,23,24,25,256,257,258,259,260],"SupportedPoints":null,"SignatureSchemes":[1027,1283,1539,515,2052,2053,2054,1025,1281,1537,513],"SupportedProtos":["h3"],"SupportedVersions":[772],"Conn":{}}}}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.2389646,"logger":"tls.handshake","msg":"choosing certificate","identifier":"pagermon.home","num_choices":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.2389781,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"pagermon.home","subjects":["pagermon.home"],"managed":true,"issuer_key":"local","hash":"30f89b2cfa041c19edb65f1facf746afb3e2127014b6bbd4d8fe8ef2a79cbeb3"}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.238985,"logger":"tls.handshake","msg":"matched certificate in cache","remote_ip":"192.168.1.17","remote_port":"60262","subjects":["pagermon.home"],"managed":true,"expiration":1706770247,"hash":"30f89b2cfa041c19edb65f1facf746afb3e2127014b6bbd4d8fe8ef2a79cbeb3"}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.2417629,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.2573142,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.015485625,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/","headers":{"Alt-Used":["pagermon.home"],"Priority":["u=1"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"],"X-Forwarded-For":["192.168.1.17"],"X-Forwarded-Host":["pagermon.home"],"Upgrade-Insecure-Requests":["1"],"Cookie":[],"Sec-Fetch-Site":["none"],"Dnt":["1"],"Accept-Encoding":["gzip, deflate, br"],"Sec-Fetch-Mode":["navigate"],"Accept-Language":["en-US,en;q=0.5"],"Sec-Fetch-User":["?1"],"Sec-Fetch-Dest":["document"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"Content-Length":["66"],"Date":["Wed, 31 Jan 2024 20:55:23 GMT"],"Vary":["Accept, Accept-Encoding"],"Content-Type":["text/html; charset=utf-8"],"Set-Cookie":[],"Connection":["keep-alive"],"Keep-Alive":["timeout=5"],"X-Powered-By":["Express"],"Location":["/auth/login"]},"status":302}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"error","ts":1706734523.2598913,"logger":"http.handlers.reverse_proxy","msg":"reading from backend","error":"unexpected EOF"}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"error","ts":1706734523.260004,"logger":"http.handlers.reverse_proxy","msg":"aborting with incomplete response","upstream":"localhost:3000","duration":0.015485625,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/","headers":{"Alt-Used":["pagermon.home"],"Priority":["u=1"],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"],"X-Forwarded-For":["192.168.1.17"],"X-Forwarded-Host":["pagermon.home"],"Upgrade-Insecure-Requests":["1"],"Cookie":[],"Sec-Fetch-Site":["none"],"Dnt":["1"],"Accept-Encoding":["gzip, deflate, br"],"Sec-Fetch-Mode":["navigate"],"Accept-Language":["en-US,en;q=0.5"],"Sec-Fetch-User":["?1"],"Sec-Fetch-Dest":["document"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"error":"reading: unexpected EOF"}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.263323,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.2851026,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.021710862,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/auth/login","headers":{"Accept-Language":["en-US,en;q=0.5"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Sec-Fetch-Dest":["document"],"Sec-Fetch-Site":["none"],"Alt-Used":["pagermon.home"],"Sec-Fetch-User":["?1"],"If-None-Match":["W/\"1be3-u6nhq9gtG+0w9h1R3cR7s6zq0Ts\""],"Accept":["text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8"],"Cookie":[],"X-Forwarded-Host":["pagermon.home"],"Accept-Encoding":["gzip, deflate, br"],"Priority":["u=1"],"Dnt":["1"],"X-Forwarded-For":["192.168.1.17"],"Upgrade-Insecure-Requests":["1"],"Sec-Fetch-Mode":["navigate"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"Keep-Alive":["timeout=5"],"X-Powered-By":["Express"],"Etag":["W/\"1be3-u6nhq9gtG+0w9h1R3cR7s6zq0Ts\""],"Date":["Wed, 31 Jan 2024 20:55:23 GMT"],"Connection":["keep-alive"]},"status":304}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3118587,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3126645,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3129315,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3197129,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3267817,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.014855711,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/javascripts/angular-sortable-view.min.js","headers":{"Alt-Used":["pagermon.home"],"If-None-Match":["W/\"27c1-18a1dfdf2ef\""],"Sec-Fetch-Mode":["no-cors"],"Accept-Language":["en-US,en;q=0.5"],"Accept":["*/*"],"X-Forwarded-Host":["pagermon.home"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Dnt":["1"],"Sec-Fetch-Dest":["script"],"X-Forwarded-For":["192.168.1.17"],"Cookie":[],"If-Modified-Since":["Tue, 22 Aug 2023 16:04:56 GMT"],"Priority":["u=2"],"Accept-Encoding":["gzip, deflate, br"],"Sec-Fetch-Site":["same-origin"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"Date":["Wed, 31 Jan 2024 20:55:23 GMT"],"Connection":["keep-alive"],"Keep-Alive":["timeout=5"],"X-Powered-By":["Express"],"Accept-Ranges":["bytes"],"Cache-Control":["public, max-age=0"],"Last-Modified":["Tue, 22 Aug 2023 16:04:56 GMT"],"Etag":["W/\"27c1-18a1dfdf2ef\""]},"status":304}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3391767,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.026180934,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/stylesheets/textAngular.css","headers":{"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Sec-Fetch-Mode":["no-cors"],"Accept-Language":["en-US,en;q=0.5"],"Sec-Fetch-Site":["same-origin"],"X-Forwarded-Proto":["https"],"Alt-Used":["pagermon.home"],"Accept-Encoding":["gzip, deflate, br"],"Sec-Fetch-Dest":["style"],"If-None-Match":["W/\"10c6-18a1dfdf2ef\""],"X-Forwarded-For":["192.168.1.17"],"Priority":["u=2"],"Accept":["text/css,*/*;q=0.1"],"Dnt":["1"],"If-Modified-Since":["Tue, 22 Aug 2023 16:04:56 GMT"],"X-Forwarded-Host":["pagermon.home"],"Cookie":[]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"Accept-Ranges":["bytes"],"Cache-Control":["public, max-age=0"],"Last-Modified":["Tue, 22 Aug 2023 16:04:56 GMT"],"Etag":["W/\"10c6-18a1dfdf2ef\""],"Date":["Wed, 31 Jan 2024 20:55:23 GMT"],"Connection":["keep-alive"],"Keep-Alive":["timeout=5"],"X-Powered-By":["Express"]},"status":304}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3458192,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.033097538,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/stylesheets/style.css","headers":{"Sec-Fetch-Dest":["style"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Cookie":[],"If-Modified-Since":["Sun, 27 Aug 2023 21:30:04 GMT"],"X-Forwarded-Proto":["https"],"Accept":["text/css,*/*;q=0.1"],"Alt-Used":["pagermon.home"],"Sec-Fetch-Mode":["no-cors"],"Priority":["u=2"],"Accept-Language":["en-US,en;q=0.5"],"X-Forwarded-Host":["pagermon.home"],"Accept-Encoding":["gzip, deflate, br"],"Sec-Fetch-Site":["same-origin"],"If-None-Match":["W/\"266b-18a38e769e0\""],"Dnt":["1"],"X-Forwarded-For":["192.168.1.17"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"Etag":["W/\"266b-18a38e769e0\""],"Date":["Wed, 31 Jan 2024 20:55:23 GMT"],"Connection":["keep-alive"],"Keep-Alive":["timeout=5"],"X-Powered-By":["Express"],"Accept-Ranges":["bytes"],"Cache-Control":["public, max-age=0"],"Last-Modified":["Sun, 27 Aug 2023 21:30:04 GMT"]},"status":304}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.3528812,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.033121838,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/javascripts/auth.main.js","headers":{"X-Forwarded-Proto":["https"],"If-Modified-Since":["Tue, 22 Aug 2023 16:04:56 GMT"],"Sec-Fetch-Site":["same-origin"],"Dnt":["1"],"X-Forwarded-Host":["pagermon.home"],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Accept-Encoding":["gzip, deflate, br"],"Cookie":[],"Accept-Language":["en-US,en;q=0.5"],"Alt-Used":["pagermon.home"],"X-Forwarded-For":["192.168.1.17"],"If-None-Match":["W/\"2f57-18a1dfdf2ef\""],"Sec-Fetch-Mode":["no-cors"],"Accept":["*/*"],"Sec-Fetch-Dest":["script"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"X-Powered-By":["Express"],"Accept-Ranges":["bytes"],"Cache-Control":["public, max-age=0"],"Last-Modified":["Tue, 22 Aug 2023 16:04:56 GMT"],"Etag":["W/\"2f57-18a1dfdf2ef\""],"Date":["Wed, 31 Jan 2024 20:55:23 GMT"],"Connection":["keep-alive"],"Keep-Alive":["timeout=5"]},"status":304}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.578456,"logger":"http.handlers.reverse_proxy","msg":"selected upstream","dial":"localhost:3000","total_upstreams":1}
Jan 31 21:55:23 anoo-standardpci440fxpiix1996 caddy[39601]: {"level":"debug","ts":1706734523.5881977,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"localhost:3000","duration":0.00965726,"request":{"remote_ip":"192.168.1.17","remote_port":"60262","client_ip":"192.168.1.17","proto":"HTTP/3.0","method":"GET","host":"pagermon.home","uri":"/templates/auth/login.html","headers":{"Accept":["application/json, text/plain, */*"],"Sec-Fetch-Mode":["cors"],"If-None-Match":["W/\"54d-18a1dfdf2ef\""],"User-Agent":["Mozilla/5.0 (Windows NT 10.0; rv:122.0) Gecko/20100101 Firefox/122.0"],"Cookie":[],"Alt-Used":["pagermon.home"],"Sec-Fetch-Dest":["empty"],"X-Forwarded-Host":["pagermon.home"],"Dnt":["1"],"Sec-Fetch-Site":["same-origin"],"Accept-Language":["en-US,en;q=0.5"],"X-Forwarded-Proto":["https"],"If-Modified-Since":["Tue, 22 Aug 2023 16:04:56 GMT"],"Accept-Encoding":["gzip, deflate, br"],"X-Forwarded-For":["192.168.1.17"]},"tls":{"resumed":false,"version":772,"cipher_suite":4867,"proto":"h3","server_name":"pagermon.home"}},"headers":{"Cache-Control":["public, max-age=0"],"Last-Modified":["Tue, 22 Aug 2023 16:04:56 GMT"],"Etag":["W/\"54d-18a1dfdf2ef\""],"Date":["Wed, 31 Jan 2024 20:55:23 GMT"],"Connection":["keep-alive"],"Keep-Alive":["timeout=5"],"X-Powered-By":["Express"],"Accept-Ranges":["bytes"]},"status":304}

I can see there is an error (probably with pagermon backend itself?) on both 2.7.5 & 2.7.6, while 2.7.5 proceeds and 2.7.6 aborts after the error log.

anoo2niem avatar Jan 31 '24 21:01 anoo2niem

Hi again,

In one of your previous posts, u mentioned that u could benefit from doing a git bisect. I didn't know what it was, and i've read me in on it. To be honest i still don't understand it, but i think i got the concept.

I didn't use git bisect, as i am under the impression that u have to manually review the code and then declare it either good or bad. Since i'm not a coder, i was not comfortable using it.

As i think i understanded the concept, i found a way to narrow down at which commit i started getting ERR_HTTP2_PROTOCOL_ERROR. The way i've accomplished this, might be stupid & unefficient :).

I've set up a test lxc and used xcaddy to build specific commits, and then started the server with ./caddy run --config Caddyfile. I've then checked in my browser wether i've got the ERR_HTTP2_PROTOCOL_ERROR or not.

The last working version/commit was:

v2.7.6-0.20231122140213-878d4918346f h1:nw8BwqTW0I5yfV34DGL8wHm4G0PXVzHLQDlJGqrrU9I= commit: 878d4918346f3c084d9972207c551919dc032078

The first version/commit where i start getting ERR_HTTP2_PROTOCOL_ERROR:

v2.7.6-0.20231123081818-4de2c1c65e48 h1:X4o7SUwpBTGO7phNZHe7SL/fcxeGhyfqsLfFAFI/jQc= commit: 4de2c1c65e48a68046817bdc074a25c1750fd38d

anoo2niem avatar Feb 01 '24 11:02 anoo2niem

/cc @WeidiDeng

francislavoie avatar Feb 01 '24 11:02 francislavoie

It seems there is a problem with express sending the wrong Content-Length header. When copying response, it hit EOF before the number of bytes are read, causing the response to fail.

In my experience, browser (in this case FireFox) doesn't actually check if the Content-Length matches what it received on HTTP 2/3, curl does check unless instructed not to.

We introduced this patch to fix 5951, and in general, allow clients to detect streaming error. Can you try this workaround for now?

WeidiDeng avatar Feb 01 '24 12:02 WeidiDeng

@WeidiDeng

After commenting out res.render(path.join(__dirname,'themes',theme, 'views', 'global', 'error'), { title: title }); in app.js, i can confirm it working and not receiving ERR_HTTP2_PROTOCOL_ERROR using commit 4de2c1c65e48a68046817bdc074a25c1750fd38d.

Many thanks!

anoo2niem avatar Feb 01 '24 12:02 anoo2niem

@WeidiDeng go 1.22 will be more strict regarding the Content-Length header:

The HTTP server and client now reject requests and responses containing an invalid empty Content-Length header. The previous behavior may be restored by setting GODEBUG field httplaxcontentlength=1.

bt90 avatar Feb 01 '24 17:02 bt90

I get this error with caddy 3.8.4 and a previously working config

symgryph avatar Jul 20 '24 19:07 symgryph

@symgryph if you have a problem, please open a topic on the forums. We can't help you without details. Post on https://caddy.community and fill out the help topic template.

francislavoie avatar Jul 20 '24 19:07 francislavoie