TLS handshake error (ws+tls)

Help
1

1. Caddy version (caddy version):

v2.4.5 h1:P1mRs6V2cMcagSPn+NWpD+OEYUYLIf6ecOa48cFGeUg=

2. How I run Caddy:

a. System environment:

Debian 5.10.46-4 (2021-08-03) x86_64 GNU/Linux (Debian 10)

b. Command:

sudo service caddy start / restart / stop / status

3. The problem I’m having:

(ws + tls) reverse proxying works with Caddy v1, fails with Caddy v2

Work with Caddy v1

sub.esdomain.com {
  proxy /3367 localhost:37566 {
    websocket
    header_upstream -Origin
  }
}

Fail with Caddy v2, Caddyfile

sub.esdomain.com {
 tls {
   protocols tls1.2 tls1.3
   ciphers TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
   curves x25519
 }
 @staff_websocket {
  path /3367
  header Connection *Upgrade*
  header Upgrade websocket
 }
 reverse_proxy @staff_websocket localhost:37566
}

4. Error messages and/or full log output:

Connection setup failed with error: Connection timeout

5. What I already tried:

I tried in some apps, some work well, but some can’t.

6. Links to relevant resources:

My issue like this one.

2

If you’re only proxying to one backend, you don’t need the matcher.

Also, in Caddy v2, path matching is exact, so path /3367 will only match requests with the path exactly /3367 and not something like /3367/foo for example. For that, you need to use /3367*.

What are in Caddy’s logs? Since you’re running as a systemd service, you can check the logs with the command listed here:

1 Like
3

Thank you, I tried journalctl -u caddy --no-pager | less, but seems get nothing useful.

Sep 24 07:43:33 instance-1 systemd[1]: Starting Caddy...
Sep 24 07:43:33 instance-1 caddy[88245]: caddy.HomeDir=/var/lib/caddy
Sep 24 07:43:33 instance-1 caddy[88245]: caddy.AppDataDir=/var/lib/caddy/.local/share/caddy
Sep 24 07:43:34 instance-1 caddy[88245]: caddy.AppConfigDir=/var/lib/caddy/.config/caddy
Sep 24 07:43:34 instance-1 caddy[88245]: caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json
Sep 24 07:43:34 instance-1 caddy[88245]: caddy.Version=v2.4.5 h1:P1mRs6V2cMcagSPn+NWpD+OEYUYLIf6ecOa48cFGeUg=
Sep 24 07:43:34 instance-1 caddy[88245]: runtime.GOOS=linux
Sep 24 07:43:34 instance-1 caddy[88245]: runtime.GOARCH=amd64
Sep 24 07:43:34 instance-1 caddy[88245]: runtime.Compiler=gc
Sep 24 07:43:34 instance-1 caddy[88245]: runtime.NumCPU=2
Sep 24 07:43:34 instance-1 caddy[88245]: runtime.GOMAXPROCS=2
Sep 24 07:43:34 instance-1 caddy[88245]: runtime.Version=go1.17
Sep 24 07:43:34 instance-1 caddy[88245]: os.Getwd=/
Sep 24 07:43:34 instance-1 caddy[88245]: LANG=C.UTF-8
Sep 24 07:43:34 instance-1 caddy[88245]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
Sep 24 07:43:34 instance-1 caddy[88245]: NOTIFY_SOCKET=/run/systemd/notify
Sep 24 07:43:34 instance-1 caddy[88245]: HOME=/var/lib/caddy
Sep 24 07:43:34 instance-1 caddy[88245]: LOGNAME=caddy

I am using path /3367, I tried to update the path to /3367*, but it also doesn’t work.

4

That’s just the start of the logs. Hit Shift+G to jump to the bottom to see the latest logs.

1 Like
5

I did not know this and that’s amazing, I’ll have to remember that trick!

6

Alternatively, less +G to do it right away (I’ll update the docs for that soon)

Also Shift+F to “follow” (like tail -f)

1 Like
7

@francislavoie Thank you so much, but no matter what I use

Shift+G or journalctl -u caddy --no-pager | less +G, there’s no other logs. All logs I can see is following.


Sep 25 22:59:04 instance-1 caddy[15448]: HOME=/var/lib/caddy

Sep 25 22:59:04 instance-1 caddy[15448]: LOGNAME=caddy

Sep 25 22:59:04 instance-1 caddy[15448]: USER=caddy

Sep 25 22:59:04 instance-1 caddy[15448]: INVOCATION_ID=0c599e557dc848279112aecb56fe5e28

Sep 25 22:59:04 instance-1 caddy[15448]: JOURNAL_STREAM=8:165592

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0482202,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"warn","ts":1632581944.049663,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":2}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0507057,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0508385,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0511289,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0002febd0"}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.051359,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["sub.esdomain.com"]}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0515633,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/lib/caddy/.local/share/caddy"}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0523117,"logger":"tls","msg":"finished cleaning storage units"}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0527992,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}

Sep 25 22:59:04 instance-1 caddy[15448]: {"level":"info","ts":1632581944.0528612,"msg":"serving initial configuration"}

Sep 25 22:59:04 instance-1 systemd[1]: Started Caddy.

Sep 25 22:59:08 instance-1 caddy[15448]: {"level":"info","ts":1632581948.4735227,"msg":"shutting down apps, then terminating","signal":"SIGTERM"}

Sep 25 22:59:08 instance-1 caddy[15448]: {"level":"warn","ts":1632581948.4735641,"msg":"exiting; byeee!! <F0><9F><91><8B>","signal":"SIGTERM"}

Sep 25 22:59:08 instance-1 systemd[1]: Stopping Caddy...

Sep 25 22:59:08 instance-1 caddy[15448]: {"level":"info","ts":1632581948.477029,"logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc0002febd0"}

Sep 25 22:59:08 instance-1 caddy[15448]: {"level":"info","ts":1632581948.4782743,"logger":"admin","msg":"stopped previous server","address":"tcp/localhost:2019"}

Sep 25 22:59:08 instance-1 caddy[15448]: {"level":"info","ts":1632581948.478296,"msg":"shutdown complete","signal":"SIGTERM","exit_code":0}

Sep 25 22:59:08 instance-1 systemd[1]: caddy.service: Succeeded.

Sep 25 22:59:08 instance-1 systemd[1]: Stopped Caddy.

Sep 25 22:59:30 instance-1 systemd[1]: Starting Caddy...

Sep 25 22:59:30 instance-1 caddy[15482]: caddy.HomeDir=/var/lib/caddy

Sep 25 22:59:30 instance-1 caddy[15482]: caddy.AppDataDir=/var/lib/caddy/.local/share/caddy

Sep 25 22:59:30 instance-1 caddy[15482]: caddy.AppConfigDir=/var/lib/caddy/.config/caddy

Sep 25 22:59:30 instance-1 caddy[15482]: caddy.ConfigAutosavePath=/var/lib/caddy/.config/caddy/autosave.json

Sep 25 22:59:30 instance-1 caddy[15482]: caddy.Version=v2.4.5 h1:P1mRs6V2cMcagSPn+NWpD+OEYUYLIf6ecOa48cFGeUg=

Sep 25 22:59:30 instance-1 caddy[15482]: runtime.GOOS=linux

Sep 25 22:59:30 instance-1 caddy[15482]: runtime.GOARCH=amd64

Sep 25 22:59:30 instance-1 caddy[15482]: runtime.Compiler=gc

Sep 25 22:59:30 instance-1 caddy[15482]: runtime.NumCPU=2

Sep 25 22:59:30 instance-1 caddy[15482]: runtime.GOMAXPROCS=2

Sep 25 22:59:30 instance-1 caddy[15482]: runtime.Version=go1.17

Sep 25 22:59:30 instance-1 caddy[15482]: os.Getwd=/

Sep 25 22:59:30 instance-1 caddy[15482]: LANG=C.UTF-8

Sep 25 22:59:30 instance-1 caddy[15482]: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin

Sep 25 22:59:30 instance-1 caddy[15482]: NOTIFY_SOCKET=/run/systemd/notify

Sep 25 22:59:30 instance-1 caddy[15482]: HOME=/var/lib/caddy

Sep 25 22:59:30 instance-1 caddy[15482]: LOGNAME=caddy

Sep 25 22:59:30 instance-1 caddy[15482]: USER=caddy

Sep 25 22:59:30 instance-1 caddy[15482]: INVOCATION_ID=3c93ebfae1e147b5a50781a4f9f6967f

Sep 25 22:59:30 instance-1 caddy[15482]: JOURNAL_STREAM=8:164838

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.2402203,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":""}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"warn","ts":1632581970.2413936,"msg":"input is not formatted with 'caddy fmt'","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":2}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.2425866,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["localhost:2019","[::1]:2019","127.0.0.1:2019"]}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.2427633,"logger":"http","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv0"}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.243474,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc000341d50"}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.2536423,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/var/lib/caddy/.local/share/caddy"}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.2538764,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["sub.esdomain.com"]}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.2543538,"logger":"tls","msg":"finished cleaning storage units"}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.2550151,"msg":"autosaved config (load with --resume flag)","file":"/var/lib/caddy/.config/caddy/autosave.json"}

Sep 25 22:59:30 instance-1 caddy[15482]: {"level":"info","ts":1632581970.255211,"msg":"serving initial configuration"}

Sep 25 22:59:30 instance-1 systemd[1]: Started Caddy.
8

Hmm. You can enable the debug global option, which may reveal more information when making requests. Add this at the top of your Caddyfile:

{
	debug
}

Are you sure you need all this? Caddy’s defaults for tls are modern and secure. It’s rarely beneficial to modify them.

9

@francislavoie

Thank you so much for your patience and help!

I updated tls to tls emailaddress, and added { debug }, and I got this

Sep 26 12:31:14 instance-1 caddy[19698]: {"level":"debug","ts":1632630674.9273658,"logger":"tls.handshake","msg":"choosing certificate","identifier":"sub.esdomain.com","num_choices":1}
Sep 26 12:31:14 instance-1 caddy[19698]: {"level":"debug","ts":1632630674.927499,"logger":"tls.handshake","msg":"default certificate selection results","identifier":"sub.esdomain.com","subjects":["sub.esdomain.com"],"managed":true,"issuer_key":"acme-v02.api.letsencrypt.org-directory","hash":"08def89f7f0fc8d0388464b32c6ffb674b0dc87826c496329a3f543d1607c4d0"}
Sep 26 12:31:14 instance-1 caddy[19698]: {"level":"debug","ts":1632630674.9276206,"logger":"tls.handshake","msg":"matched certificate in cache","subjects":["sub.esdomain.com"],"managed":true,"expiration":1640213016,"hash":"08def89f7f0fc8d0388464b32c6ffb674b0dc87826c496329a3f543d1607c4d0"}

reverse_proxy does not seem to be working properly. The log for reverse_proxy works properly is the following

Sep 26 12:19:06 instance-1 caddy[18698]: {"level":"debug","ts":1632629946.1246195,"logger":"http.handlers.reverse_proxy","msg":"connection closed","upstream":"localhost:37566","request":{"remote_addr":"104.91.215.112:65035","proto":"HTTP/1.1","method":"GET","host":"sub.esdomain.com","uri":"/3367","headers":{"User-Agent":["Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US) AppleWebKit/533.20.25 (KHTML, like Gecko) Version/5.0.4 Safari/533.20.27"],"Upgrade":["websocket"],"X-Forwarded-For":["104.91.215.112"],"Sec-Websocket-Key":["6bANQYehipbnhDf25htzgg=="],"Sec-Websocket-Version":["13"],"X-Forwarded-Proto":["https"],"Connection":["Upgrade"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"sub.esdomain.com"}},"duration":31.097209599}

Thank you.

10

Hmm. That reverse_proxy log reads to me like your websocket server closed the TCP connection after 30 seconds. That might be okay, depending on whether the websocket server closed the connection intentionally (timed out after not hearing a ping message from the frontend for example, maybe)

At this point, I don’t feel I understand what’s going on. Please elaborate on the exact behaviour you’re seeing in your browser. What’s going on in your network tab in the browser dev tools?

1 Like
11

I used two proxy softwares, one was able to succeed and one failed. The one that failed returned the following error message

2021-09-26 15:47:11.700381 <WARNING> [SGConnectionSetupContext-7712] Connection setup failed with error: Connection timeout, sub.esdomain.com ->caddy.community:443

another log shows

Handshake failed: 200 OK
12

That’s really not much to go on. :confused: I’m not sure I have an answer for you.

13

Thank you all the same. I will use caddy1 instead. Thank you.

14

Are both of your applications served by single upstream? Because I see only one reverse_proxy in your config. If not, please share your full Caddyfile.

Also this is odd

Are you proxying to caddy.community?

2 Likes
15

The unfortunate part about doing that is it kind of dumps all the effort others have put in to helping you down the drain. We’d really appreciate more details so you can have it working with Caddy 2 and so everyone’s time doesn’t get wasted…

1 Like
16

Yes, I gave the full Caddyfile.

I use two applications that are served by single upstream, one is on iPhone called loon, it works well. The other is on macOS called surge, it gives the error that I have given. Where I currently live, I need proxy access to some websites. E.g. I use proxy to access to caddy.community.

If I use caddy1, both applications are working fine, until I switch to caddy2.

After doing some research, I now basically think it’s not a caddy2 error, but a problem with this app on the macOS I’m using.

@matt

17

BTW, I found someone meet the same issue like me.

18

I would suggest making sure the headers going to the upstream are right. Caddy 2 has different default header handling.

19

This is proxying only websocket connections.

Do you truly need only websockets? The websocket subdrective of the proxy directive in Caddy v1 signaled allowing proxying websockets while proxing non-websocket connections. The matcher in your v2 config will only proxy websockets. Caddy 2 upgrades to websockets automatically, so you most likely need only the path matcher. Can you verify this?

1 Like
20

Yep, thank you.