diff --git a/cmd/fmsgd/empty_conn_test.go b/cmd/fmsgd/empty_conn_test.go new file mode 100644 index 0000000..ed9da65 --- /dev/null +++ b/cmd/fmsgd/empty_conn_test.go @@ -0,0 +1,145 @@ +package main + +import ( + "bytes" + "crypto/tls" + "errors" + "io" + "log" + "net" + "os" + "strings" + "sync" + "syscall" + "testing" + "time" +) + +type syncBuffer struct { + mu sync.Mutex + b bytes.Buffer +} + +func (s *syncBuffer) Write(p []byte) (int, error) { + s.mu.Lock() + defer s.mu.Unlock() + return s.b.Write(p) +} + +func (s *syncBuffer) String() string { + s.mu.Lock() + defer s.mu.Unlock() + return s.b.String() +} + +// serveOnce accepts one TLS connection, runs handleConn on it after the +// client function returns, and returns everything handleConn logged. +func serveOnce(t *testing.T, client func(addr string)) string { + t.Helper() + cert, _ := senderTestCertificate(t, time.Now().Add(time.Hour)) + ln, err := tls.Listen("tcp", "127.0.0.1:0", &tls.Config{Certificates: []tls.Certificate{cert}}) + if err != nil { + t.Fatal(err) + } + defer ln.Close() + + logs := &syncBuffer{} + log.SetOutput(logs) + defer log.SetOutput(os.Stderr) + + done := make(chan struct{}) + go func() { + defer close(done) + c, err := ln.Accept() + if err != nil { + return + } + handleConn(c) + }() + + client(ln.Addr().String()) + + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("handleConn did not return") + } + return logs.String() +} + +func tlsClient(t *testing.T, addr string) *tls.Conn { + t.Helper() + c, err := tls.Dial("tcp", addr, &tls.Config{InsecureSkipVerify: true, ServerName: "fmsg.example.com"}) + if err != nil { + t.Fatal(err) + } + return c +} + +func TestHandleConnTCPProbeDoesNotWarn(t *testing.T) { + logs := serveOnce(t, func(addr string) { + c, err := net.Dial("tcp", addr) + if err != nil { + t.Fatal(err) + } + c.Close() + }) + if strings.Contains(logs, "WARN") { + t.Fatalf("TCP connect-and-close should not warn, got:\n%s", logs) + } + if !strings.Contains(logs, "INFO: 127.0.0.1:") || !strings.Contains(logs, "closed the connection without sending data") { + t.Fatalf("TCP connect-and-close should be logged at INFO with the peer address, got:\n%s", logs) + } +} + +func TestHandleConnTLSProbeDoesNotWarn(t *testing.T) { + logs := serveOnce(t, func(addr string) { + c := tlsClient(t, addr) + if err := c.Handshake(); err != nil { + t.Fatal(err) + } + c.Close() + }) + if strings.Contains(logs, "WARN") { + t.Fatalf("TLS handshake-and-close should not warn, got:\n%s", logs) + } + if !strings.Contains(logs, "INFO: 127.0.0.1:") || !strings.Contains(logs, "closed the connection without sending data") { + t.Fatalf("TLS handshake-and-close should be logged at INFO with the peer address, got:\n%s", logs) + } +} + +func TestHandleConnPartialHeaderWarns(t *testing.T) { + logs := serveOnce(t, func(addr string) { + c := tlsClient(t, addr) + if _, err := c.Write([]byte{1}); err != nil { // version byte, then nothing + t.Fatal(err) + } + c.Close() + }) + if !strings.Contains(logs, "WARN: reading header from") { + t.Fatalf("a partial header should warn, got:\n%s", logs) + } +} + +func TestClosedWithoutData(t *testing.T) { + reset := &net.OpError{Op: "read", Net: "tcp", Err: os.NewSyscallError("read", syscall.ECONNRESET)} + cases := []struct { + name string + bytesRead int64 + err error + want bool + }{ + {"eof before data", 0, io.EOF, true}, + {"reset before data", 0, reset, true}, + {"eof after data", 1, io.EOF, false}, + {"unexpected eof after data", 3, io.ErrUnexpectedEOF, false}, + {"timeout before data", 0, os.ErrDeadlineExceeded, false}, + {"other error", 0, errors.New("tls: first record does not look like a TLS handshake"), false}, + } + for _, tc := range cases { + c := &responseTrackingConn{bytesRead: tc.bytesRead} + if got := closedWithoutData(c, tc.err); got != tc.want { + t.Errorf("%s: closedWithoutData = %v, want %v", tc.name, got, tc.want) + } + } +} diff --git a/cmd/fmsgd/host.go b/cmd/fmsgd/host.go index fb97863..1b8dcb9 100644 --- a/cmd/fmsgd/host.go +++ b/cmd/fmsgd/host.go @@ -19,6 +19,7 @@ import ( "path/filepath" "slices" "strings" + "syscall" "time" "unicode" "unicode/utf8" @@ -1690,6 +1691,25 @@ func abortConn(c net.Conn) { type responseTrackingConn struct { net.Conn wroteResponse bool + bytesRead int64 +} + +func (c *responseTrackingConn) Read(b []byte) (int, error) { + n, err := c.Conn.Read(b) + c.bytesRead += int64(n) + return n, err +} + +// closedWithoutData reports whether the peer went away before sending any +// message bytes: it connected (and possibly completed the TLS handshake), +// then closed or reset the connection. TCP health checks, load balancer +// probes and port scanners do this constantly, so it is logged at INFO +// rather than as a warning. +func closedWithoutData(c *responseTrackingConn, err error) bool { + if c.bytesRead > 0 { + return false + } + return errors.Is(err, io.EOF) || errors.Is(err, syscall.ECONNRESET) } func (c *responseTrackingConn) Write(b []byte) (int, error) { @@ -1713,6 +1733,11 @@ func handleConn(c net.Conn) { // read header header, r, err := readHeader(tc) if err != nil { + if closedWithoutData(tc, err) { + log.Printf("INFO: %s closed the connection without sending data", c.RemoteAddr().String()) + abortConn(c) + return + } log.Printf("WARN: reading header from, %s: %s", c.RemoteAddr().String(), err) if tc.wroteResponse { _ = c.Close()