From cace340e7a7f0decf234da08f6af1ae570563533 Mon Sep 17 00:00:00 2001 From: Mark Mennell Date: Fri, 25 Sep 2026 11:52:13 +0800 Subject: [PATCH 1/2] Don't warn when a connection closes without sending data TCP health checks, load balancer probes and port scanners connect to the fmsg port (sometimes completing the TLS handshake) and close without sending anything. Each one logged "WARN: reading header from, : EOF", which floods the log and buries real warnings. handleConn now counts the bytes it reads, and when the header read fails with EOF or a connection reset before any bytes arrived, it closes the connection without a warning. The existing INFO line still records the connection. A partial or malformed header, a timeout, or any other error still warns as before. Co-Authored-By: Claude Opus 5.5 (1M context) --- cmd/fmsgd/empty_conn_test.go | 139 +++++++++++++++++++++++++++++++++++ cmd/fmsgd/host.go | 23 ++++++ 2 files changed, 162 insertions(+) create mode 100644 cmd/fmsgd/empty_conn_test.go diff --git a/cmd/fmsgd/empty_conn_test.go b/cmd/fmsgd/empty_conn_test.go new file mode 100644 index 0000000..ec9255f --- /dev/null +++ b/cmd/fmsgd/empty_conn_test.go @@ -0,0 +1,139 @@ +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) + } +} + +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) + } +} + +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..d04100f 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,24 @@ 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 isn't worth 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 +1732,10 @@ func handleConn(c net.Conn) { // read header header, r, err := readHeader(tc) if err != nil { + if closedWithoutData(tc, err) { + abortConn(c) + return + } log.Printf("WARN: reading header from, %s: %s", c.RemoteAddr().String(), err) if tc.wroteResponse { _ = c.Close() From cd8bab3802a2dcea1061d8e502f35d2a61e52e0f Mon Sep 17 00:00:00 2001 From: Mark Mennell Date: Fri, 25 Sep 2026 12:52:17 +0800 Subject: [PATCH 2/2] Log connections that close without data at INFO Operators still see who connected and from where, just not as a warning. Co-Authored-By: Claude Opus 5.5 (1M context) --- cmd/fmsgd/empty_conn_test.go | 6 ++++++ cmd/fmsgd/host.go | 4 +++- 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/cmd/fmsgd/empty_conn_test.go b/cmd/fmsgd/empty_conn_test.go index ec9255f..ed9da65 100644 --- a/cmd/fmsgd/empty_conn_test.go +++ b/cmd/fmsgd/empty_conn_test.go @@ -87,6 +87,9 @@ func TestHandleConnTCPProbeDoesNotWarn(t *testing.T) { 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) { @@ -100,6 +103,9 @@ func TestHandleConnTLSProbeDoesNotWarn(t *testing.T) { 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) { diff --git a/cmd/fmsgd/host.go b/cmd/fmsgd/host.go index d04100f..1b8dcb9 100644 --- a/cmd/fmsgd/host.go +++ b/cmd/fmsgd/host.go @@ -1703,7 +1703,8 @@ func (c *responseTrackingConn) Read(b []byte) (int, error) { // 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 isn't worth a warning. +// 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 @@ -1733,6 +1734,7 @@ func handleConn(c net.Conn) { 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 }