feat(log): implement custom error log filter to suppress "context can… (#470)

* feat(log): implement custom error log filter to suppress "context canceled" messages

fixes #446

Signed-off-by: Jason Cameron <git@jasoncameron.dev>

* feat(log): suppress 'context canceled' errors in HTTP logs

Signed-off-by: Jason Cameron <git@jasoncameron.dev>

---------

Signed-off-by: Jason Cameron <git@jasoncameron.dev>

cmd/anubis/main.go

@@ -309,7 +309,7 @@ func main() {
 	h = internal.XForwardedForToXRealIP(h)
 	h = internal.XForwardedForUpdate(h)
 
-	srv := http.Server{Handler: h}
+	srv := http.Server{Handler: h, ErrorLog: internal.GetFilteredHTTPLogger()}
 	listener, listenerUrl := setupListener(*bindNetwork, *bind)
 	slog.Info(
 		"listening",
@@ -348,7 +348,7 @@ func metricsServer(ctx context.Context, done func()) {
 	mux := http.NewServeMux()
 	mux.Handle(anubis.BasePrefix+"/metrics", promhttp.Handler())
 
-	srv := http.Server{Handler: mux}
+	srv := http.Server{Handler: mux, ErrorLog: internal.GetFilteredHTTPLogger()}
 	listener, metricsUrl := setupListener(*metricsBindNetwork, *metricsBind)
 	slog.Debug("listening for metrics", "url", metricsUrl)
 

docs/docs/CHANGELOG.md

@@ -19,6 +19,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - Add a warning for clients that don't store cookies
 - Disable Open Graph passthrough by default ([#435](https://github.com/TecharoHQ/anubis/issues/435))
 - Clarify the license of the mascot images ([#442](https://github.com/TecharoHQ/anubis/issues/442))
+- Started Suppressing 'Context canceled' errors from http in the logs ([#446](https://github.com/TecharoHQ/anubis/issues/446))
 
 ## v1.17.1: Asahi sas Brutus: Echo 1
 

internal/log.go

@@ -2,9 +2,11 @@ package internal
 
 import (
 	"fmt"
+	"log"
 	"log/slog"
 	"net/http"
 	"os"
+	"strings"
 )
 
 func InitSlog(level string) {
@@ -34,3 +36,24 @@ func GetRequestLogger(r *http.Request) *slog.Logger {
 		"x-real-ip", r.Header.Get("X-Real-Ip"),
 	)
 }
+
+// ErrorLogFilter is used to suppress "context canceled" logs from the http server when a request is canceled (e.g., when a client disconnects).
+type ErrorLogFilter struct {
+	Unwrap *log.Logger
+}
+
+func (elf *ErrorLogFilter) Write(p []byte) (n int, err error) {
+	logMessage := string(p)
+	if strings.Contains(logMessage, "context canceled") {
+		return len(p), nil // Suppress the log by doing nothing
+	}
+	if elf.Unwrap != nil {
+		return elf.Unwrap.Writer().Write(p)
+	}
+	return len(p), nil
+}
+
+func GetFilteredHTTPLogger() *log.Logger {
+	stdErrLogger := log.New(os.Stderr, "", log.LstdFlags) // essentially what the default logger is.
+	return log.New(&ErrorLogFilter{Unwrap: stdErrLogger}, "", 0)
+}

internal/log_test.go

@@ -0,0 +1,46 @@
+package internal
+
+import (
+	"bytes"
+	"log"
+	"strings"
+	"testing"
+)
+
+func TestErrorLogFilter(t *testing.T) {
+	var buf bytes.Buffer
+	destLogger := log.New(&buf, "", 0)
+	errorFilterWriter := &ErrorLogFilter{Unwrap: destLogger}
+	testErrorLogger := log.New(errorFilterWriter, "", 0)
+
+	// Test Case 1: Suppressed message
+	suppressedMessage := "http: proxy error: context canceled"
+	testErrorLogger.Println(suppressedMessage)
+
+	if buf.Len() != 0 {
+		t.Errorf("Suppressed message was written to output. Output: %q", buf.String())
+	}
+	buf.Reset()
+
+	// Test Case 2: Allowed message
+	allowedMessage := "http: another error occurred"
+	testErrorLogger.Println(allowedMessage)
+
+	output := buf.String()
+	if !strings.Contains(output, allowedMessage) {
+		t.Errorf("Allowed message was not written to output. Output: %q", output)
+	}
+	if !strings.HasSuffix(output, "\n") {
+		t.Errorf("Allowed message output is missing newline. Output: %q", output)
+	}
+	buf.Reset()
+
+	// Test Case 3: Partially matching message (should be suppressed)
+	partiallyMatchingMessage := "Some other log before http: proxy error: context canceled and after"
+	testErrorLogger.Println(partiallyMatchingMessage)
+
+	if buf.Len() != 0 {
+		t.Errorf("Partially matching message was written to output. Output: %q", buf.String())
+	}
+	buf.Reset()
+}