Skip to content

Commit 07ec142

Browse files
committed
fix(api): continue accepted counter writes after client abort
- detach accepted POST writes from request cancellation with bounded timeouts - keep counter reads request-scoped and normalize tracked host/path input - log aborted transports separately and cover detached writes in tests
1 parent 544048c commit 07ec142

13 files changed

Lines changed: 567 additions & 47 deletions

File tree

apps/api/internal/api/log.go

Lines changed: 99 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,8 @@ const (
2222
rateLimitWindow = 60 * time.Second
2323
rateLimitCount = int64(80)
2424
benchmarkWriteTargetURL = "https://bench.vercount.one/gurt"
25+
readCountsTimeout = 5 * time.Second
26+
writeCountsTimeout = 5 * time.Second
2527
)
2628

2729
var suspiciousUA = regexp.MustCompile(`python-requests|python/|requests/|curl/|wget/|go-http-client/|httpie/|postman/|axios/|node-fetch/|empty|unknown|bot|crawl|spider`)
@@ -112,7 +114,7 @@ func (h *LogHandler) V1Get(w http.ResponseWriter, r *http.Request) {
112114

113115
target, message := validateTargetURL(targetURL)
114116
if message != "" {
115-
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": targetURL, "reason": message}))
117+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": strings.TrimSpace(targetURL), "reason": message}))
116118
writeJSON(w, http.StatusOK, map[string]any{
117119
"error": message,
118120
"site_uv": 0,
@@ -124,7 +126,7 @@ func (h *LogHandler) V1Get(w http.ResponseWriter, r *http.Request) {
124126

125127
data, err := h.readCounts(r.Context(), target.Host, target.Path)
126128
if err != nil {
127-
h.log.Error("counter read failed", requestLogFields(r, "counter.read_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": targetURL}))
129+
h.log.Error("counter read failed", requestLogFields(r, "counter.read_failed", mergeFields(targetLogFields(strings.TrimSpace(targetURL), target), map[string]any{"status": http.StatusInternalServerError, "error": err.Error()})))
128130
writeJSON(w, http.StatusInternalServerError, map[string]string{"error": "Internal server error"})
129131
return
130132
}
@@ -146,7 +148,7 @@ func (h *LogHandler) V1Post(w http.ResponseWriter, r *http.Request) {
146148

147149
target, message := validateTargetURL(data.URL)
148150
if message != "" {
149-
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": data.URL, "reason": message}))
151+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": strings.TrimSpace(data.URL), "reason": message}))
150152
writeJSON(w, http.StatusOK, map[string]any{
151153
"error": message,
152154
"site_uv": 0,
@@ -156,14 +158,14 @@ func (h *LogHandler) V1Post(w http.ResponseWriter, r *http.Request) {
156158
return
157159
}
158160

159-
counts, err := h.writeCounts(r.Context(), target.Host, target.Path, data.IsNewUV)
161+
counts, err := h.writeAcceptedCounts(r.Context(), target.Host, target.Path, data.IsNewUV)
160162
if err != nil {
161-
h.log.Error("counter update failed", requestLogFields(r, "counter.write_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": data.URL}))
163+
h.logWriteFailure(r, strings.TrimSpace(data.URL), target, data.IsNewUV, err)
162164
writeJSON(w, http.StatusInternalServerError, map[string]string{"error": "Internal server error"})
163165
return
164166
}
165167

166-
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}))
168+
h.logWriteSuccess(r, strings.TrimSpace(data.URL), target, data.IsNewUV, counts)
167169
writeJSON(w, http.StatusOK, counts)
168170
}
169171

@@ -182,14 +184,14 @@ func (h *LogHandler) V2Get(w http.ResponseWriter, r *http.Request) {
182184

183185
target, message := validateTargetURL(targetURL)
184186
if message != "" {
185-
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": targetURL, "reason": message}))
187+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": strings.TrimSpace(targetURL), "reason": message}))
186188
h.writeV2Success(w, http.StatusOK, message, zeroCounters())
187189
return
188190
}
189191

190192
data, err := h.readCounts(r.Context(), target.Host, target.Path)
191193
if err != nil {
192-
h.log.Error("counter read failed", requestLogFields(r, "counter.read_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": targetURL}))
194+
h.log.Error("counter read failed", requestLogFields(r, "counter.read_failed", mergeFields(targetLogFields(strings.TrimSpace(targetURL), target), map[string]any{"status": http.StatusInternalServerError, "error": err.Error()})))
193195
h.writeV2Error(w, http.StatusInternalServerError, "Internal server error", nil)
194196
return
195197
}
@@ -211,19 +213,19 @@ func (h *LogHandler) V2Post(w http.ResponseWriter, r *http.Request) {
211213

212214
target, message := validateTargetURL(data.URL)
213215
if message != "" {
214-
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": data.URL, "reason": message}))
216+
h.log.Warn("invalid tracked url", requestLogFields(r, "target_url.invalid", map[string]any{"status": http.StatusOK, "target_url": strings.TrimSpace(data.URL), "reason": message}))
215217
h.writeV2Success(w, http.StatusOK, message, zeroCounters())
216218
return
217219
}
218220

219-
counts, err := h.writeCounts(r.Context(), target.Host, target.Path, data.IsNewUV)
221+
counts, err := h.writeAcceptedCounts(r.Context(), target.Host, target.Path, data.IsNewUV)
220222
if err != nil {
221-
h.log.Error("counter update failed", requestLogFields(r, "counter.write_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": data.URL}))
223+
h.logWriteFailure(r, strings.TrimSpace(data.URL), target, data.IsNewUV, err)
222224
h.writeV2Error(w, http.StatusInternalServerError, "Internal server error", nil)
223225
return
224226
}
225227

226-
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}))
228+
h.logWriteSuccess(r, strings.TrimSpace(data.URL), target, data.IsNewUV, counts)
227229
h.writeV2Success(w, http.StatusOK, "Data updated successfully", counts)
228230
}
229231

@@ -241,9 +243,9 @@ func (h *LogHandler) BenchmarkWrite(w http.ResponseWriter, r *http.Request) {
241243
return
242244
}
243245

244-
counts, err := h.writeCounts(r.Context(), target.Host, target.Path, true)
246+
counts, err := h.writeRequestScopedCounts(r.Context(), target.Host, target.Path, true)
245247
if err != nil {
246-
h.log.Error("benchmark counter update failed", requestLogFields(r, "counter.benchmark_write_failed", map[string]any{"status": http.StatusInternalServerError, "error": err.Error(), "target_url": benchmarkWriteTargetURL}))
248+
h.log.Error("benchmark counter update failed", requestLogFields(r, "counter.benchmark_write_failed", mergeFields(targetLogFields(benchmarkWriteTargetURL, target), map[string]any{"status": http.StatusInternalServerError, "error": err.Error()})))
247249
h.writeV2Error(w, http.StatusInternalServerError, "Internal server error", nil)
248250
return
249251
}
@@ -301,7 +303,7 @@ func (h *LogHandler) decodeCountRequest(w http.ResponseWriter, r *http.Request,
301303
}
302304

303305
func (h *LogHandler) readCounts(ctx context.Context, host string, path string) (CounterData, error) {
304-
ctx, cancel := context.WithTimeout(ctx, 5*time.Second)
306+
ctx, cancel := context.WithTimeout(ctx, readCountsTimeout)
305307
defer cancel()
306308

307309
siteUV, err := h.counter.FetchSiteUV(ctx, host, path)
@@ -322,9 +324,19 @@ func (h *LogHandler) readCounts(ctx context.Context, host string, path string) (
322324
return CounterData{SiteUV: siteUV, SitePV: sitePV, PagePV: pagePV}, nil
323325
}
324326

325-
func (h *LogHandler) writeCounts(ctx context.Context, host string, path string, isNewUV bool) (CounterData, error) {
326-
ctx, cancel := context.WithTimeout(ctx, 5*time.Second)
327+
func (h *LogHandler) writeAcceptedCounts(ctx context.Context, host string, path string, isNewUV bool) (CounterData, error) {
328+
detachedCtx, cancel := context.WithTimeout(context.WithoutCancel(ctx), writeCountsTimeout)
327329
defer cancel()
330+
return h.writeCounts(detachedCtx, host, path, isNewUV)
331+
}
332+
333+
func (h *LogHandler) writeRequestScopedCounts(ctx context.Context, host string, path string, isNewUV bool) (CounterData, error) {
334+
timeoutCtx, cancel := context.WithTimeout(ctx, writeCountsTimeout)
335+
defer cancel()
336+
return h.writeCounts(timeoutCtx, host, path, isNewUV)
337+
}
338+
339+
func (h *LogHandler) writeCounts(ctx context.Context, host string, path string, isNewUV bool) (CounterData, error) {
328340

329341
siteUV, err := h.counter.RecordSiteUV(ctx, host, isNewUV)
330342
if err != nil {
@@ -357,6 +369,7 @@ func zeroCounters() CounterData {
357369
}
358370

359371
func validateTargetURL(raw string) (targetURL, string) {
372+
raw = strings.TrimSpace(raw)
360373
parsed, err := url.Parse(raw)
361374
if err != nil {
362375
return targetURL{}, "Invalid URL format"
@@ -370,12 +383,77 @@ func validateTargetURL(raw string) (targetURL, string) {
370383
return targetURL{}, "Invalid URL host"
371384
}
372385

373-
path := parsed.Path
374-
if path == "" {
375-
path = "/"
386+
host := strings.ToLower(parsed.Hostname())
387+
if host == "" {
388+
return targetURL{}, "Invalid URL host"
389+
}
390+
391+
port := parsed.Port()
392+
if port != "" && !isDefaultPort(parsed.Scheme, port) {
393+
host = net.JoinHostPort(host, port)
394+
}
395+
396+
normalized := counter.NormalizeTarget(host, parsed.Path)
397+
return targetURL{Host: normalized.Host, Path: normalized.Path}, ""
398+
}
399+
400+
func isDefaultPort(scheme string, port string) bool {
401+
return (scheme == "http" && port == "80") || (scheme == "https" && port == "443")
402+
}
403+
404+
func (h *LogHandler) logWriteSuccess(r *http.Request, rawTarget string, target targetURL, isNewUV bool, counts CounterData) {
405+
fields := mergeFields(targetLogFields(rawTarget, target), map[string]any{
406+
"is_new_uv": isNewUV,
407+
"site_uv": counts.SiteUV,
408+
"site_pv": counts.SitePV,
409+
"page_pv": counts.PagePV,
410+
})
411+
412+
if transportErr := r.Context().Err(); transportErr != nil {
413+
fields["transport_error"] = transportErr.Error()
414+
h.log.Info("counter update completed after transport abort", requestLogFields(r, "counter.write_detached_completed", fields))
415+
return
416+
}
417+
418+
h.log.Debug("counter update completed", requestLogFields(r, "counter.write_completed", fields))
419+
}
420+
421+
func (h *LogHandler) logWriteFailure(r *http.Request, rawTarget string, target targetURL, isNewUV bool, err error) {
422+
fields := mergeFields(targetLogFields(rawTarget, target), map[string]any{
423+
"status": http.StatusInternalServerError,
424+
"error": err.Error(),
425+
"is_new_uv": isNewUV,
426+
})
427+
428+
if transportErr := r.Context().Err(); transportErr != nil {
429+
fields["transport_error"] = transportErr.Error()
430+
h.log.Error("counter update failed after transport abort", requestLogFields(r, "counter.write_detached_failed", fields))
431+
return
376432
}
377433

378-
return targetURL{Host: parsed.Host, Path: path}, ""
434+
h.log.Error("counter update failed", requestLogFields(r, "counter.write_failed", fields))
435+
}
436+
437+
func targetLogFields(raw string, target targetURL) map[string]any {
438+
fields := map[string]any{
439+
"host": target.Host,
440+
"target_path": target.Path,
441+
}
442+
if raw != "" {
443+
fields["target_url"] = raw
444+
}
445+
return fields
446+
}
447+
448+
func mergeFields(base map[string]any, extra map[string]any) map[string]any {
449+
merged := make(map[string]any, len(base)+len(extra))
450+
for key, value := range base {
451+
merged[key] = value
452+
}
453+
for key, value := range extra {
454+
merged[key] = value
455+
}
456+
return merged
379457
}
380458

381459
func (l *rateLimiter) Check(ctx context.Context, r *http.Request) rateLimitResult {

apps/api/internal/app/server.go

Lines changed: 20 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -66,20 +66,32 @@ func requestLoggingMiddleware(log *Logger) func(http.Handler) http.Handler {
6666
next.ServeHTTP(wrapped, r)
6767

6868
status := wrapped.Status()
69-
if status == 0 {
70-
status = http.StatusOK
71-
}
72-
7369
route := routePattern(r)
74-
log.Info("request completed", map[string]any{
75-
"event": "request.completed",
70+
fields := map[string]any{
7671
"request_id": middleware.GetReqID(r.Context()),
7772
"method": r.Method,
7873
"route": route,
7974
"path": r.URL.Path,
80-
"status": status,
8175
"duration_ms": time.Since(startedAt).Milliseconds(),
82-
})
76+
}
77+
if status != 0 {
78+
fields["status"] = status
79+
}
80+
81+
if transportErr := r.Context().Err(); transportErr != nil {
82+
fields["event"] = "request.aborted"
83+
fields["transport_error"] = transportErr.Error()
84+
log.Warn("request aborted", fields)
85+
return
86+
}
87+
88+
if status == 0 {
89+
status = http.StatusOK
90+
fields["status"] = status
91+
}
92+
93+
fields["event"] = "request.completed"
94+
log.Info("request completed", fields)
8395
})
8496
}
8597
}

0 commit comments

Comments
 (0)