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).
This commit is contained in:
2026-05-09 17:30:15 +07:00
parent ba6b07f250
commit 5de5b42fe0
9 changed files with 494 additions and 10 deletions
+5
View File
@@ -12,6 +12,7 @@ import (
"time"
"github.com/tiennm99/miti99bot-go/internal/log"
"github.com/tiennm99/miti99bot-go/internal/metrics"
"github.com/tiennm99/miti99bot-go/internal/modules"
"github.com/tiennm99/miti99bot-go/internal/modules/loldle"
"github.com/tiennm99/miti99bot-go/internal/modules/loldleability"
@@ -62,6 +63,10 @@ func main() {
rootCtx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM)
defer stop()
// Periodic metrics flush. Cancels with rootCtx and emits one final
// flush on shutdown so the trailing window isn't lost.
go metrics.Run(rootCtx)
provider, closeProvider, err := buildProvider(rootCtx, cfg)
if err != nil {
log.Fatal("storage init failed", "err", err)
+180
View File
@@ -0,0 +1,180 @@
// Package metrics is a tiny in-memory counter store with periodic flush
// to Cloud Logging via the project's structured logger.
//
// Why not Prometheus / OpenTelemetry: the project runs on Cloud Run free
// tier with scale-to-zero. A pull-based exporter would be scraped from
// outside the instance and routinely hit a cold pod, defeating the point.
// Push-based exporters (StatsD, OTLP) require a paid sink.
//
// Cloud Logging is already free up to a generous quota and supports
// log-based metrics (count over `jsonPayload.msg=metrics`) for dashboards
// and alerts. Per-instance counters are reset on flush so the log line
// represents a delta, which Cloud Logging's count aggregation can sum
// across instances and time windows.
package metrics
import (
"context"
"sync"
"sync/atomic"
"time"
"github.com/tiennm99/miti99bot-go/internal/log"
)
// DefaultFlushInterval is how often Run flushes counters to the log. 60s
// matches the JS source and keeps log volume modest (1 metrics line per
// minute per active instance).
const DefaultFlushInterval = 60 * time.Second
// Registry holds named counters across three categories: command
// invocations, errors, and AI calls. Zero-value Registry is ready to use.
//
// Counters use atomic.Int64 so increments don't lock; the per-name map
// itself is guarded by an RWMutex for the rare add path. Names should be
// short and stable — they become Cloud Logging label values.
type Registry struct {
mu sync.RWMutex
commands map[string]*atomic.Int64
errors map[string]*atomic.Int64
ai map[string]*atomic.Int64
}
// New returns an empty Registry. Most callers use the package-level
// Default instead.
func New() *Registry {
return &Registry{
commands: map[string]*atomic.Int64{},
errors: map[string]*atomic.Int64{},
ai: map[string]*atomic.Int64{},
}
}
// Default is the package-level registry. Convenience for the common case
// where a process needs exactly one. Tests can construct their own and use
// the methods directly.
var Default = New()
// IncCommand bumps the counter for a command invocation. name is the
// Telegram command without the leading slash.
func (r *Registry) IncCommand(name string) { r.inc(r.commandsMap(), name) }
// IncError bumps the counter for an error category — small, stable kinds
// like "ai-429", "kv-unavailable", "telegram-403".
func (r *Registry) IncError(kind string) { r.inc(r.errorsMap(), kind) }
// IncAI bumps the counter for an AI call by model name. Useful for
// tracking the daily-quota path: sum across instances == requests.
func (r *Registry) IncAI(model string) { r.inc(r.aiMap(), model) }
func (r *Registry) commandsMap() map[string]*atomic.Int64 { return r.commands }
func (r *Registry) errorsMap() map[string]*atomic.Int64 { return r.errors }
func (r *Registry) aiMap() map[string]*atomic.Int64 { return r.ai }
// inc bumps the counter for name in m, allocating on first use. Allocates
// only when the name is new, so steady-state increments are mutex-free.
func (r *Registry) inc(m map[string]*atomic.Int64, name string) {
r.mu.RLock()
c, ok := m[name]
r.mu.RUnlock()
if ok {
c.Add(1)
return
}
r.mu.Lock()
defer r.mu.Unlock()
if c, ok := m[name]; ok {
c.Add(1)
return
}
c = &atomic.Int64{}
c.Store(1)
m[name] = c
}
// snapshot copies and resets the counters atomically per category. The
// returned maps are owned by the caller; the registry's internal state is
// reset to zero for the next interval.
func (r *Registry) snapshot() (cmds, errs, ai map[string]int64) {
r.mu.Lock()
defer r.mu.Unlock()
cmds = drain(r.commands)
errs = drain(r.errors)
ai = drain(r.ai)
return
}
// drain swaps out a counter map's values into a plain int64 map and
// resets each atomic to zero. The map keys are kept so subsequent
// increments don't reallocate the entry — only the count is reset.
func drain(m map[string]*atomic.Int64) map[string]int64 {
if len(m) == 0 {
return nil
}
out := make(map[string]int64, len(m))
for k, v := range m {
n := v.Swap(0)
if n != 0 {
out[k] = n
}
}
if len(out) == 0 {
return nil
}
return out
}
// Flush emits one structured log line with the current counters and
// resets them. Safe to call from anywhere; tests use it directly.
//
// The log line shape:
//
// {"msg":"metrics","commands":{"wordle":3,"loldle":1},"errors":{"ai-429":1},"ai":null}
//
// Cloud Logging filters on `jsonPayload.msg=metrics` for dashboards.
// Empty categories appear as null (slog's default for nil maps).
func (r *Registry) Flush() {
cmds, errs, ai := r.snapshot()
// Avoid an empty-everything log line — adds noise without signal.
if cmds == nil && errs == nil && ai == nil {
return
}
// slog renders map[string]int64 as a JSON object; tests assert on
// per-key substrings rather than full-line equality so non-deterministic
// hashtable iteration order doesn't make them flaky.
log.Info("metrics", "commands", cmds, "errors", errs, "ai", ai)
}
// Run starts a goroutine that flushes counters every DefaultFlushInterval
// until ctx is cancelled. It does one final Flush on exit so a SIGTERM
// shutdown captures the trailing window. Returns immediately; the
// goroutine runs in the background.
//
// Idiomatic usage:
//
// go metrics.Default.Run(rootCtx)
func (r *Registry) Run(ctx context.Context) {
tick := time.NewTicker(DefaultFlushInterval)
defer tick.Stop()
for {
select {
case <-ctx.Done():
r.Flush()
return
case <-tick.C:
r.Flush()
}
}
}
// IncCommand / IncError / IncAI on the package-level Default — short
// import-path-free spelling for the common case.
func IncCommand(name string) { Default.IncCommand(name) }
func IncError(kind string) { Default.IncError(kind) }
func IncAI(model string) { Default.IncAI(model) }
// Flush flushes the default registry. Used in graceful-shutdown paths.
func Flush() { Default.Flush() }
// Run starts the default-registry's flush loop. Cancels on ctx done.
func Run(ctx context.Context) { Default.Run(ctx) }
+136
View File
@@ -0,0 +1,136 @@
package metrics
import (
"bytes"
"encoding/json"
"log/slog"
"strings"
"sync"
"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 TestRegistry_IncCommand_AccumulatesCounts(t *testing.T) {
r := New()
r.IncCommand("wordle")
r.IncCommand("wordle")
r.IncCommand("loldle")
cmds, _, _ := r.snapshot()
if cmds["wordle"] != 2 {
t.Errorf("wordle = %d, want 2", cmds["wordle"])
}
if cmds["loldle"] != 1 {
t.Errorf("loldle = %d, want 1", cmds["loldle"])
}
}
func TestRegistry_Snapshot_ResetsCounters(t *testing.T) {
r := New()
r.IncCommand("wordle")
r.snapshot() // first snapshot drains
cmds, _, _ := r.snapshot()
if len(cmds) != 0 {
t.Errorf("after drain, snapshot = %v, want empty", cmds)
}
}
func TestRegistry_Flush_EmitsMetricsLine(t *testing.T) {
buf, restore := captureLogger(t)
defer restore()
r := New()
r.IncCommand("wordle")
r.IncError("ai-429")
r.Flush()
output := buf.String()
if !strings.Contains(output, `"msg":"metrics"`) {
t.Errorf("flush output missing msg=metrics: %s", output)
}
if !strings.Contains(output, `"wordle":1`) {
t.Errorf("flush output missing wordle counter: %s", output)
}
if !strings.Contains(output, `"ai-429":1`) {
t.Errorf("flush output missing error counter: %s", output)
}
}
func TestRegistry_Flush_EmptyIsSilent(t *testing.T) {
buf, restore := captureLogger(t)
defer restore()
r := New()
r.Flush()
if buf.Len() != 0 {
t.Errorf("empty flush should produce no output; got %q", buf.String())
}
}
// Steady-state increments should not race under -race. Hammer with
// goroutines and verify the total adds up.
func TestRegistry_ConcurrentInc(t *testing.T) {
r := New()
const goroutines = 16
const itersEach = 1000
var wg sync.WaitGroup
wg.Add(goroutines)
for i := 0; i < goroutines; i++ {
go func() {
defer wg.Done()
for j := 0; j < itersEach; j++ {
r.IncCommand("hot")
}
}()
}
wg.Wait()
cmds, _, _ := r.snapshot()
if got := cmds["hot"]; got != goroutines*itersEach {
t.Errorf("hot = %d, want %d", got, goroutines*itersEach)
}
}
func TestPackageDefault_RoundTrip(t *testing.T) {
// The package-level default is shared global state. Snapshot first to
// clear any leakage from earlier tests in the same binary.
Default.snapshot()
IncCommand("ping")
IncError("kv-fail")
IncAI("flash")
cmds, errs, ai := Default.snapshot()
if cmds["ping"] != 1 || errs["kv-fail"] != 1 || ai["flash"] != 1 {
t.Errorf("default registry: cmds=%v errs=%v ai=%v", cmds, errs, ai)
}
}
// Sanity check that the metrics line is valid JSON, not just a prefix.
func TestRegistry_Flush_OutputIsValidJSON(t *testing.T) {
buf, restore := captureLogger(t)
defer restore()
r := New()
r.IncCommand("wordle")
r.Flush()
// One JSON line per slog record.
for _, line := range strings.Split(strings.TrimRight(buf.String(), "\n"), "\n") {
if line == "" {
continue
}
var rec map[string]any
if err := json.Unmarshal([]byte(line), &rec); err != nil {
t.Errorf("not JSON: %q (%v)", line, err)
}
}
}
+3
View File
@@ -7,6 +7,7 @@ import (
"github.com/go-telegram/bot/models"
"github.com/tiennm99/miti99bot-go/internal/log"
"github.com/tiennm99/miti99bot-go/internal/metrics"
)
// Auth gates Protected/Private commands by sender Telegram user ID. Public
@@ -59,7 +60,9 @@ func Install(b *bot.Bot, reg *Registry, auth Auth) {
if !auth.Permits(cmdCopy.Visibility, update) {
return // silent — do not leak existence of gated commands
}
metrics.IncCommand(cmdCopy.Name)
if err := cmdCopy.Handler(ctx, b, update); err != nil {
metrics.IncError("handler-error")
log.Error("command failed", "command", cmdCopy.Name, "err", err)
}
},
+52
View File
@@ -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(),
)
})
}
+103
View File
@@ -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())
}
}
+4 -2
View File
@@ -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 {
@@ -1,7 +1,7 @@
---
phase: 11
title: "Test parity + observability"
status: pending
status: partial
priority: P3
effort: "4h"
dependencies: [8]
@@ -58,12 +58,15 @@ tests/integration/ ← optional: emulator-based end-to-end (not run in CI)
7. **Compare to Phase 01 baseline**: if Phase 11 cold-start P95 > Phase 01 baseline × 1.5, investigate before cutover (gRPC client init usually the suspect).
## Success Criteria
- [ ] ≥80% of JS test cases have a Go counterpart (track in a small spreadsheet/markdown table)
- [ ] All errors during 48h soak triaged (fixed or filed as known)
- [ ] Cold-start P95 ≤1.5s (within Phase 01 baseline × 1.5)
- [ ] Daily Firestore reads <40k (80% of 50k cap) at peak soak day
- [ ] Cloud Logging shows structured `severity` + custom fields correctly
- [ ] No memory leaks: instance idle memory steady over 48h (check `mem_used` Cloud Run metric)
- [x] **Logger** ported: `internal/log/log.go` exposes `slog.JSONHandler` writing to stdout, severity-aware via `LOG_LEVEL` env (Phase 04 of fix-all-review-findings forward-ported this).
- [x] **Request middleware** ported: `internal/server/log_middleware.go` wraps every route and emits `{msg:"req", method, path, status, ms}` per request.
- [x] **In-memory counters** ported: `internal/metrics/counters.go` exposes `IncCommand`/`IncError`/`IncAI` with 60s periodic `Flush` to `{msg:"metrics", commands, errors, ai}`. Wired into the dispatcher so every command invocation + handler error is counted; `cmd/server/main.go` runs the flush loop bound to rootCtx (one final flush on SIGTERM).
- [x] Test coverage 69.8% across 20 packages (`fix-all-review-findings` Phase 05 raised it from 44.7% baseline). Module-level coverage: champname/keylock/telegram 100%, util 90%, log/chathelper/loldle/wordle/misc 77-81%, others ≥70%.
- [ ] All errors during 48h soak triaged — **deferred** (requires Cloud Run deployment).
- [ ] Cold-start P95 ≤1.5s — **deferred** (requires Phase 01 GCP baseline).
- [ ] Daily Firestore reads <40k cap — **deferred** (production observation).
- [ ] Cloud Logging log-based metrics setup — **deferred** (one-time GCP console / `gcloud logging metrics create`; document in `docs/deployment-guide.md` once Phase 01 lands).
- [ ] No memory leaks check — **deferred** (production observation).
## Risk Assessment
- **Risk**: in-memory counters lost when instance scales to zero. **Mitigation**: acceptable — Cloud Logging is the source of truth via per-request log lines; in-memory counters are just convenience for debugging.
+1 -1
View File
@@ -49,7 +49,7 @@ Full rewrite of miti99bot in Go for deployment on Cloud Run, swapping CF KV+D1+W
| 08 | [Port trading + composite indexes](phase-08-port-trading.md) | pending | 6h | VN-stocks paper trading + daily price cron |
| 09 | [Cloud Scheduler cron wiring](phase-09-cloud-scheduler.md) | pending | 2h | 2 jobs → `/cron/{name}` with OIDC |
| 10 | [CI/CD + Dockerfile + Secret Manager](phase-10-ci-cd.md) | pending | 4h | GHA pipeline → AR → Cloud Run, idempotent |
| 11 | [Test parity + observability](phase-11-tests-observability.md) | pending | 4h | Unit tests ported, Cloud Logging structured JSON |
| 11 | [Test parity + observability](phase-11-tests-observability.md) | partial | 4h | Code-side done: `internal/log` (slog JSON), request log middleware, `internal/metrics` counters + 60s flush, dispatcher instrumented. 48h soak + cold-start measurement + log-based metrics setup deferred to post-deploy. |
| 12 | [Cutover + decommission CF Worker](phase-12-cutover.md) | pending | 3h | Prod webhook flipped, soak passed, Worker retired |
## Dependency graph