Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fixes and Logging #71

Merged
merged 3 commits into from
Nov 29, 2022
Merged

Fixes and Logging #71

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
f6dacc1
fix: prevent 1st Read() after record() to return 0 bytes
ydylla Nov 2, 2022
504fa04
feat: add remote addr logging to important errors
ydylla Nov 4, 2022
d410e98
fix: connection processing not stopping on matcher error
ydylla Nov 2, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 10 additions & 2 deletions layer4/connection.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,14 +22,15 @@ import (
"sync"

"github.com/caddyserver/caddy/v2"
"go.uber.org/zap"
)

// WrapConnection wraps an underlying connection into a layer4 connection that
// supports recording and rewinding, as well as adding context with a replacer
// and variable table. This function is intended for use at the start of a
// connection handler chain where the underlying connection is not yet a layer4
// Connection value.
func WrapConnection(underlying net.Conn, buf *bytes.Buffer) *Connection {
func WrapConnection(underlying net.Conn, buf *bytes.Buffer, logger *zap.Logger) *Connection {
repl := caddy.NewReplacer()
repl.Set("l4.conn.remote_addr", underlying.RemoteAddr())
repl.Set("l4.conn.local_addr", underlying.LocalAddr())
Expand All @@ -41,6 +42,7 @@ func WrapConnection(underlying net.Conn, buf *bytes.Buffer) *Connection {
return &Connection{
Conn: underlying,
Context: ctx,
Logger: logger,
buf: buf,
}
}
Expand All @@ -62,6 +64,8 @@ type Connection struct {
// The context for the connection.
Context context.Context

Logger *zap.Logger

buf *bytes.Buffer // stores recordings
bufReader io.Reader // used to read buf so it doesn't discard bytes
recording bool
Expand All @@ -83,7 +87,10 @@ func (cx *Connection) Read(p []byte) (n int, err error) {
cx.bufReader = nil
err = nil
}
return
// prevent first read from returning 0 bytes because of empty bufReader
if !(n == 0 && err == nil) {
return
}
}

// buffer has been "depleted" so read from
Expand Down Expand Up @@ -121,6 +128,7 @@ func (cx *Connection) Wrap(conn net.Conn) *Connection {
return &Connection{
Conn: conn,
Context: cx.Context,
Logger: cx.Logger,
buf: cx.buf,
bufReader: cx.bufReader,
recording: cx.recording,
Expand Down
88 changes: 88 additions & 0 deletions layer4/connection_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,88 @@
package layer4

import (
"bytes"
"net"
"testing"

"go.uber.org/zap"
)

func TestConnection_RecordAndRewind(t *testing.T) {
in, out := net.Pipe()
defer in.Close()
defer out.Close()

cx := WrapConnection(out, &bytes.Buffer{}, zap.NewNop())
defer cx.Close()

matcherData := []byte("foo")
consumeData := []byte("bar")

buf := make([]byte, len(matcherData))

go func() {
in.Write(matcherData)
in.Write(consumeData)
}()

// 1st matcher

cx.record()

n, err := cx.Read(buf)
if err != nil {
t.Fatal(err)
}
if n != len(matcherData) {
t.Fatalf("expected to read %d bytes but got %d", len(matcherData), n)
}
if bytes.Compare(matcherData, buf) != 0 {
t.Fatalf("expected %s but received %s", matcherData, buf)
}

cx.rewind()

// 2nd matcher (reads same data)

cx.record()

n, err = cx.Read(buf)
if err != nil {
t.Fatal(err)
}
if n != len(matcherData) {
t.Fatalf("expected to read %d bytes but got %d", len(matcherData), n)
}
if bytes.Compare(matcherData, buf) != 0 {
t.Fatalf("expected %s but received %s", matcherData, buf)
}

cx.rewind()

// 1st consumer (no record call)

n, err = cx.Read(buf)
if err != nil {
t.Fatal(err)
}
if n != len(matcherData) {
t.Fatalf("expected to read %d bytes but got %d", len(matcherData), n)
}
if bytes.Compare(matcherData, buf) != 0 {
t.Fatalf("expected %s but received %s", matcherData, buf)
}

// 2nd consumer (reads other data)

n, err = cx.Read(buf)
if err != nil {
t.Fatal(err)
}
if n != len(consumeData) {
t.Fatalf("expected to read %d bytes but got %d", len(consumeData), n)
}
if bytes.Compare(consumeData, buf) != 0 {
t.Fatalf("expected %s but received %s", consumeData, buf)
}
}
13 changes: 13 additions & 0 deletions layer4/matchers.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (
"strings"

"github.com/caddyserver/caddy/v2"
"go.uber.org/zap"
)

func init() {
Expand All @@ -46,6 +47,18 @@ func (mset MatcherSet) Match(cx *Connection) (matched bool, err error) {
cx.record()
matched, err = m.Match(cx)
cx.rewind()
if cx.Logger.Core().Enabled(zap.DebugLevel) {
matcher := "unknown"
if cm, ok := m.(caddy.Module); ok {
matcher = cm.CaddyModule().String()
}
cx.Logger.Debug("matching",
zap.String("remote", cx.RemoteAddr().String()),
zap.Error(err),
zap.String("matcher", matcher),
zap.Bool("matched", matched),
)
}
if !matched || err != nil {
return
}
Expand Down
3 changes: 2 additions & 1 deletion layer4/routes.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -127,7 +127,8 @@ func wrapRoute(route *Route, logger *zap.Logger) Middleware {
// route must match at least one of the matcher sets
matched, err := route.matcherSets.AnyMatch(cx)
if err != nil {
logger.Error("matching connection", zap.Error(err))
logger.Error("matching connection", zap.String("remote", cx.RemoteAddr().String()), zap.Error(err))
return nil // return nil so the error does not get logged again
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Where would it be logged again? I don't see anywhere else we use the value err.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be logged again in server.go#L109

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Interesting, are you seeing that in your logs? How does err get returned from here?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The return statement is completely new to fix this:

The first bug (at least I think it is one 😄) is that when a matcher returns an error the processing is not stopped. Instead the next matcher is tried and if that matches its handlers are executed even if the connection is broken.

You can see example logs of the processing not stopping in the initial post. When using return err instead one would see the double logging.

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I follow so far, except I don't see where we are using return err anywhere. We always return nextCopy.Handle(cx) instead.

(Sorry if I'm being a bit slow to understand.)

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we are talking past each other :)

I included the comment to signify we are returning nil on purpose, because otherwise it may look like a bug.

You are right we mostly return nextCopy.Handle(cx) except for exactly this case, since we want to stop the execution of the chain. But we already logged (handled) the error, so it is wrong to return the error (like it's often the case in if err != nil blocks). Because the last return value from the chain will eventually appear in server.go#L106 and thus would get logged in server.go#L109 which we do not want because we already logged it.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @mholt, did you found the time to think about this?

Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ydylla I'm so sorry for the delay on this PR. (It's not fair to you, that's for sure.) I was traveling this last week and also taking a little break from sprinting on Caddy stuff after the 2.6 release (to avoid burnout), and now I'm way behind on notifications. 😅 I'll be catching up soon!

If we can find another maintainer who is willing to review and approve this and other PRs, that might be a good idea so it's not always blocked by me. I feel bad about that! I might look around and see who would be willing to accept the invitation. This plugin just isn't nearly as active as the main Caddy project so it has fewer candidates.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No problem at all, I understand that you are very busy. Don't feel bad, you are doing good work with caddy.
But you have to endure me pining you from time to time 😄

I just used the delay to clean up the commits and fix the failing tests in the l4socks module.

}
if !matched {
return nextCopy.Handle(cx)
Expand Down
4 changes: 2 additions & 2 deletions layer4/server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -100,13 +100,13 @@ func (s Server) handle(conn net.Conn) {
buf.Reset()
defer bufPool.Put(buf)

cx := WrapConnection(conn, buf)
cx := WrapConnection(conn, buf, s.logger)

start := time.Now()
err := s.compiledRoute.Handle(cx)
duration := time.Since(start)
if err != nil {
s.logger.Error("handling connection", zap.Error(err))
s.logger.Error("handling connection", zap.String("remote", cx.RemoteAddr().String()), zap.Error(err))
}

s.logger.Debug("connection stats",
Expand Down
12 changes: 7 additions & 5 deletions modules/l4http/httpmatcher_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -6,13 +6,15 @@ import (
"crypto/tls"
"encoding/base64"
"encoding/json"
"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/modules/caddyhttp"
"github.com/mholt/caddy-l4/layer4"
"io"
"net"
"sync"
"testing"

"github.com/caddyserver/caddy/v2"
"github.com/caddyserver/caddy/v2/modules/caddyhttp"
"github.com/mholt/caddy-l4/layer4"
"go.uber.org/zap"
)

func assertNoError(t *testing.T, err error) {
Expand All @@ -31,7 +33,7 @@ func httpMatchTester(t *testing.T, matcherSets caddyhttp.RawMatcherSets, data []
_ = out.Close()
}()

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer func() {
Expand Down Expand Up @@ -200,7 +202,7 @@ func TestHttpMatchingByProtocolWithHttps(t *testing.T) {
_ = out.Close()
}()

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer func() {
Expand Down
12 changes: 7 additions & 5 deletions modules/l4proxyprotocol/handler_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,12 +3,14 @@ package l4proxyprotocol
import (
"bytes"
"context"
"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"io"
"net"
"sync"
"testing"

"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"go.uber.org/zap"
)

func assertString(t *testing.T, expected string, value string) {
Expand All @@ -23,7 +25,7 @@ func TestProxyProtocolHandleV1(t *testing.T) {
in, out := net.Pipe()
defer closePipe(wg, in, out)

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer wg.Done()
Expand Down Expand Up @@ -61,7 +63,7 @@ func TestProxyProtocolHandleV2(t *testing.T) {
in, out := net.Pipe()
defer closePipe(wg, in, out)

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer wg.Done()
Expand Down Expand Up @@ -99,7 +101,7 @@ func TestProxyProtocolHandleGarbage(t *testing.T) {
in, out := net.Pipe()
defer closePipe(wg, in, out)

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer wg.Done()
Expand Down
10 changes: 6 additions & 4 deletions modules/l4proxyprotocol/matcher_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,11 +3,13 @@ package l4proxyprotocol
import (
"bytes"
"encoding/hex"
"github.com/mholt/caddy-l4/layer4"
"io"
"net"
"sync"
"testing"

"github.com/mholt/caddy-l4/layer4"
"go.uber.org/zap"
)

var ProxyV1Example = []byte("PROXY TCP4 192.168.0.1 192.168.0.11 56324 443\r\n")
Expand All @@ -31,7 +33,7 @@ func TestProxyProtocolMatchV1(t *testing.T) {
in, out := net.Pipe()
defer closePipe(wg, in, out)

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer wg.Done()
Expand All @@ -57,7 +59,7 @@ func TestProxyProtocolMatchV2(t *testing.T) {
in, out := net.Pipe()
defer closePipe(wg, in, out)

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer wg.Done()
Expand All @@ -83,7 +85,7 @@ func TestProxyProtocolMatchGarbage(t *testing.T) {
in, out := net.Pipe()
defer closePipe(wg, in, out)

cx := layer4.WrapConnection(in, &bytes.Buffer{})
cx := layer4.WrapConnection(in, &bytes.Buffer{}, zap.NewNop())
go func() {
wg.Add(1)
defer wg.Done()
Expand Down
8 changes: 5 additions & 3 deletions modules/l4socks/socks4_matcher_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,11 +3,13 @@ package l4socks
import (
"bytes"
"context"
"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"io"
"net"
"testing"

"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"go.uber.org/zap"
)

func assertNoError(t *testing.T, err error) {
Expand Down Expand Up @@ -76,7 +78,7 @@ func TestSocks4Matcher_Match(t *testing.T) {
_ = out.Close()
}()

cx := layer4.WrapConnection(out, &bytes.Buffer{})
cx := layer4.WrapConnection(out, &bytes.Buffer{}, zap.NewNop())
go func() {
_, err := in.Write(tc.data)
assertNoError(t, err)
Expand Down
8 changes: 5 additions & 3 deletions modules/l4socks/socks5_handler_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,17 +3,19 @@ package l4socks
import (
"bytes"
"context"
"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"io"
"net"
"testing"

"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"go.uber.org/zap"
)

func replay(t *testing.T, handler *Socks5Handler, expectedError string, messages [][]byte) {
t.Helper()
in, out := net.Pipe()
cx := layer4.WrapConnection(out, &bytes.Buffer{})
cx := layer4.WrapConnection(out, &bytes.Buffer{}, zap.NewNop())
defer func() {
_ = in.Close()
_, _ = io.Copy(io.Discard, out)
Expand Down
8 changes: 5 additions & 3 deletions modules/l4socks/socks5_matcher_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,11 +3,13 @@ package l4socks
import (
"bytes"
"context"
"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"io"
"net"
"testing"

"github.com/caddyserver/caddy/v2"
"github.com/mholt/caddy-l4/layer4"
"go.uber.org/zap"
)

func TestSocks5Matcher_Match(t *testing.T) {
Expand Down Expand Up @@ -53,7 +55,7 @@ func TestSocks5Matcher_Match(t *testing.T) {
_ = out.Close()
}()

cx := layer4.WrapConnection(out, &bytes.Buffer{})
cx := layer4.WrapConnection(out, &bytes.Buffer{}, zap.NewNop())
go func() {
_, err := in.Write(tc.data)
assertNoError(t, err)
Expand Down
Loading