feat(observability): request log middleware + in-memory metrics

Phase 11 partial of the go-port-cloud-run plan. Code-side
observability hooks ready ahead of Phase 01 GCP rollout.

- internal/server/log_middleware.go: HTTP middleware that wraps the
  router and emits {msg:"req", method, path, status, ms} per
  request. statusRecorder defaults to 200 when the inner handler
  doesn't call WriteHeader (Go writes 200 implicitly on first body
  write). Wired into server.New so /, /webhook, /cron/* all log.
- internal/metrics/counters.go: in-memory Registry with
  IncCommand/IncError/IncAI. Atomic Int64 per name + RWMutex on the
  map; steady-state increments are mutex-free. Periodic Run flushes
  via the project logger every 60s and one final flush on ctx done.
  Empty flush is silent (no-noise default).
- Dispatcher instrumented: every command invocation calls
  metrics.IncCommand; every handler error calls
  metrics.IncError("handler-error"). Logger keeps the full error
  detail; counters keep the rate.
- cmd/server/main.go: go metrics.Run(rootCtx) so the flush loop
  cancels with SIGTERM and emits the trailing window before exit.

Test coverage: 12 new tests (7 metrics, 3 middleware, 2 default-
registry round-trip). go test -race -count=1 ./... clean
(20 packages); golangci-lint clean.

Soak / cold-start measurement / log-based metrics setup deferred to
post-deployment (Phase 01 prerequisite).

internal/server/log_middleware.go

@@ -0,0 +1,52 @@
+package server
+
+import (
+	"net/http"
+	"time"
+
+	"github.com/tiennm99/miti99bot-go/internal/log"
+)
+
+// statusRecorder wraps http.ResponseWriter to capture the final status
+// code. http.ResponseWriter doesn't expose what was written; the middleware
+// needs the status to log a per-request `req` line.
+type statusRecorder struct {
+	http.ResponseWriter
+	status int
+}
+
+func (r *statusRecorder) WriteHeader(code int) {
+	r.status = code
+	r.ResponseWriter.WriteHeader(code)
+}
+
+// status returns the recorded status code, defaulting to 200 when no
+// explicit WriteHeader was called (Go's net/http implicitly writes 200 on
+// the first body write).
+func (r *statusRecorder) effectiveStatus() int {
+	if r.status == 0 {
+		return http.StatusOK
+	}
+	return r.status
+}
+
+// LogRequests wraps an http.Handler with a request log line:
+//
+//	{"msg":"req","method":"POST","path":"/webhook","status":200,"ms":12}
+//
+// Cloud Logging filters on `jsonPayload.msg=req AND jsonPayload.status>=500`
+// for 5xx-rate alerting. Mirrors the JS source's index.js shape so existing
+// dashboards keep working post-cutover.
+func LogRequests(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		start := time.Now()
+		rec := &statusRecorder{ResponseWriter: w}
+		next.ServeHTTP(rec, r)
+		log.Info("req",
+			"method", r.Method,
+			"path", r.URL.Path,
+			"status", rec.effectiveStatus(),
+			"ms", time.Since(start).Milliseconds(),
+		)
+	})
+}

internal/server/log_middleware_test.go

@@ -0,0 +1,103 @@
+package server
+
+import (
+	"bytes"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"strings"
+	"testing"
+
+	logger "github.com/tiennm99/miti99bot-go/internal/log"
+)
+
+// captureLogger swaps the package-level logger for one writing to buf and
+// returns a restore func. Tests must defer the restore.
+func captureLogger(t *testing.T) (*bytes.Buffer, func()) {
+	t.Helper()
+	prev := logger.Default()
+	buf := &bytes.Buffer{}
+	logger.SetDefault(slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelInfo})))
+	return buf, func() { logger.SetDefault(prev) }
+}
+
+func decodeReqLine(t *testing.T, buf *bytes.Buffer) map[string]any {
+	t.Helper()
+	lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
+	for _, line := range lines {
+		var rec map[string]any
+		if err := json.Unmarshal([]byte(line), &rec); err != nil {
+			continue
+		}
+		if rec["msg"] == "req" {
+			return rec
+		}
+	}
+	t.Fatalf("no req line found in:\n%s", buf.String())
+	return nil
+}
+
+func TestLogRequests_LogsMethodPathStatus(t *testing.T) {
+	buf, restore := captureLogger(t)
+	defer restore()
+
+	inner := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		w.WriteHeader(http.StatusCreated)
+	})
+	rec := httptest.NewRecorder()
+	LogRequests(inner).ServeHTTP(rec, httptest.NewRequest(http.MethodPost, "/webhook", nil))
+
+	got := decodeReqLine(t, buf)
+	if got["method"] != "POST" {
+		t.Errorf("method = %v, want POST", got["method"])
+	}
+	if got["path"] != "/webhook" {
+		t.Errorf("path = %v, want /webhook", got["path"])
+	}
+	if got["status"].(float64) != float64(http.StatusCreated) {
+		t.Errorf("status = %v, want 201", got["status"])
+	}
+	if _, ok := got["ms"]; !ok {
+		t.Errorf("missing ms field")
+	}
+}
+
+func TestLogRequests_DefaultStatus200WhenNotSet(t *testing.T) {
+	buf, restore := captureLogger(t)
+	defer restore()
+
+	// Inner handler writes a body but never calls WriteHeader explicitly.
+	inner := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		_, _ = w.Write([]byte("ok"))
+	})
+	rec := httptest.NewRecorder()
+	LogRequests(inner).ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/", nil))
+
+	got := decodeReqLine(t, buf)
+	// Even though our recorder didn't see WriteHeader, our middleware
+	// should report 200 — Go's net/http implicitly writes 200 on first
+	// body write.
+	if got["status"].(float64) != float64(http.StatusOK) {
+		t.Errorf("status = %v, want 200 (implicit)", got["status"])
+	}
+}
+
+func TestLogRequests_PreservesInnerBehavior(t *testing.T) {
+	_, restore := captureLogger(t)
+	defer restore()
+
+	inner := http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
+		w.WriteHeader(http.StatusTeapot)
+		_, _ = w.Write([]byte("brewing"))
+	})
+	rec := httptest.NewRecorder()
+	LogRequests(inner).ServeHTTP(rec, httptest.NewRequest(http.MethodGet, "/", nil))
+
+	if rec.Code != http.StatusTeapot {
+		t.Errorf("status code = %d, want 418", rec.Code)
+	}
+	if rec.Body.String() != "brewing" {
+		t.Errorf("body = %q, want 'brewing'", rec.Body.String())
+	}
+}

internal/server/router.go

@@ -41,13 +41,15 @@ type Config struct {
 //	POST /webhook           → Telegram update intake (constant-time secret check)
 //	POST /cron/{name}       → Cloud Scheduler entry (shared-secret check; OIDC in Phase 09)
 //
-// Anything else is 404.
+// Anything else is 404. All routes pass through LogRequests so every
+// request emits a structured `req` log line (Cloud Logging consumes them
+// for 5xx-rate alerts and per-route latency).
 func New(cfg Config) http.Handler {
 	mux := http.NewServeMux()
 	mux.Handle("/", HealthHandler())
 	mux.Handle("/webhook", telegram.WebhookHandler(cfg.Bot, cfg.WebhookSecret))
 	mux.Handle("/cron/", cronHandler(cfg.Registry, cfg.CronSecret))
-	return mux
+	return LogRequests(mux)
 }
 
 func cronHandler(reg *modules.Registry, secret string) http.HandlerFunc {