Skip to content

Commit 4a1952e

Browse files
EvanNotFoundEvanNotFound
committed
feat(api): add structured request and event logging
- replace custom logger with `slog` text/json handlers and stable fields - log request IDs, matched routes, status, and duration for all requests - normalize API, counter, Busuanzi, and health events with tests
1 parent 6c10413 commit 4a1952e

9 files changed

Lines changed: 295 additions & 69 deletions

File tree

‎apps/api/internal/api/log.go‎

Lines changed: 50 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,8 @@ import (
1313
"time"
1414

1515
"github.com/EvanNotFound/vercount/apps/api/internal/counter"
16+
"github.com/go-chi/chi/v5"
17+
"github.com/go-chi/chi/v5/middleware"
1618
redis "github.com/redis/go-redis/v9"
1719
)
1820

@@ -102,14 +104,14 @@ func (h *LogHandler) V1Get(w http.ResponseWriter, r *http.Request) {
102104

103105
targetURL := r.URL.Query().Get("url")
104106
if targetURL == "" {
105-
h.log.Warn("GET request with missing URL parameter", nil)
107+
h.log.Warn("missing tracked url parameter", requestLogFields(r, "request.invalid", map[string]any{"status": http.StatusBadRequest, "reason": "missing_url"}))
106108
writeJSON(w, http.StatusBadRequest, map[string]string{"error": "Missing url parameter"})
107109
return
108110
}
109111

110112
target, message := validateTargetURL(targetURL)
111113
if message != "" {
112-
h.log.Warn("Invalid URL for v1 GET", map[string]any{"url": targetURL, "message": message})
114+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": targetURL, "reason": message}))
113115
writeJSON(w, http.StatusOK, map[string]any{
114116
"error": message,
115117
"site_uv": 0,
@@ -121,12 +123,12 @@ func (h *LogHandler) V1Get(w http.ResponseWriter, r *http.Request) {
121123

122124
data, err := h.readCounts(r.Context(), target.Host, target.Path)
123125
if err != nil {
124-
h.log.Error("Failed to read counts", map[string]any{"error": err.Error(), "url": targetURL})
126+
h.log.Error("counter read failed", requestLogFields(r, "counter.read_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": targetURL}))
125127
writeJSON(w, http.StatusInternalServerError, map[string]string{"error": "Internal server error"})
126128
return
127129
}
128130

129-
h.log.Info("Retrieved data for GET request", map[string]any{"host": target.Host, "path": target.Path, "site_uv": data.SiteUV, "site_pv": data.SitePV, "page_pv": data.PagePV})
131+
h.log.Debug("counter read completed", requestLogFields(r, "counter.read_completed", map[string]any{"host": target.Host, "target_path": target.Path, "site_uv": data.SiteUV, "site_pv": data.SitePV, "page_pv": data.PagePV}))
130132
writeJSON(w, http.StatusOK, data)
131133
}
132134

@@ -143,7 +145,7 @@ func (h *LogHandler) V1Post(w http.ResponseWriter, r *http.Request) {
143145

144146
target, message := validateTargetURL(data.URL)
145147
if message != "" {
146-
h.log.Warn("Invalid URL for v1 POST", map[string]any{"url": data.URL, "message": message})
148+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": data.URL, "reason": message}))
147149
writeJSON(w, http.StatusOK, map[string]any{
148150
"error": message,
149151
"site_uv": 0,
@@ -155,12 +157,12 @@ func (h *LogHandler) V1Post(w http.ResponseWriter, r *http.Request) {
155157

156158
counts, err := h.writeCounts(r.Context(), target.Host, target.Path, data.IsNewUV)
157159
if err != nil {
158-
h.log.Error("Failed to update counts", map[string]any{"error": err.Error(), "url": data.URL})
160+
h.log.Error("counter update failed", requestLogFields(r, "counter.write_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": data.URL}))
159161
writeJSON(w, http.StatusInternalServerError, map[string]string{"error": "Internal server error"})
160162
return
161163
}
162164

163-
h.log.Info("Data updated", map[string]any{"host": target.Host, "path": target.Path, "isNewUv": data.IsNewUV, "site_uv": counts.SiteUV, "site_pv": counts.SitePV, "page_pv": counts.PagePV})
165+
h.log.Debug("counter update completed", requestLogFields(r, "counter.write_completed", map[string]any{"host": target.Host, "target_path": target.Path, "is_new_uv": data.IsNewUV, "site_uv": counts.SiteUV, "site_pv": counts.SitePV, "page_pv": counts.PagePV}))
164166
writeJSON(w, http.StatusOK, counts)
165167
}
166168

@@ -172,26 +174,26 @@ func (h *LogHandler) V2Get(w http.ResponseWriter, r *http.Request) {
172174

173175
targetURL := r.URL.Query().Get("url")
174176
if targetURL == "" {
175-
h.log.Warn("GET request with missing URL parameter", nil)
177+
h.log.Warn("missing tracked url parameter", requestLogFields(r, "request.invalid", map[string]any{"status": http.StatusBadRequest, "reason": "missing_url"}))
176178
h.writeV2Error(w, http.StatusBadRequest, "Missing url parameter", nil)
177179
return
178180
}
179181

180182
target, message := validateTargetURL(targetURL)
181183
if message != "" {
182-
h.log.Warn("Invalid URL for v2 GET", map[string]any{"url": targetURL, "message": message})
184+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": targetURL, "reason": message}))
183185
h.writeV2Success(w, http.StatusOK, message, zeroCounters())
184186
return
185187
}
186188

187189
data, err := h.readCounts(r.Context(), target.Host, target.Path)
188190
if err != nil {
189-
h.log.Error("Failed to read counts", map[string]any{"error": err.Error(), "url": targetURL})
191+
h.log.Error("counter read failed", requestLogFields(r, "counter.read_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": targetURL}))
190192
h.writeV2Error(w, http.StatusInternalServerError, "Internal server error", nil)
191193
return
192194
}
193195

194-
h.log.Info("Retrieved data for GET request", map[string]any{"host": target.Host, "path": target.Path, "site_uv": data.SiteUV, "site_pv": data.SitePV, "page_pv": data.PagePV})
196+
h.log.Debug("counter read completed", requestLogFields(r, "counter.read_completed", map[string]any{"host": target.Host, "target_path": target.Path, "site_uv": data.SiteUV, "site_pv": data.SitePV, "page_pv": data.PagePV}))
195197
h.writeV2Success(w, http.StatusOK, "Data retrieved successfully", data)
196198
}
197199

@@ -208,19 +210,19 @@ func (h *LogHandler) V2Post(w http.ResponseWriter, r *http.Request) {
208210

209211
target, message := validateTargetURL(data.URL)
210212
if message != "" {
211-
h.log.Warn("Invalid URL for v2 POST", map[string]any{"url": data.URL, "message": message})
213+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": data.URL, "reason": message}))
212214
h.writeV2Success(w, http.StatusOK, message, zeroCounters())
213215
return
214216
}
215217

216218
counts, err := h.writeCounts(r.Context(), target.Host, target.Path, data.IsNewUV)
217219
if err != nil {
218-
h.log.Error("Failed to update counts", map[string]any{"error": err.Error(), "url": data.URL})
220+
h.log.Error("counter update failed", requestLogFields(r, "counter.write_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": data.URL}))
219221
h.writeV2Error(w, http.StatusInternalServerError, "Internal server error", nil)
220222
return
221223
}
222224

223-
h.log.Info("Data updated", map[string]any{"host": target.Host, "path": target.Path, "isNewUv": data.IsNewUV, "site_uv": counts.SiteUV, "site_pv": counts.SitePV, "page_pv": counts.PagePV})
225+
h.log.Debug("counter update completed", requestLogFields(r, "counter.write_completed", map[string]any{"host": target.Host, "target_path": target.Path, "is_new_uv": data.IsNewUV, "site_uv": counts.SiteUV, "site_pv": counts.SitePV, "page_pv": counts.PagePV}))
224226
h.writeV2Success(w, http.StatusOK, "Data updated successfully", counts)
225227
}
226228

@@ -250,6 +252,7 @@ func (h *LogHandler) allowV2Request(w http.ResponseWriter, r *http.Request) bool
250252
func (h *LogHandler) decodeCountRequest(w http.ResponseWriter, r *http.Request, v2 bool) (countRequest, bool) {
251253
var data countRequest
252254
if err := json.NewDecoder(r.Body).Decode(&data); err != nil {
255+
h.log.Warn("invalid JSON request body", requestLogFields(r, "request.invalid", map[string]any{"status": http.StatusBadRequest, "reason": "invalid_json", "error": err.Error()}))
253256
if v2 {
254257
h.writeV2Error(w, http.StatusBadRequest, "Invalid JSON body", nil)
255258
} else {
@@ -259,6 +262,7 @@ func (h *LogHandler) decodeCountRequest(w http.ResponseWriter, r *http.Request,
259262
}
260263

261264
if data.URL == "" {
265+
h.log.Warn("missing tracked url parameter", requestLogFields(r, "request.invalid", map[string]any{"status": http.StatusBadRequest, "reason": "missing_url"}))
262266
if v2 {
263267
h.writeV2Error(w, http.StatusBadRequest, "Missing url", nil)
264268
} else {
@@ -367,18 +371,18 @@ func (l *rateLimiter) Check(ctx context.Context, r *http.Request) rateLimitResul
367371
return nil
368372
})
369373
if err != nil {
370-
l.log.Warn("Rate limit cleanup failed", map[string]any{"ip": ip, "error": err.Error()})
374+
l.log.Warn("rate limit cleanup failed", requestLogFields(r, "rate_limit.cleanup_failed", map[string]any{"ip": ip, "ua": ua, "error": err.Error()}))
371375
return rateLimitResult{Success: true, Limit: rateLimitCount, Remaining: rateLimitCount, Reset: reset}
372376
}
373377

374378
count, err := countCmd.Result()
375379
if err != nil {
376-
l.log.Warn("Rate limit count failed", map[string]any{"ip": ip, "error": err.Error()})
380+
l.log.Warn("rate limit count failed", requestLogFields(r, "rate_limit.count_failed", map[string]any{"ip": ip, "ua": ua, "error": err.Error()}))
377381
return rateLimitResult{Success: true, Limit: rateLimitCount, Remaining: rateLimitCount, Reset: reset}
378382
}
379383

380384
if count >= rateLimitCount {
381-
l.log.Warn("Rate limit exceeded", map[string]any{"ip": ip, "ua": ua, "limit": rateLimitCount, "remaining": 0})
385+
l.log.Warn("rate limit exceeded", requestLogFields(r, "rate_limit.exceeded", map[string]any{"ip": ip, "ua": ua, "limit": rateLimitCount, "remaining": 0, "status": http.StatusTooManyRequests}))
382386
return rateLimitResult{
383387
Success: false,
384388
Limit: rateLimitCount,
@@ -395,19 +399,18 @@ func (l *rateLimiter) Check(ctx context.Context, r *http.Request) rateLimitResul
395399
return nil
396400
})
397401
if err != nil {
398-
l.log.Warn("Rate limit add failed", map[string]any{"ip": ip, "error": err.Error()})
402+
l.log.Warn("rate limit state update failed", requestLogFields(r, "rate_limit.persist_failed", map[string]any{"ip": ip, "ua": ua, "error": err.Error()}))
399403
return rateLimitResult{Success: true, Limit: rateLimitCount, Remaining: rateLimitCount, Reset: reset}
400404
}
401405

402406
remaining := rateLimitCount - (count + 1)
403-
l.log.Info("Request received", map[string]any{"ip": ip, "ua": ua, "path": r.URL.Path, "timestamp": now.UnixMilli()})
404407

405408
if suspiciousUA.MatchString(ua) {
406-
l.log.Warn("Suspicious user agent detected", map[string]any{"ip": ip, "ua": ua})
409+
l.log.Warn("suspicious user agent detected", requestLogFields(r, "security.suspicious_user_agent", map[string]any{"ip": ip, "ua": ua}))
407410
}
408411

409412
if remaining < 20 {
410-
l.log.Warn("Approaching rate limit", map[string]any{"ip": ip, "ua": ua, "remaining": remaining})
413+
l.log.Warn("request is nearing rate limit", requestLogFields(r, "rate_limit.near_limit", map[string]any{"ip": ip, "ua": ua, "remaining": remaining, "limit": rateLimitCount}))
411414
}
412415

413416
return rateLimitResult{Success: true, Limit: rateLimitCount, Remaining: remaining, Reset: reset}
@@ -436,3 +439,29 @@ func clientIP(r *http.Request) string {
436439

437440
return "127.0.0.1"
438441
}
442+
443+
func requestLogFields(r *http.Request, event string, fields map[string]any) map[string]any {
444+
out := map[string]any{
445+
"event": event,
446+
"request_id": middleware.GetReqID(r.Context()),
447+
"method": r.Method,
448+
"route": routePattern(r),
449+
"path": r.URL.Path,
450+
}
451+
452+
for key, value := range fields {
453+
out[key] = value
454+
}
455+
456+
return out
457+
}
458+
459+
func routePattern(r *http.Request) string {
460+
if routeContext := chi.RouteContext(r.Context()); routeContext != nil {
461+
if pattern := routeContext.RoutePattern(); pattern != "" {
462+
return pattern
463+
}
464+
}
465+
466+
return r.URL.Path
467+
}

‎apps/api/internal/api/public.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -50,7 +50,7 @@ func (h *PublicHandler) Healthz(w http.ResponseWriter, r *http.Request) {
5050
defer cancel()
5151

5252
if err := h.redis.Ping(ctx).Err(); err != nil {
53-
h.log.Warn("Redis readiness check failed", map[string]any{"error": err.Error()})
53+
h.log.Warn("redis readiness check failed", map[string]any{"event": "healthz.redis_unreachable", "error": err.Error()})
5454
writeJSON(w, http.StatusServiceUnavailable, map[string]any{
5555
"service": publicServiceName,
5656
"status": "not_ready",
@@ -78,7 +78,7 @@ func (h *PublicHandler) Script(w http.ResponseWriter, r *http.Request) {
7878

7979
fullPath := filepath.Clean(h.scriptPath)
8080
if _, err := os.Stat(fullPath); err != nil {
81-
h.log.Error("Script file not found", map[string]any{"path": fullPath, "error": err.Error()})
81+
h.log.Error("script file not found", map[string]any{"event": "script.not_found", "path": fullPath, "error": err.Error()})
8282
http.NotFound(w, r)
8383
return
8484
}

‎apps/api/internal/app/runtime.go‎

Lines changed: 104 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,12 @@
11
package app
22

33
import (
4-
"encoding/json"
54
"fmt"
6-
"log"
5+
"io"
6+
"log/slog"
77
"os"
8+
"sort"
89
"strings"
9-
"time"
1010
)
1111

1212
const (
@@ -96,45 +96,130 @@ func resolveScriptPath() string {
9696

9797
type Logger struct {
9898
debug bool
99+
inner *slog.Logger
99100
}
100101

101102
func NewLogger(debug bool) *Logger {
102-
log.SetOutput(os.Stdout)
103-
log.SetFlags(0)
104-
return &Logger{debug: debug}
103+
return newLogger(debug, os.Stdout)
104+
}
105+
106+
func newLogger(debug bool, writer io.Writer) *Logger {
107+
if writer == nil {
108+
writer = os.Stdout
109+
}
110+
111+
options := &slog.HandlerOptions{
112+
Level: slog.LevelInfo,
113+
ReplaceAttr: func(_ []string, attr slog.Attr) slog.Attr {
114+
if attr.Key == slog.LevelKey {
115+
if level, ok := attr.Value.Any().(slog.Level); ok {
116+
attr.Value = slog.StringValue(strings.ToLower(level.String()))
117+
}
118+
}
119+
return attr
120+
},
121+
}
122+
if debug {
123+
options.Level = slog.LevelDebug
124+
}
125+
126+
var handler slog.Handler
127+
if debug {
128+
handler = slog.NewTextHandler(writer, options)
129+
} else {
130+
handler = slog.NewJSONHandler(writer, options)
131+
}
132+
133+
env := "production"
134+
if debug {
135+
env = "development"
136+
}
137+
138+
return &Logger{
139+
debug: debug,
140+
inner: slog.New(handler).With("service", "api", "env", env),
141+
}
105142
}
106143

107144
func (l *Logger) Debug(message string, data any) {
108145
if !l.debug {
109146
return
110147
}
111-
l.print("DEBUG", message, data)
148+
l.log(slog.LevelDebug, message, data)
112149
}
113150

114151
func (l *Logger) Info(message string, data any) {
115-
l.print("INFO", message, data)
152+
l.log(slog.LevelInfo, message, data)
116153
}
117154

118155
func (l *Logger) Warn(message string, data any) {
119-
l.print("WARN", message, data)
156+
l.log(slog.LevelWarn, message, data)
120157
}
121158

122159
func (l *Logger) Error(message string, data any) {
123-
l.print("ERROR", message, data)
160+
l.log(slog.LevelError, message, data)
124161
}
125162

126-
func (l *Logger) print(level string, message string, data any) {
127-
prefix := fmt.Sprintf("[%s] %s: %s", time.Now().UTC().Format(time.RFC3339), level, message)
128-
if data == nil {
129-
log.Print(prefix)
163+
func (l *Logger) log(level slog.Level, message string, data any) {
164+
if l == nil || l.inner == nil {
130165
return
131166
}
132167

133-
encoded, err := json.Marshal(data)
134-
if err != nil {
135-
log.Printf("%s %v", prefix, data)
136-
return
168+
args := slogArgs(data)
169+
switch level {
170+
case slog.LevelDebug:
171+
l.inner.Debug(message, args...)
172+
case slog.LevelWarn:
173+
l.inner.Warn(message, args...)
174+
case slog.LevelError:
175+
l.inner.Error(message, args...)
176+
default:
177+
l.inner.Info(message, args...)
178+
}
179+
}
180+
181+
func slogArgs(data any) []any {
182+
switch value := data.(type) {
183+
case nil:
184+
return nil
185+
case error:
186+
return []any{"error", value.Error()}
187+
case map[string]any:
188+
keys := make([]string, 0, len(value))
189+
for key := range value {
190+
keys = append(keys, key)
191+
}
192+
sort.Strings(keys)
193+
194+
args := make([]any, 0, len(value)*2)
195+
for _, key := range keys {
196+
args = append(args, key, sanitizeLogValue(value[key]))
197+
}
198+
return args
199+
default:
200+
return []any{"data", sanitizeLogValue(value)}
137201
}
202+
}
138203

139-
log.Printf("%s %s", prefix, string(encoded))
204+
func sanitizeLogValue(value any) any {
205+
switch typed := value.(type) {
206+
case nil:
207+
return nil
208+
case error:
209+
return typed.Error()
210+
case map[string]any:
211+
cleaned := make(map[string]any, len(typed))
212+
for key, nested := range typed {
213+
cleaned[key] = sanitizeLogValue(nested)
214+
}
215+
return cleaned
216+
case []any:
217+
cleaned := make([]any, len(typed))
218+
for index, nested := range typed {
219+
cleaned[index] = sanitizeLogValue(nested)
220+
}
221+
return cleaned
222+
default:
223+
return typed
224+
}
140225
}

0 commit comments

Comments
 (0)