Non blocking matchers & matching timeout breaking l4 as a listener wrapper

[WeidiDeng]

Pull 192 modified routes handling. It works for normal configuration where all possible matchers are predefined.

There is one breaking change in that when compiling a routesList, the next handler is only called when a match is made. As a listener wrapper this means non-matched connections will not be forwarded to the http server. Originally next handler is called if the connection is not matched by any of the matchers in the routes.

Here is an example config that worked in the past, but is now broken (The tls proxy parts work, but local http server doesn't):

{
  "logging": {
    "logs": {
      "default": {
        "level": "DEBUG"
      }
    }
  },
  "apps": {
    "http": {
      "servers": {
        "srv0": {
          "listen": [
            ":80"
          ],
          "listener_wrappers": [
            {
              "wrapper": "layer4",
              "routes": [
                {
                  "match": [
                    {
                      "tls": {
                        "sni": [
                          "example.com",
                        ]
                      }
                    }
                  ],
                  "handle": [
                    {
                      "handler": "proxy",
                      "upstreams": [
                        {
                          "dial": [
                            "1.1.1.1:443"
                          ]
                        }
                      ]
                    }
                  ]
                }
              ]
            }
          ],
          "routes": [
            {
              "match": [
                {
                  "host": [
                    "127.0.0.1"
                  ]
                }
              ],
              "handle": [
                {
                  "handler": "subroute",
                  "routes": [
                    {
                      "handle": [
                        {
                          "body": "hello",
                          "handler": "static_response"
                        }
                      ]
                    }
                  ]
                }
              ],
              "terminal": true
            }
          ]
        }
      }
    },
    "pki": {
      "certificate_authorities": {
        "local": {
          "install_trust": false
        }
      }
    },
    "tls": {
      "automation": {
        "policies": [
          {
            "issuers": [
              {
                "module": "internal"
              }
            ]
          }
        ]
      }
    }
  }
}

@ydylla @mholt I think the original behavior should be restored. If a matcher matches a connection, that connection is handled by the corresponding handler. And if that handler will call the next handler, the handler provider will be called. Otherwise, next is called. Essentially next is a fallback handler.

And, from the messages, it tries to solve when matching, some of the data is not available so a conclusion can be made. But some times a conclusion can be made based on the available data. TLS is one of them. Trying to read a connection again and again in this case makes no sense, wasting server processing powers. There are two solution I think, one a nil match error means more data is needed to read a conclusion, or a special error that means this matcher can never happen. And if all the routes can determine a match can't happen, the next handler will be called.

[WeidiDeng]

Here is the relevant log:

{"level":"debug","ts":1719452095.799098,"logger":"caddy.listeners.layer4","msg":"prefetched","remote":"127.0.0.1:57051","bytes":67}
{"level":"debug","ts":1719452095.799098,"logger":"caddy.listeners.layer4","msg":"matching","remote":"127.0.0.1:57051","matcher":"layer4.matchers.tls","matched":false}
{"level":"warn","ts":1719452105.813285,"logger":"caddy.listeners.layer4","msg":"matching connection","remote":"127.0.0.1:57051","error":"aborted matching according to timeout"}
{"level":"debug","ts":1719452105.813285,"logger":"caddy.listeners.layer4","msg":"connection stats","remote":"127.0.0.1:57051","read":67,"written":0,"duration":10.0141872}
{"level":"debug","ts":1719453152.4126937,"logger":"caddy.listeners.layer4","msg":"prefetched","remote":"127.0.0.1:57430","bytes":253}
{"level":"debug","ts":1719453152.4126937,"logger":"layer4.matchers.tls","msg":"matched","remote":"127.0.0.1:57430","server_name":"example.com"}
{"level":"debug","ts":1719453152.4126937,"logger":"caddy.listeners.layer4","msg":"matching","remote":"127.0.0.1:57430","matcher":"layer4.matchers.tls","matched":true}
{"level":"debug","ts":1719453152.5728302,"logger":"layer4.handlers.proxy","msg":"dial upstream","remote":"127.0.0.1:57430","upstream":"1.1.1.1:443"}
{"level":"debug","ts":1719453152.9675741,"logger":"caddy.listeners.layer4","msg":"connection stats","remote":"127.0.0.1:57430","read":317,"written":4821,"duration":0.5548802}

Notice I increased the timeout to 10 seconds. It won't help as the connect is read in vain. In this case I'm send an http request.

[WeidiDeng]

Feel strange about the prefetch in the loop, if a matcher requires more data, why doesn't it read more in the first place?A deadline will stop it anyway. If a connection requires writing to determine the exact protocol type, it is not suitable to be matched. Except http matcher which can match method, path etc., other matchers can determine based on a few bytes that is available and a conclusion can be made.

[mholt]

Hey Weidi! Great questions/comments. (I've been recovering from a very tired spell -- I'll try to catch up ASAP.)

if a matcher requires more data, why doesn't it read more in the first place?

Because the client may not send more. What if the matcher requires, say, 10 bytes to match, but the client only sends 3 bytes and then waits for the server to respond?

There is one breaking change in that when compiling a routesList, the next handler is only called when a match is made

Hmm this may have been fixed with a recent commit? I don't remember for sure.

[WeidiDeng]

Because the client may not send more. What if the matcher requires, say, 10 bytes to match, but the client only sends 3 bytes and then waits for the server to respond?

If the connection is written to, the match decision is already made. Matcher should only read from a connection, not write to a it because matcher thinks it's a type of connection. And there is no such thing happening right now in the module, socks5 which this patch is supposed to handle. In this case, if a client sends some data that looks like socks5 proxy, caddy can try to write to it to get more information about the connection, later these data have to be discarded when it is handled by the handler, as he said in that patch:

The socks5 matcher is sadly very limited, since the initial data send to the server is very short. It can only match on the requested auth methods. To get to the interesting part of the handshake the matcher would have to respond and select an auth method. Theoretically this should be possible but goes far beyond initial support. Since it would also require dropping the first few response bytes from the handler (aka upstream real socks server).

Hmm this may have been fixed with a recent commit? I don't remember for sure.

This is the latest commit.

I see he also tries to fix it by using the wrong method in this patch. This time the connection should be handled by a fallback handler, and yet he just limits the number of loops in the vain hope the proxy protocol matcher would match it. The problem is as I said, there is no distinction made between whether the matcher needs more data or just that the fallback handler should be called because non of the matchers matches, non considering that matchers write to connections because matchers presume it's a specific type of protocol (which is not done anyway at this time).

[ydylla]

Yeah I was afraid I would break the listener wrapper. Sorry.
The problem is that the new behavior only calls the fallback handler after a match. Which never happens in your example config for the http only request. The config could be fixed by adding a route with http matcher and empty/missing handle block.

{
  "match": [
    {"http": []}
  ]
}

Currently I do not see a way for restoring the old behavior of calling the fallback handler without a match. We need the loop since clients apparently do not always send all data at once (like I mentioned in #72 (comment)).

if a matcher requires more data, why doesn't it read more in the first place

The point of the changed behavior is to prevent matchers from blocking, so people have to think less about the matcher order. And developers less about how they write matchers. This has nothing to do with matchers writing data.
For example now you could have a matcher do a io.ReadFull with some large buffer as first matcher without it blocking all other routes if a client does not send enough data. The original example where I encountered this was with socks4 vs socks5. See #68 (comment):

Another annoyance is if you want to multiplex socks4 & socks5 like in the bellow socks.json config. The socks5 matcher has to be executed first, because if the socks4 matcher runs first it tries to read 8 bytes but a client connecting with socks5 will often only send 3 or 4 bytes causing the socks4 matcher to block indefinitely.

[WeidiDeng]

Currently I do not see a way for restoring the old behavior of calling the fallback handler without a match. We need the loop since clients apparently do not always send all data at once (like I mentioned in #72 (comment)).

That's a breaking change and unexpected. And as I said, without a fallback in this case causes more unexpected problems. And current codes do nothing to find if the matcher can't match anymore and call the fallback in this case.

The point of the changed behavior is to prevent matchers from blocking, so people have to think less about the matcher order. And developers less about how they write matchers. This has nothing to do with matchers writing data. For example now you could have a matcher do a io.ReadFull with some large buffer as first matcher without it blocking all other routes if a client does not send enough data. The original example where I encountered this was with socks4 vs socks5. See #68 (comment):

That's a positive change. I'll see what can be done with the loop. Right now no fallback and the loop simply doesn't know when to quit as there is no matched routes, and connection is handled by an no op handler is not considered hurts current implementation very much in edge cases.

[WeidiDeng]

This comment almost makes it like ordering is not important and non-blocking is 100% better than the old behavior. Ordering is important, as people expect this behavior for very long time.

Less block time is appreciated for drastic different protocols, but handler chains should still be respected. This is also true for caddy http server.

[ydylla]

That's a breaking change and unexpected. And as I said, without a fallback in this case causes more unexpected problems.

It's only a problem for the listener wrapper. For which you are very likely the only user since it is neither documented on caddyserver.com nor in the readme of layer4. So one must read the code to even know it exists.

I agree breaking changes are bad, but it gets increasingly difficult to keep all config scenarios in mind when developing for layer4. Someday someone should add a kind of integration test suite with some example configs that should work. Additionally, proper version numbers for layer4 would likely also help make changes more visible. For now there is a reason why:

This app is very capable and flexible, but is still in development. Please expect breaking changes.

is mentioned in the readme.

This comment almost makes it like ordering is not important and non-blocking is 100% better than the old behavior.

Ordering is still somewhat respected, by trying matchers according to order first. Yes I did make a bad decision by jumping back to the 1st matcher initially, but this is fixed by now.

Currently I am quite happy how the new behavior works. But I am obviously biased :D
Even with the now discovered changed behavior in the listener wrapper, I think the benefits outweigh the downside of having to specify an extra matcher for the listener wrapper.

[WeidiDeng]

@ydylla As I mentioned in the other pr, your code doesn't respect if a handler is called instead always tries to rematch. That config has no practical meaning doesn't mean your handling is without problems. Adding an iteration counter doesn't fix the underlying problem. And that's the direct result of not respecting the fallback handler.

Ordering is still somewhat respected, by trying matchers according to order first. Yes I did make a bad decision by jumping back to the 1st matcher initially, but this is fixed by now.

It still tries jumping back to 1st matcher if a handler is handled again. And another retry.

It's only a problem for the listener wrapper. For which you are very likely the only user since it is neither documented on caddyserver.com nor in the readme of layer4. So one must read the code to even know it exists.

But your changes are causing other bugs as well, not just only for the listener wrapper, just as I said, not respecting the fallback handler. There are known caddy community members who use this poorly undocumented feature. Likely only user is such an arrogant presumption. Breaking changes doesn't mean older behaviours shouldn't be restored, which I did in here. In addition to restoring the old fallback behaviour, it addresses the underlying problems that matchers which can't match will be skipped automatically if there is no reason to. I'd like you to take a look at it to say what you think of it.

[WeidiDeng]

@ydylla Can you tell me why we still goto the first handler in this case?

[ydylla]

your code doesn't respect if a handler is called instead always tries to rematch

Not always. Just if the handler is not a terminal one, matching continues (see routes.go#L177). This is for example needed for a route with a tls handler followed by a route with a proxy handler. So layer4 terminates tls and can accept https and http traffic on the same port.

[
  {
    "match": [
      {"tls": {"sni": ["localhost"]}}
    ],
    "handle": [
      {"handler": "tls"}
    ]
  },
  {
    "match": [
      {"http": [{"host": ["localhost"]}]}
    ],
    "handle": [
      {
        "handler": "proxy",
        "upstreams": [{"dial": ["127.0.0.1:10080"]}]
      }
    ]
  }
]

On a match the fallback handler is still called. It is passed in routes.go#L166 as next into the handler chain. That's why the layer4 listener wrapper still works if it is used with a matcher.

Can you tell me why we still goto the first handler in this case?

I find it much more intuitve to continue where we left and then start at the beginning again. So its a continuous circle.
The looping and not skipping previously tried matchers is done because clients not always send all data in one go. I mentioned it in #72 (comment):

In reality it also seems to depend on how the client sends the data. Curl for example seems to send the http2 upgrade request first and after that the http2 frames. Instead of both together with the same "flush".

Please try the prefetch.json config from #192 with the 4 curl commands on your PR (#208). You will see only one of them works. The simple http request one. This config and commands worked on 145ec36 (before my rewrite) and on current master ca3e2f3. So right now your PR is also a breaking change. Like I said its really hard to keep every possible config in mind.

Sadly I still do not see a good way of keeping both behaviors. Its a fundamental problem of who is owning the incoming connection. Using a listener wrapper on top of the caddy http app is also a bit of a hack or at least backwards. It would be much nicer if the caddy http server is a handler of layer4. Like @mholt also mentioned here #70 (comment)

One of my (few) regrets about how I built Caddy 2 is that I didn't make the http module inside a network or layer4 module. In other words, I wish this is how Caddy worked, and if I were to design a Caddy v3, it'd probably take this idea further. Because yeah, it makes a lot of sense for layer4 to be the main app module that can then run applications on top of it.

[WeidiDeng]

I'll see what can be done to make that JSON configuration work. Didn't actually test those.

[WeidiDeng]

I'll provide more concrete configuration examples and corresponding curl commands when I have time and update or create a new issue to show some unexpected breaks (I've some in mind). And discuss them in depth.