Caddy attempts to connect downstream server via HTTPS although not configured to do so

demonti · June 14, 2021, 8:51pm

1. Caddy version (`caddy version`):

2.4.1.

2. How I run Caddy:

I am using Caddy (besides others) as a reverse proxy to the SCM Manager, a web frontend for managing SVN, Mercurial and GIT repositories.

a. System environment:

Kubuntu 21.04/x64 (bare metal, no virtualisation)

b. Command:

I am trying to check out one of my repositories from my company’s workstation:

hg clone https://scm.xxxxxxx.de/repo/scmadmin/blog-contents

d. My complete Caddyfile or JSON config:

{ 
  "admin":
  { 
    "disabled": false,
    "config":
    {
      "persist": false
    }
  },
  "logging":
  {
    "sink":
    {
      "writer":
      {
        "output": "file",
        "filename": "/opt/caddy/logs/sink.log",
        "roll": true,
        "roll_size_mb": 100,
        "roll_local_time": true,
        "roll_keep": 0,
        "roll_keep_days": 0
      }
    },
    "logs":
    {
      "default":
      {
        "writer":
        {
          "output": "file",
          "filename": "/opt/caddy/logs/caddy.log",
          "roll": true,
          "roll_size_mb": 100,
          "roll_local_time": true,
          "roll_keep": 0,
          "roll_keep_days": 0
        },
        "level": "info",
        "encoder": { "format": "json" }
      }
    }
  },
  "storage":
  {
    "module": "file_system",
    "root": "/opt/caddy/store"
  },
  "apps":
  {
    "http":
    {
      "grace_period": "5s",
      "servers": 
      {
        "all":
        {
          "listen":
          [
            "[::]:80",
            "[::]:443"
          ],
          "routes":
          [
            {
              "group": "site selection",
              "match":
              [
                {
                  "host": [ "www.yyyyyyyy.de", "der.yyyyyyyy.de" ]
                }
              ],
              "handle":
              [
                {
                  "handler": "file_server",
                  "root": "/opt/caddy/sites/yyyyyyyy/cur",
                  "index_names": [ "index.html", "index.xml" ]
                }
              ]
            },
            {
              "group": "site selection",
              "match":
              [
                {
                  "host": [ "www.zzzzzzzz.de" ]
                }
              ],
              "handle":
              [
                {
                  "handler": "file_server",
                  "root": "/opt/caddy/sites/zzzzzzzz",
                  "index_names": [ "index.html" ]
                }
              ]
            },
            {
              "group": "site selection",
              "match":
              [
                {
                  "host": [ "scm.xxxxxxx.de" ]
                }
              ],
              "handle":
              [
                {
                  "handler": "reverse_proxy",
                  "transport":
                  {
                    "protocol": "http",
                    "compression": false,
                    "versions": ["1.1"]
                  },
                  "upstreams":
                  [ 
                    {
                      "dial": "[::1]:1080"
                    }
                  ]
                }
              ]
            },
            {
              "group": "site selection",
              "handle": 
              [
                {
                  "handler": "file_server",
                  "root": "/opt/caddy/sites/default",
                  "index_names": [ "index.html" ]
                }
              ]
            }
          ],
          "logs":
          {
            "default_logger_name": "default"
          }
        }
      }
    }
  }
}

3. The problem I’m having:

The problem is that despite the configuration, caddy attempts to connect the downstream server (SCM Manager) via HTTPS. But this happens only if I connect from my company’s workstation. From within my home network or from a direct connection from outside, everything works fine.

4. Error messages and/or full log output:

5. What I already tried:

Setup:

workstation in the company
-> proxy (195.253.xxx.xxx)
-> home router with NAT
-> caddy (192.168.1.9:443)
-> scm manager (::1:1080)

Software versions:
  - workstation: 
    OS: Kubuntu 21.04/x64, 
    Mercurial: 5.6.1
  - Proxy: Squid 4.10
  - Host of caddy/scm manager:
    OS: Kubuntu 21.04/x64
    Caddy: 2.4.1
    SCM Manager: 2.18.0

1st exchange
------------
workstation:
> hg clone https://scm.xxxxxxx.de/repo/scmadmin/blog-contents

communication between proxy and caddy:

tcpflow -c -D -i any port 443 (on 192.168.1.9)

195.253.xxx.xxx.36318-192.168.001.009.00443: 
0000: 1603 0102 0001 0001 fc03 0377 ddd1 579f eea5 e699 ac1f 2d50 67da 810a 19c5 f656  ...........w..W.......-Pg......V
0020: e1c5 db07 267f 50fe 002a 8e20 0c51 2219 9be2 db41 0312 41b3 ac34 f8e7 2f3c 0944  ....&.P..*. .Q"....A..A..4../<.D
...515 bytes in total

192.168.001.009.00443-195.253.xxx.xxx.36318:
0000: 1603 0300 7a02 0000 7603 034c eeb8 6114 a518 bb9a 6efa bc73 0cc4 cb89 e335 4e34  ....z...v..L..a.....n..s.....5N4
0020: 75e8 72d1 dda6 994e fcc4 4320 0c51 2219 9be2 db41 0312 41b3 ac34 f8e7 2f3c 0944  u.r....N..C .Q"....A..A..4../<.D
...quite a lot of data

communication between caddy and scm manager:

tcpflow -c -D -i any port 1080

::1.60586-::1.01080: 
0000: 4745 5420 2f72 6570 6f2f 7363 6d61 646d 696e 2f62 6c6f 672d 636f 6e74 656e 7473  GET /repo/scmadmin/blog-contents
0020: 3f63 6d64 3d63 6170 6162 696c 6974 6965 7320 4854 5450 2f31 2e31 0d0a 486f 7374  ?cmd=capabilities HTTP/1.1..Host
0040: 3a20 7363 6d2e xxxx xxxx xxxx xx2e 6465 0d0a 5573 6572 2d41 6765 6e74 3a20 6d65  : scm.xxxxxxx.de..User-Agent: me
0060: 7263 7572 6961 6c2f 7072 6f74 6f2d 312e 3020 284d 6572 6375 7269 616c 2035 2e36  rcurial/proto-1.0 (Mercurial 5.6
0080: 2e31 290d 0a41 6363 6570 743a 2061 7070 6c69 6361 7469 6f6e 2f6d 6572 6375 7269  .1)..Accept: application/mercuri
00a0: 616c 2d30 2e31 0d0a 4163 6365 7074 2d45 6e63 6f64 696e 673a 2069 6465 6e74 6974  al-0.1..Accept-Encoding: identit
00c0: 790d 0a58 2d46 6f72 7761 7264 6564 2d46 6f72 3a20 3139 352e 3235 332e 322e 3135  y..X-Forwarded-For: 195.253.2.15
00e0: 300d 0a58 2d46 6f72 7761 7264 6564 2d50 726f 746f 3a20 6874 7470 730d 0a0d 0a    0..X-Forwarded-Proto: https....

::1.01080-::1.60586: 
0000: 4854 5450 2f31 2e31 2034 3031 2055 6e61 7574 686f 7269 7a65 640d 0a57 5757 2d41  HTTP/1.1 401 Unauthorized..WWW-A
0020: 7574 6865 6e74 6963 6174 653a 2042 6173 6963 2072 6561 6c6d 3d22 534f 4e49 4120  uthenticate: Basic realm="SONIA 
0040: 3a3a 2053 434d 204d 616e 6167 6572 220d 0a43 6163 6865 2d43 6f6e 7472 6f6c 3a20  :: SCM Manager"..Cache-Control: 
0060: 6d75 7374 2d72 6576 616c 6964 6174 652c 6e6f 2d63 6163 6865 2c6e 6f2d 7374 6f72  must-revalidate,no-cache,no-stor
0080: 650d 0a43 6f6e 7465 6e74 2d4c 656e 6774 683a 2030 0d0a 5365 7276 6572 3a20 4a65  e..Content-Length: 0..Server: Je
00a0: 7474 7928 392e 342e 3335 2e76 3230 3230 3131 3230 290d 0a0d 0a                   tty(9.4.35.v20201120)....

caddy log entry:

{"level":"error","ts":1623700858.5017047,"logger":"http.log.access.default","msg":"handled request","request":{"remote_addr":"195.253.xxx.xxx:36318","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"Accept":["application/mercurial-0.1"],"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"],"Accept-Encoding":["identity"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"common_log":"195.253.xxx.xxx - - [14/Jun/2021:22:00:58 +0200] \"GET /repo/scmadmin/blog-contents?cmd=capabilities HTTP/1.1\" 401 0","duration":0.002265057,"size":0,"status":401,"resp_headers":{"Server":["Caddy","Jetty(9.4.35.v20201120)"],"Www-Authenticate":["Basic realm=\"SONIA :: SCM Manager\""],"Cache-Control":["must-revalidate,no-cache,no-store"],"Content-Length":["0"]}}


2nd exchange
------------

Mercurial dialog:

http authorization required for https://scm.xxxxxxx.de/repo/scmadmin/blog-contents
realm: SONIA :: SCM Manager
user: klaus
password: 
abort: HTTP Error 502: Bad Gateway

communication between proxy and caddy:

195.253.xxx.xxx.36324-192.168.001.009.00443: 
0000: 1603 0102 0001 0001 fc03 032d d68d 57bf 6d69 c900 fe1f dd72 714e bfc5 2d63 e5b8  ...........-..W.mi.....rqN..-c..
0020: abc2 c69b a18d 362e d204 3d20 25b3 34cf e1cf c163 e34e 65ea e0a8 5319 a028 77f7  ......6...= %.4....c.Ne...S..(w.
0040: 48c7 3411 19e3 6b7f 2568 4617 003e 1302 1303 1301 c02c c030 009f cca9 cca8 ccaa  H.4...k.%hF..>.......,.0........
0060: c02b c02f 009e c024 c028 006b c023 c027 0067 c00a c014 0039 c009 c013 0033 009d  .+./...$.(.k.#.'.g.....9.....3..
0080: 009c 003d 003c 0035 002f 00ff 0100 0175 0000 0013 0011 0000 0e73 636d 2exx xxxx  ...=.<.5./.....u.........scm.xxx
00a0: xxxx xxxx 2e64 6500 0b00 0403 0001 0200 0a00 0c00 0a00 1d00 1700 1e00 1900 1800  xxxx.de.........................
00c0: 2300 0000 1600 0000 1700 0000 0d00 2a00 2804 0305 0306 0308 0708 0808 0908 0a08  #.............*.(...............
00e0: 0b08 0408 0508 0604 0105 0106 0103 0303 0103 0204 0205 0206 0200 2b00 0504 0304  ..........................+.....
0100: 0303 002d 0002 0101 0033 0026 0024 001d 0020 b6e1 e1d5 97e3 fb10 7a69 a2b7 8d2b  ...-.....3.&.$... ........zi...+
0120: 17d4 6592 64c8 2e74 34dc 7ca5 d44b 1b14 7400 0015 00cf 0000 0000 0000 0000 0000  ..e.d..t4.|..K..t...............
0140: 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000  ................................
0160: 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000  ................................
0180: 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000  ................................
01a0: 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000  ................................
01c0: 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000  ................................
01e0: 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000  ................................
0200: 0000 0000 00                                                                     .....

192.168.001.009.00443-195.253.xxx.xxx.36324: 
0000: 1603 0300 7a02 0000 7603 0353 97d2 902e b45f 8ce8 14e1 46d5 90f9 a981 8ef1 dcd8  ....z...v..S....._....F.........
0020: 7e59 1e5f e55c e815 fba0 dc20 25b3 34cf e1cf c163 e34e 65ea e0a8 5319 a028 77f7  ~Y._.\..... %.4....c.Ne...S..(w.
0040: 48c7 3411 19e3 6b7f 2568 4617 1301 0000 2e00 2b00 0203 0400 3300 2400 1d00 204b  H.4...k.%hF.......+.....3.$... K
0060: 3060 9170 e2d5 2cc0 7c43 6297 8a86 3cbc a653 e584 e326 beb7 c978 1ca6 7efd 7614  0`.p..,.|Cb...<..S...&...x..~.v.
0080: 0303 0001 0117 0303 0017 7778 42a6 45c8 f5fe 304e 2273 46f4 0d52 c40c a912 27be  ..........wxB.E...0N"sF..R....'.
00a0: 6c17 0303 0eff fd78 8d0d 4ba1 0547 c7e1 796a 2698 293f ac40 abe2 4a82 5178 e701  l......x..K..G..yj&.)?.@..J.Qx..
00c0: 5079 3a1d 0bfc a045 7ea2 405c c221 e3fe e883 16c0 f55b d49f 3906 d334 db83 d858  Py:....E~.@\.!.......[..9..4...X
00e0: a409 6669 522a 834a f34c 355e c800 767d e1d9 fe60 d5b0 87f2 5cb3 69e3 4797 8c06  ..fiR*.J.L5^..v}...`....\.i.G...

communication between caddy and scm manager:

::1.60588-::1.01080: 
0000: 1603 0100 ee01 0000 ea03 0377 8425 bb66 6353 5028 6667 f371 67af ea30 383f a89d  ...........w.%.fcSP(fg.qg..08?..
0020: 644b de8b 3d9e 0418 33b7 e620 e013 1332 d36a 353c 703b 75cb 121a c44a 05c7 fba6  dK..=...3.. ...2.j5<p;u....J....
0040: a047 3c7e ce12 b218 f413 a4ed 0026 c02f c030 c02b c02c cca8 cca9 c013 c009 c014  .G<~.........&./.0.+.,..........
0060: c00a 009c 009d 002f 0035 c012 000a 1301 1303 1302 0100 007b 0005 0005 0100 0000  ......./.5.............{........
0080: 0000 0a00 0a00 0800 1d00 1700 1800 1900 0b00 0201 0000 0d00 1a00 1808 0404 0308  ................................
00a0: 0708 0508 0604 0105 0106 0105 0306 0302 0102 03ff 0100 0100 0012 0000 002b 0009  .............................+..
00c0: 0803 0403 0303 0203 0100 3300 2600 2400 1d00 20ab 0752 ae96 d4b9 7cec eb1c 947b  ..........3.&.$... ..R....|....{
00e0: 5d0b c1a5 f369 1c3d 775d 1a75 1a7c 0a9f e86c 6b                                  ]....i.=w].u.|...lk

::1.01080-::1.60588: 
0000: 4854 5450 2f31 2e31 2034 3030 2049 6c6c 6567 616c 2063 6861 7261 6374 6572 2043  HTTP/1.1 400 Illegal character C
0020: 4e54 4c3d 3078 3136 0d0a 436f 6e74 656e 742d 5479 7065 3a20 7465 7874 2f68 746d  NTL=0x16..Content-Type: text/htm
0040: 6c3b 6368 6172 7365 743d 6973 6f2d 3838 3539 2d31 0d0a 436f 6e74 656e 742d 4c65  l;charset=iso-8859-1..Content-Le
0060: 6e67 7468 3a20 3730 0d0a 436f 6e6e 6563 7469 6f6e 3a20 636c 6f73 650d 0a53 6572  ngth: 70..Connection: close..Ser
0080: 7665 723a 204a 6574 7479 2839 2e34 2e33 352e 7632 3032 3031 3132 3029 0d0a 0d0a  ver: Jetty(9.4.35.v20201120)....
00a0: 3c68 313e 4261 6420 4d65 7373 6167 6520 3430 303c 2f68 313e 3c70 7265 3e72 6561  <h1>Bad Message 400</h1><pre>rea
00c0: 736f 6e3a 2049 6c6c 6567 616c 2063 6861 7261 6374 6572 2043 4e54 4c3d 3078 3136  son: Illegal character CNTL=0x16
00e0: 3c2f 7072 653e                                                                   </pre>

caddy log entries:

{"level":"error","ts":1623700861.3709624,"logger":"http.log.error.default","msg":"tls: first record does not look like a TLS handshake","request":{"remote_addr":"195.253.xxx.xxx:36324","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"Authorization":["Basic xxxxxxxxxxxxxxx"],"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"],"Accept-Encoding":["identity"],"Accept":["application/mercurial-0.1"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"duration":0.001667712,"status":502,"err_id":"cf1w2ce0e","err_trace":"reverseproxy.statusError (reverseproxy.go:861)"}
{"level":"error","ts":1623700861.3710773,"logger":"http.log.access.default","msg":"handled request","request":{"remote_addr":"195.253.xxx.xxx:36324","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"Accept-Encoding":["identity"],"Accept":["application/mercurial-0.1"],"Authorization":["Basic xxxxxxxxxxxxxxx"],"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"common_log":"195.253.xxx.xxx - - [14/Jun/2021:22:01:01 +0200] \"GET https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities HTTP/1.1\" 502 0","duration":0.001667712,"size":0,"status":502,"resp_headers":{"Server":["Caddy"]}}

6. Links to relevant resources:

francislavoie · June 14, 2021, 9:02pm

Those logs aren’t the reverse_proxy requests that Caddy makes, those are the access logs from Caddy itself. I see no evidence that Caddy is making TLS requests to your upstream.

This means some client made an HTTP request to Caddy on its configured HTTPS port.

You should set the log level to debug for the default logger, and watch those for information from the http.handlers.reverse_proxy module to see what it’s doing.

demonti · June 14, 2021, 9:17pm

This is what I thought, too. This is the reason why I logged the traffic on port 443. And there is definitely no unencrypted traffic on that port. And even if so, it does not explain why caddy tries to connect via HTTPS on port 1080. In an earlier version of the configuration, I did not have the “versions: [“1.1”]” configuration in it. I could see something in the traffic to port 1080 that looked like the ALPN negotiation – it included “h2” and “http” as readable text. But I’ll try to turn on debug level and run it again.

demonti · June 14, 2021, 9:27pm

So here is the log output with debug level (I added an empty line between the two requests)

{"level":"debug","ts":1623705671.167524,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"[::1]:1080","request":{"remote_addr":"195.253.xxx.xxx:44302","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"Accept":["application/mercurial-0.1"],"X-Forwarded-For":["195.253.xxx.xxx"],"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"],"X-Forwarded-Proto":["https"],"Accept-Encoding":["identity"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"headers":{"Www-Authenticate":["Basic realm=\"SONIA :: SCM Manager\""],"Cache-Control":["must-revalidate,no-cache,no-store"],"Content-Length":["0"],"Server":["Jetty(9.4.35.v20201120)"]},"status":401}
{"level":"error","ts":1623705671.1678524,"logger":"http.log.access.default","msg":"handled request","request":{"remote_addr":"195.253.xxx.xxx:44302","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"Accept-Encoding":["identity"],"Accept":["application/mercurial-0.1"],"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"common_log":"195.253.xxx.xxx - - [14/Jun/2021:23:21:11 +0200] \"GET /repo/scmadmin/blog-contents?cmd=capabilities HTTP/1.1\" 401 0","duration":0.003374398,"size":0,"status":401,"resp_headers":{"Server":["Caddy","Jetty(9.4.35.v20201120)"],"Www-Authenticate":["Basic realm=\"SONIA :: SCM Manager\""],"Cache-Control":["must-revalidate,no-cache,no-store"],"Content-Length":["0"]}}

{"level":"debug","ts":1623705677.3241606,"logger":"http.handlers.reverse_proxy","msg":"upstream roundtrip","upstream":"[::1]:1080","request":{"remote_addr":"195.253.xxx.xxx:44312","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"Accept-Encoding":["identity"],"Accept":["application/mercurial-0.1"],"Authorization":["Basic xxxxxxxxxxxxxxxx"],"X-Forwarded-For":["195.253.xxx.xxx"],"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"],"X-Forwarded-Proto":["https"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"duration":0.001549706,"error":"tls: first record does not look like a TLS handshake"}
{"level":"error","ts":1623705677.32444,"logger":"http.log.error.default","msg":"tls: first record does not look like a TLS handshake","request":{"remote_addr":"195.253.xxx.xxx:44312","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"Authorization":["Basic xxxxxxxxxxxxxxxx"],"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"],"Accept-Encoding":["identity"],"Accept":["application/mercurial-0.1"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"duration":0.001866127,"status":502,"err_id":"91wxm9dse","err_trace":"reverseproxy.statusError (reverseproxy.go:861)"}
{"level":"error","ts":1623705677.324536,"logger":"http.log.access.default","msg":"handled request","request":{"remote_addr":"195.253.xxx.xxx:44312","proto":"HTTP/1.1","method":"GET","host":"scm.xxxxxxx.de","uri":"https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities","headers":{"User-Agent":["mercurial/proto-1.0 (Mercurial 5.6.1)"],"Accept-Encoding":["identity"],"Accept":["application/mercurial-0.1"],"Authorization":["Basic xxxxxxxxxxxxxxxx"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"","proto_mutual":true,"server_name":"scm.xxxxxxx.de"}},"common_log":"195.253.xxx.xxx - - [14/Jun/2021:23:21:17 +0200] \"GET https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities HTTP/1.1\" 502 0","duration":0.001866127,"size":0,"status":502,"resp_headers":{"Server":["Caddy"]}}

demonti · July 3, 2021, 2:00pm

So no more advice, no more ideas what I can do? I’ve updated to the newest version in the meantime, but no improvement. It seems that I have to invoke plan B, switching to nginx. This seems a PITA in respect to LetsEncrypt, which is awesomely solved in caddy, I have to admit.

francislavoie · July 3, 2021, 2:17pm

Can you try with a Caddyfile config? (It’s easier to write a valid Caddyfile config than JSON, easier to shoot yourself in the foot with JSON).

What’s the simplest possible config you can use to replicate this issue?

What if you remove the compression and version options? They shouldn’t be necessary.

You shouldn’t need to "listen" on port 80, Caddy will automatically wire up HTTP->HTTPS redirects via Automatic HTTPS. Adding port 80 to the listener will override that. No need.

demonti · July 5, 2021, 7:40pm

Hi francislavoie,

while I have never written a single line of code in GO, I took a view into the code anyway and found something interesting. If I see correctly, the two log entries “http.handlers.reverse_proxy” origin from line 570 of the file modules/caddyhttp/reverseproxy/reverseproxy.go. Did you notice the difference between the two entries?

The “uri” request parameter in the first case is

 "uri":"/repo/scmadmin/blog-contents?cmd=capabilities"

while the second is

 "uri":"https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities"

i.e. the URI in the first, working request does not contain the URI protocol or the authority part, only path and query, while the URI of the second request does contain both the protocol and authority.

Now the interesting part: In the function “directRequest” (line 774), “req” parameter is modified by replacing the host part of the “URL” member. However, the protocol is left unchanged. Unfortunately, not the “URL” parameter is logged, but the “RequestURI” parameter. But if one assumes that they are identical, this could explain the behaviour I experienced. The protocol, “https” in the second case, would be preserved and the called Golang library would perform an HTTPS instead of the desired HTTP request.

In my humble opinion, the directRequest function should replace the protocol as well, at least if the upstream only provides exclusively HTTP or HTTPS, as this is the case in my configuration.

francislavoie · July 5, 2021, 8:39pm

The scheme gets set in the httptransport.go code:

reverseProxy calls h.Transport.RoundTrip(req) which calls h.SetScheme(req) which does some scheme adjustment.

github.com

caddyserver/caddy/blob/master/modules/caddyhttp/reverseproxy/httptransport.go#L252

    
      
          	if sliceContains(h.Versions, "2") {
          		if err := http2.ConfigureTransport(rt); err != nil {
          			return nil, err
          		}
          	}
          
          
	return rt, nil
          }
          
          
// RoundTrip implements http.RoundTripper.
          func (h *HTTPTransport) RoundTrip(req *http.Request) (*http.Response, error) {
          	h.SetScheme(req)
          
          
	// if H2C ("HTTP/2 over cleartext") is enabled and the upstream request is
          	// HTTP/2 without TLS, use the alternate H2C-capable transport instead
          	if req.ProtoMajor == 2 && req.URL.Scheme == "http" && h.h2cTransport != nil {
          		return h.h2cTransport.RoundTrip(req)
          	}
          
          
	return h.Transport.RoundTrip(req)
          }

If there’s a fix to be made, it would probably be here.

But I don’t quite understand why you’re the first person to run into this problem in over a year of Caddy v2 being released. I’m trying to understand what specifically is different about your setup to cause this issue.

francislavoie · July 5, 2021, 8:45pm

Can you try with a Caddyfile like this? Does this yield the same issue?

{
	admin off
	storage file_system {
		root /opt/caddy/store
	}
	log {
		output file /opt/caddy/logs/caddy.log
		format json
		level debug
	}
}

www.yyyyyyyy.de, der.yyyyyyyy.de {
	root * /opt/caddy/sites/yyyyyyyy/cur
	file_server {
		index index.html index.xml
	}
}

www.zzzzzzzz.de {
	root * /opt/caddy/sites/zzzzzzzz
	file_server
}

scm.xxxxxxx.de {
	reverse_proxy [::1]:1080
}

http:// {
	root * /opt/caddy/sites/default
	file_server
}

francislavoie · July 5, 2021, 9:08pm

Since I don’t know how to replicate this issue, I suggest you try to debug this yourself by making a custom build.

Luckily, it’s very easy to compile Caddy. Install Go (basically involves downloading a .tar and unzipping it, adding its bin dir to your user’s PATH), then clone the Caddy repo and build it:

$ git clone "https://github.com/caddyserver/caddy.git"
$ cd caddy/cmd/caddy/
$ go build

This’ll give you a caddy binary in your current directory after a few seconds that you can use.

To make any code changes, I recommend using VSCode, it has great Go integration with an official extension (it’ll prompt you to install gopls, do so).

What you can do is log at each step of the way what’s going on with the values in the request. You can basically spam these lines all over, rebuild, and test it:

fmt.Printf("Thing: %+v\n", thing)

This’ll print out thing to stdout with whatever Stringer implementation the type has.

demonti · July 6, 2021, 8:25am

Hi,

yes, maybe the SetScheme is the problematic function. If the req.URL.Schema is set as it is probably in the second connection attempt, then the scheme is left unchanged. This raises two questions:

why does the second request contains a scheme at all? The answer seems to be outside of the reverse proxy code.
Isn’t there a logic error? Why does the protocol of the original request actually matter for connecting the upstream? In many cases where a reverse proxy is used it is also used as an SSL/TLS termination and internal communication further takes place unencrypted. I expected that the protocol of the upstream connection is solely based on the configuration and not at all on the protocol of the incoming request. This puzzles me what the intention of this code is.

I can try to use your provided configuration and build caddy on my own and add some debug output, but, as I wrote, I don’t know Golang, so my mileage will be limited.

By the way: I just looked at the last log line I provided earlier to you: It seems that the request was sent in the “proxy style”:

"common_log":"195.253.xxx.xxx - - [14/Jun/2021:23:21:17 +0200] \"GET https://scm.xxxxxxx.de/repo/scmadmin/blog-contents?cmd=capabilities HTTP/1.1\" 
                                                                     ^^^^^^^^^^^^^^^^^^^^^^

i.e. the first line of the HTTP request contains the full URL instead of only the path part. This may answer the first question and then this may be also a fault of the Mercurial code (or the library they use).

francislavoie · July 6, 2021, 12:26pm

All I can do is theorize at this point, so I think you’ll need to dig a bit deeper. Like I said, it shouldn’t be difficult at all. If you run into a snag, let me know. Just need to toss in some debug prints a bit everywhere to see what’s happening.

demonti · July 6, 2021, 1:35pm

Well, I can try to verify my assumption that the “reverseProxy” function in reverseproxy.go receives a “req” parameter where the value of “URL” component is equals to the logged “RequestURI” parameter. Everything else is a question whether and how the Caddy team want to handle the potentially bad request (containing the full URL in the GET line, which is to my limited knowledge of HTTP only allowed for accessing proxy servers) and whether it really makes sense to choose the upstream protocol from the original request protocol (to me a “no” to the latter, but I am not aware whether in a different use scenario of Caddy this maybe would so).

francislavoie · July 6, 2021, 3:54pm

Yes, we can implement a fix, but the problem is I don’t fully understand what’s going on with the values, so I need your help to inspect exactly what’s happening down the pipe in your case that’s causing it to go wrong.

Once we have a better understanding, we can consider how to fix it.

demonti · July 6, 2021, 8:13pm

Now at home, I have found an easy way to reproduce the problem on my system. Please note that I always use port 80 and that the requests use the proxy syntax (“absolute form” in HTTP speak):

netcat localhost 80 <<EOF
GET http://scm.xxxxxxx.de HTTP/1.1
Host: scm.xxxxxxx.de

EOF
HTTP/1.1 200 OK
Content-Length: 1915
Content-Type: text/html;charset=utf-8
Date: Tue, 06 Jul 2021 19:54:54 GMT
Server: Caddy
Server: Jetty(9.4.35.v20201120)

<html page of the upstream server>

Now the same request with https instead of http in the request line:

netcat localhost 80 <<EOF
GET https://scm.xxxxxxx.de HTTP/1.1
Host: scm.xxxxxxx.de

EOF
HTTP/1.1 502 Bad Gateway
Server: Caddy
Date: Tue, 06 Jul 2021 19:55:15 GMT
Content-Length: 0

(I tried the same on port 443 with openssl and received similar behavior)

So it is the proof that the protocol of the URL behind the GET is used to select the protocol for connecting the upstream server. Contrary to my earlier statements, all HTTP servers are required to accept the “absolute form”, see section 5.3.2 of RFC 7230. So I believe this is a misbehavior of Caddy.

francislavoie · July 6, 2021, 8:30pm

Fascinating.

So http package - net/http - Go Packages specifies for the URL field:

// For server requests, the URL is parsed from the URI
// supplied on the Request-Line as stored in RequestURI.  For
// most requests, fields other than Path and RawQuery will be
// empty. (See RFC 7230, Section 5.3)

So the request having scheme/host is kinda unexpected from the client’s part. I’d say it’s a bug on both ends. Yes, Caddy should probably sanitize the URL to remove the scheme and host, but the Mercurial client probably shouldn’t use the scheme and host in the request line either, if that is what you’re reporting.

demonti · July 6, 2021, 8:36pm

Yes, I agree that this is definitely an uncommon request that is being generated by the Mercurial client, but as far as I understand the HTTP protocol (see earlier reference), it is still a valid request. I guess that you don’t need any further debugging from my side, otherwise let me know.

francislavoie · July 6, 2021, 8:55pm

I’ve opened a PR for this with a proposed fix, but I haven’t tested it yet.

github.com/caddyserver/caddy

reverseproxy: Sanitize scheme and host on incoming requests

caddyserver:master ← caddyserver:sanitize-request

opened 08:54PM - 06 Jul 21 UTC

francislavoie

+14 -0

See https://caddy.community/t/caddy-attempts-to-connect-downstream-server-via-ht…tps-although-not-configured-to-do-so/12765 for context, and later another report of the same problem in https://caddy.community/t/reverse-proxying-trying-to-make-a-tls-connection-to-an-http-only-backend/13954 Basically some wacky HTTP clients may sometimes make HTTP requests with request-line like this: ``` GET https://example.com/some/path Host: example.com ``` _Most_ well behaved clients make requests like this: ``` GET /some/path Host: example.com ``` Technically, both are valid as per HTTP RFCs, but the former ends up breaking some assumptions that the code makes, like that the scheme is empty before being passed onto the `reverse_proxy` module. The effect was that these requests would tell `http.Client` to use a different scheme than configured. For example, configured `reverse_proxy` to proxy over HTTP, but the scheme in the original request's request-line had `https://` so it would try to proxy over HTTPS :scream: The docs for [`Request.URL`](https://golang.org/pkg/net/http/#Request.URL) do say: // For server requests, the URL is parsed from the URI // supplied on the Request-Line as stored in RequestURI. For // most requests, fields other than Path and RawQuery will be // empty. (See RFC 7230, Section 5.3) So it's definitely pretty unexpected to receive the scheme and host in the URL. This change should just wipe out the scheme and host in the URL, which are otherwise covered by `Request.Host` and `Request.TLS` (and that's how all of the code in Caddy access the host and whether the request was secured). ~~I realize this is a risky change because it affects _every request_ handled by Caddy. We should definitely tread lightly here. But I think this is the most logical and simplest way to solve this.~~ I've adjusted the implementation to only do the sanitization in the `reverseproxy` package, and to restore it after `reverseproxy` is done.

If you’d like to test it, you can grab a build from the CI job (once the tests complete in a few minutes):

https://github.com/caddyserver/caddy/actions/runs/1005799137

demonti · July 6, 2021, 9:13pm

Thumbs up! Just logged in into my office system and successfully cloned a repository. Thanks a lot.

system · July 14, 2021, 8:51pm

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