Better logging

lib/web/app.go

@@ -5,11 +5,15 @@ import (
 	"fmt"
 	"html/template"
 	"io"
+	"log"
 	"mime"
 	"net/http"
 	"net/url"
+	"os"
+	"path/filepath"
 	"strconv"
 	"strings"
+	"sync"
 	"time"
 
 	"cpu-benchmark-server/lib/model"
@@ -25,6 +29,7 @@ type App struct {
 	store     *store.Store
 	templates *template.Template
 	pageSize  int
+	errorLog  *dailyErrorLogger
 }
 
 type indexPageData struct {
@@ -48,9 +53,9 @@ type indexPageData struct {
 type jsonSubmissionEnvelope struct {
 	Submitter string          `json:"submitter"`
 	Platform  string          `json:"platform"`
-	Benchmark *model.BenchmarkResult `json:"benchmark"`
+	Benchmark json.RawMessage `json:"benchmark"`
-	Result    *model.BenchmarkResult `json:"result"`
+	Result    json.RawMessage `json:"result"`
-	Data      *model.BenchmarkResult `json:"data"`
+	Data      json.RawMessage `json:"data"`
 }
 
 type flatSubmissionEnvelope struct {
@@ -63,7 +68,7 @@ type errorResponse struct {
 	Error string `json:"error"`
 }
 
-func New(store *store.Store, pageSize int) (*App, error) {
+func New(store *store.Store, pageSize int, errorLogDir string) (*App, error) {
 	funcs := template.FuncMap{
 		"formatInt64": formatInt64,
 		"formatFloat": formatFloat,
@@ -76,10 +81,16 @@ func New(store *store.Store, pageSize int) (*App, error) {
 		return nil, err
 	}
 
+	errorLog, err := newDailyErrorLogger(errorLogDir)
+	if err != nil {
+		return nil, err
+	}
+
 	return &App{
 		store:     store,
 		templates: templates,
 		pageSize:  pageSize,
+		errorLog:  errorLog,
 	}, nil
 }
 
@@ -87,6 +98,7 @@ func (a *App) Routes() http.Handler {
 	router := chi.NewRouter()
 	router.Use(middleware.RequestID)
 	router.Use(middleware.RealIP)
+	router.Use(a.errorLoggingMiddleware)
 	router.Use(middleware.Logger)
 	router.Use(middleware.Recoverer)
 	router.Use(middleware.Timeout(30 * time.Second))
@@ -99,6 +111,162 @@ func (a *App) Routes() http.Handler {
 	return router
 }
 
+func (a *App) Close() error {
+	if a == nil || a.errorLog == nil {
+		return nil
+	}
+
+	return a.errorLog.Close()
+}
+
+type dailyErrorLogger struct {
+	dir    string
+	mu     sync.Mutex
+	date   string
+	file   *os.File
+	logger *log.Logger
+}
+
+const maxLoggedResponseBodyBytes = 2048
+
+func newDailyErrorLogger(dir string) (*dailyErrorLogger, error) {
+	l := &dailyErrorLogger{dir: dir}
+	if err := l.rotateIfNeeded(time.Now()); err != nil {
+		return nil, err
+	}
+
+	return l, nil
+}
+
+func (l *dailyErrorLogger) rotateIfNeeded(now time.Time) error {
+	date := now.Format("2006-01-02")
+	if l.file != nil && l.date == date {
+		return nil
+	}
+
+	if err := os.MkdirAll(l.dir, 0o755); err != nil {
+		return err
+	}
+
+	path := filepath.Join(l.dir, date+".error.log")
+	file, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0o644)
+	if err != nil {
+		return err
+	}
+
+	if l.file != nil {
+		_ = l.file.Close()
+	}
+
+	l.date = date
+	l.file = file
+	l.logger = log.New(file, "", log.LstdFlags)
+	return nil
+}
+
+func (l *dailyErrorLogger) LogRequest(r *http.Request, status int, duration time.Duration, responseBody string) {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	now := time.Now()
+	if err := l.rotateIfNeeded(now); err != nil {
+		log.Printf("error log rotation failed: %v", err)
+		return
+	}
+
+	l.logger.Printf(
+		`status=%d method=%s path=%q query=%q ip=%q request_id=%q duration=%s content_type=%q content_length=%d user_agent=%q response_body=%q`,
+		status,
+		r.Method,
+		r.URL.Path,
+		r.URL.RawQuery,
+		r.RemoteAddr,
+		middleware.GetReqID(r.Context()),
+		duration,
+		r.Header.Get("Content-Type"),
+		r.ContentLength,
+		r.UserAgent(),
+		responseBody,
+	)
+}
+
+func (l *dailyErrorLogger) Close() error {
+	l.mu.Lock()
+	defer l.mu.Unlock()
+
+	if l.file == nil {
+		return nil
+	}
+
+	err := l.file.Close()
+	l.file = nil
+	l.logger = nil
+	l.date = ""
+	return err
+}
+
+type statusCapturingResponseWriter struct {
+	http.ResponseWriter
+	status        int
+	body          strings.Builder
+	bodyTruncated bool
+}
+
+func (w *statusCapturingResponseWriter) WriteHeader(status int) {
+	w.status = status
+	w.ResponseWriter.WriteHeader(status)
+}
+
+func (w *statusCapturingResponseWriter) Write(b []byte) (int, error) {
+	if w.status == 0 {
+		w.status = http.StatusOK
+	}
+
+	if w.body.Len() < maxLoggedResponseBodyBytes {
+		remaining := maxLoggedResponseBodyBytes - w.body.Len()
+		if len(b) > remaining {
+			_, _ = w.body.Write(b[:remaining])
+			w.bodyTruncated = true
+		} else {
+			_, _ = w.body.Write(b)
+		}
+	} else {
+		w.bodyTruncated = true
+	}
+
+	return w.ResponseWriter.Write(b)
+}
+
+func (w *statusCapturingResponseWriter) LoggedBody() string {
+	body := strings.TrimSpace(w.body.String())
+	if body == "" {
+		return ""
+	}
+
+	if w.bodyTruncated {
+		return body + "... [truncated]"
+	}
+
+	return body
+}
+
+func (a *App) errorLoggingMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		startedAt := time.Now()
+		ww := &statusCapturingResponseWriter{ResponseWriter: w}
+		next.ServeHTTP(ww, r)
+
+		status := ww.status
+		if status == 0 {
+			status = http.StatusOK
+		}
+
+		if status >= http.StatusBadRequest {
+			a.errorLog.LogRequest(r, status, time.Since(startedAt), ww.LoggedBody())
+		}
+	})
+}
+
 func (a *App) handleIndex(w http.ResponseWriter, r *http.Request) {
 	page := parsePositiveInt(r.URL.Query().Get("page"), 1)
 	text := strings.TrimSpace(r.URL.Query().Get("text"))
@@ -244,10 +412,24 @@ func parseJSONSubmission(r *http.Request) (model.BenchmarkResult, string, string
 	if err := json.Unmarshal(body, &nested); err == nil {
 		submitter = firstNonEmpty(nested.Submitter, submitter)
 		platform = firstNonEmpty(nested.Platform, platform)
-		for _, candidate := range []*model.BenchmarkResult{nested.Benchmark, nested.Result, nested.Data} {
+		for _, candidate := range []struct {
-			if candidate != nil {
+			name    string
-				return *candidate, submitter, platform, nil
+			payload json.RawMessage
+		}{
+			{name: "benchmark", payload: nested.Benchmark},
+			{name: "result", payload: nested.Result},
+			{name: "data", payload: nested.Data},
+		} {
+			if len(candidate.payload) == 0 || string(candidate.payload) == "null" {
+				continue
 			}
+
+			var result model.BenchmarkResult
+			if err := json.Unmarshal(candidate.payload, &result); err != nil {
+				return model.BenchmarkResult{}, "", "", fmt.Errorf("decode %s JSON: %w", candidate.name, err)
+			}
+
+			return result, submitter, platform, nil
 		}
 	}
 

main.go

@@ -29,6 +29,9 @@ func run(logger *log.Logger) error {
 	if err := os.MkdirAll(cfg.BadgerDir, 0o755); err != nil {
 		return err
 	}
+	if err := os.MkdirAll("data/logs", 0o755); err != nil {
+		return err
+	}
 
 	benchmarkStore, err := store.Open(cfg.BadgerDir)
 	if err != nil {
@@ -43,10 +46,15 @@ func run(logger *log.Logger) error {
 	}
 	defer closeOnce.Do(closeStore)
 
-	app, err := web.New(benchmarkStore, cfg.PageSize)
+	app, err := web.New(benchmarkStore, cfg.PageSize, "data/logs")
 	if err != nil {
 		return err
 	}
+	defer func() {
+		if err := app.Close(); err != nil {
+			logger.Printf("close error log: %v", err)
+		}
+	}()
 
 	server := &http.Server{
 		Addr:              cfg.Addr,