diff --git a/AGENTS.md b/AGENTS.md index 8ade84f..3646f00 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -257,6 +257,16 @@ Checks `X-Forwarded-For` header first (for proxied requests), then falls back to - `WriteTimeout`: configurable via `backup_timeout` (converted to `time.Duration`) - TLS minimum version: TLS 1.3 (when HTTPS enabled) +### TLS Error Handling + +The server uses a `serverWrapper` type to intercept and classify errors from `Serve()` and `ServeTLS()`. TLS-specific errors are logged at debug level to reduce log clutter: + +- Uses `errors.As` to detect TLS error types: `tls.AlertError`, `tls.CertificateVerificationError`, `tls.ECHRejectionError`, `tls.RecordHeaderError` +- Also checks for "tls:" prefix in error messages +- Additionally uses `http.Server.ErrorLog` with a custom logger that writes at debug level for net/http's internal TLS-related messages + +This ensures client-side TLS errors (handshake failures, certificate issues) don't clutter production logs. + ## Dependencies - `github.com/hjson/hjson-go` v3.3.0 — HJSON config parsing diff --git a/README.md b/README.md index 66fee67..d4fe4c8 100644 --- a/README.md +++ b/README.md @@ -111,6 +111,19 @@ good enough cypher. And one more thing user and password are mandatory, we should have at least some minimal barriers, right? +## Logging + +Backer logs events via Go's `slog`. Log levels: error, warn, info, debug. + +### TLS Error Handling + +TLS handshake errors and other client-side SSL/TLS errors are logged at **debug** level to reduce log clutter. +This includes: +- Certificate verification failures +- Handshake failures +- Protocol errors +- TLS-specific connection issues + ## Special Thanks This project was developed with the assistance of **opencode** (AI co-programmer powered by MIMO). The AI helped with: diff --git a/cmd/backer/main.go b/cmd/backer/main.go index 532fb4c..9d1e2d2 100644 --- a/cmd/backer/main.go +++ b/cmd/backer/main.go @@ -2,6 +2,7 @@ package main import ( + "errors" "flag" "fmt" "net/http" @@ -43,7 +44,7 @@ func main() { log.Infof("Starting backer version %s at %s", version, server.Addr) if backer.C.NoHTTPS { - if err := server.ListenAndServe(); err != nil && err != http.ErrServerClosed { + if err := server.Serve(); err != nil && !errors.Is(err, http.ErrServerClosed) { log.Fatalf("Failed to start server: %v", err) } } else { @@ -55,7 +56,7 @@ func main() { log.Fatalf("Certificate key file error: %v", err) } - if err := server.ListenAndServeTLS(backer.C.Cert, backer.C.Key); err != nil && err != http.ErrServerClosed { + if err := server.ServeTLS(backer.C.Cert, backer.C.Key); err != nil && !errors.Is(err, http.ErrServerClosed) { log.Fatalf("Failed to start server: %v", err) } } diff --git a/internal/backer/newServer.go b/internal/backer/newServer.go index d841fdf..7edf156 100644 --- a/internal/backer/newServer.go +++ b/internal/backer/newServer.go @@ -3,6 +3,7 @@ package backer import ( "context" "crypto/tls" + "errors" "fmt" "io" "net" @@ -14,6 +15,36 @@ import ( "backer/internal/log" ) +// isTLSError checks if the given error is TLS-related. +// It checks for both TLS-specific error types and error messages containing "tls:". +func isTLSError(err error) bool { + if err == nil { + return false + } + + var alertErr *tls.AlertError + if errors.As(err, &alertErr) && alertErr != nil { + return true + } + + var certErr *tls.CertificateVerificationError + if errors.As(err, &certErr) && certErr != nil { + return true + } + + var echErr *tls.ECHRejectionError + if errors.As(err, &echErr) && echErr != nil { + return true + } + + var recordErr *tls.RecordHeaderError + if errors.As(err, &recordErr) && recordErr != nil { + return true + } + + return strings.HasPrefix(err.Error(), "tls:") +} + // withServerHeader wraps a handler to add Server header to all responses. func withServerHeader(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { @@ -23,7 +54,8 @@ func withServerHeader(next http.Handler) http.Handler { } // NewServer starts new server instance with given config file. -func NewServer(configPath string) (*http.Server, error) { +// It returns a serverWrapper that intercepts and classifies server errors. +func NewServer(configPath string) (*serverWrapper, error) { //nolint: revive _ = log.Init("info", "") // Initialize logger with defaults for early logging. if err := LoadConfig(configPath); err != nil { @@ -139,21 +171,27 @@ func NewServer(configPath string) (*http.Server, error) { // HTTP mode if nohttps is enabled in config. // HTTPS mode if nohttps is disabled in config. if C.NoHTTPS { - return &http.Server{ + return &serverWrapper{ + Server: &http.Server{ + Addr: fmt.Sprintf("%s:%d", C.Address, C.Port), + Handler: withServerHeader(mux), + ReadHeaderTimeout: readHeaderTimeout, + WriteTimeout: time.Duration(C.BackupTimeout) * time.Minute, + ErrorLog: log.DebugLogger(), + }, + }, nil + } + + return &serverWrapper{ + Server: &http.Server{ Addr: fmt.Sprintf("%s:%d", C.Address, C.Port), Handler: withServerHeader(mux), ReadHeaderTimeout: readHeaderTimeout, WriteTimeout: time.Duration(C.BackupTimeout) * time.Minute, - }, nil - } - - return &http.Server{ - Addr: fmt.Sprintf("%s:%d", C.Address, C.Port), - Handler: withServerHeader(mux), - ReadHeaderTimeout: readHeaderTimeout, - WriteTimeout: time.Duration(C.BackupTimeout) * time.Minute, - TLSConfig: &tls.Config{ - MinVersion: tls.VersionTLS13, + TLSConfig: &tls.Config{ + MinVersion: tls.VersionTLS13, + }, + ErrorLog: log.DebugLogger(), }, }, nil } @@ -235,4 +273,42 @@ func getCompressionAlgorithm(requestedExt string) string { } } +// serverWrapper wraps http.Server to intercept and classify errors. +type ( + serverWrapper struct { + *http.Server + } +) + +// Serve starts the server and classifies any errors returned. +// TLS-related errors are logged at debug level, other errors at warn level. +func (sw *serverWrapper) Serve() error { + err := sw.ListenAndServe() + + if err != nil { + if isTLSError(err) { + log.Debugf("Server error: %v", err) + } else { + log.Warnf("Server error: %v", err) + } + } + + return err +} + +// ServeTLS starts the TLS server and classifies any errors returned. +func (sw *serverWrapper) ServeTLS(certFile, keyFile string) error { + err := sw.ListenAndServeTLS(certFile, keyFile) + + if err != nil { + if isTLSError(err) { + log.Debugf("Server TLS error: %v", err) + } else { + log.Warnf("Server TLS error: %v", err) + } + } + + return err +} + /* vim: setlocal ft=go noet ai ts=4 sw=4 sts=4: */ diff --git a/internal/log/main.go b/internal/log/main.go index 33ff2e0..28a4e03 100644 --- a/internal/log/main.go +++ b/internal/log/main.go @@ -2,9 +2,12 @@ package log import ( + "context" "fmt" + "log" "log/slog" "os" + "strings" "time" ) @@ -13,6 +16,13 @@ var ( Log *os.File ) +// slogWriter implements io.Writer to redirect standard log to slog. +type ( + slogWriter struct { + handler slog.Handler + } +) + // Init sets up logger stuff. // level can be error, warn, info, debug; if something other is supplied, info level is selected. func Init(level, filename string) error { @@ -122,6 +132,44 @@ func Debugf(format string, a ...any) { slog.Debug(fmt.Sprintf(format, a...)) } +// DebugLogger returns a standard library logger that writes to debug level. +// This is useful for assigning to http.Server.ErrorLog to move TLS handshake +// and other client-side errors to debug level. +func DebugLogger() *log.Logger { + opts := &slog.HandlerOptions{ + Level: slog.LevelDebug, + } + + handler := slog.NewTextHandler(Log, opts) + + return log.New(&slogWriter{handler: handler}, "", 0) +} + +// Write implements io.Writer. It differentiates TLS/SSL errors from other errors. +// TLS-related errors are logged at debug level, while other errors (handler issues, +// unexpected behavior) are logged at warn level. +func (w *slogWriter) Write(p []byte) (int, error) { + msg := string(p) + + isTLSError := strings.Contains(msg, "tls") || + strings.Contains(msg, "ssl") || + strings.Contains(msg, "TLS") || + strings.Contains(msg, "SSL") || + strings.Contains(msg, "handshake") || + strings.Contains(msg, "certificate") + + level := slog.LevelWarn + if isTLSError { + level = slog.LevelDebug + } + + record := slog.NewRecord(time.Now(), level, msg, 0) + + _ = w.handler.Handle(context.TODO(), record) + + return len(p), nil +} + // Fatal logs args at error level and quits with status code 1. func Fatal(args ...any) { slog.Error(fmt.Sprint(args...))