Skip to content

Commit db79202

Browse files
authored
Ship botlog URI with query params intact (#9)
* Ship botlog URI with query params intact - Add ParsedLine.RawURI (path + query string) alongside RawPath so observers see the full hit URL; populated in all three parse paths (text/$request, text/$uri, JSON request_uri) - Switch botlog Observer to prefer RawURI with fallback chain RawURI -> RawPath -> URI; gatesrv-side HasQueryParams now works on bot-log events instead of always returning false - Bump DefaultBatchInterval 5s -> 30s; quiet hosts were flushing ~50-event payloads every tick, larger batches compress better - Cover the new field across both parsers including percent-encoded query strings, plus the observer fallback chain * Drop redundant ParsedLine.RawPath - RawPath was only read by botlog Observer as the middle of a three-level fallback (RawURI -> RawPath -> URI). All three parser paths populate RawPath and RawURI together, so RawPath was never the only field set — middle fallback was unreachable - Remove rawPathFromRequest and rawPathFromJSON; this eliminates a duplicate strings.SplitN per parsed line on the hot path - Collapse observer fallback to RawURI -> URI; drop the synthetic TestObserver_FallsBackToRawPathWhenRawURIEmpty that exercised the unreachable state - Rename TestParsedLine_RawPathUnnormalized to *_RawURIUnnormalized and drop wantRawPath assertions; recordedLine.rawPath gone too * Cap botlog Event.URI at URITruncate - Add Config.URITruncate (default 2048) symmetrical to UATruncate; IE's legacy 2083-char URL limit covers >99% of legitimate traffic - Observer truncates Event.URI before BuildEvent so pathological bot probes (4-8KB base64/SQLi payloads in query strings) cannot bloat WAL writes or the gatesrv POST body - Pre-fix RawPath stripped queries kept URIs naturally short; with RawURI carrying the query verbatim we need an explicit cap * Update README botlog defaults - BatchInterval 5s -> 30s - Add URITruncate row (default 2048)
1 parent ecfe96b commit db79202

8 files changed

Lines changed: 114 additions & 55 deletions

File tree

README.md

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -149,10 +149,11 @@ Channel = "stable" # stable / beta
149149
# Token = "" # required — issued by topsrv.io per project
150150
# Endpoint = "" # default: [Push].Endpoint with /v1/bot-logs path
151151
# BatchSize = 5000 # events per batch
152-
# BatchInterval = "5s" # flush interval
152+
# BatchInterval = "30s" # flush interval
153153
# SpoolDir = "" # default: [Push].SpoolDir; a "botlog/" subdir is created inside
154154
# MaxSpoolMB = 200 # WAL disk budget
155155
# UATruncate = 1024 # truncate user-agent at this length
156+
# URITruncate = 2048 # truncate request URI at this length
156157
# ExtraUAPatterns = ["MyCustomCrawler/"] # local additions to the bot list
157158
```
158159

@@ -183,10 +184,11 @@ Channel = "stable" # stable / beta
183184
| `BotLogs.Token` || Bot-logs ingest bearer token (separate from `Push.Token`) |
184185
| `BotLogs.Endpoint` | derived | Ingest URL; defaults to `[Push].Endpoint` with `/v1/bot-logs` path |
185186
| `BotLogs.BatchSize` | `5000` | Events per batch |
186-
| `BotLogs.BatchInterval` | `5s` | Flush interval |
187+
| `BotLogs.BatchInterval` | `30s` | Flush interval |
187188
| `BotLogs.SpoolDir` | derived | Parent dir for WAL spool; `botlog/` subdir is created inside. Defaults to `[Push].SpoolDir` |
188189
| `BotLogs.MaxSpoolMB` | `200` | Disk budget for spool subdir |
189190
| `BotLogs.UATruncate` | `1024` | Max UA length per event |
191+
| `BotLogs.URITruncate` | `2048` | Max URI length per event |
190192
| `BotLogs.ExtraUAPatterns` | `[]` | Local additions to known-bots UA patterns |
191193

192194
### Environment variables

cfg/local.toml.dist

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -45,8 +45,9 @@ Channel = "stable" # stable / beta
4545
# Token = "" # required — issued by topsrv.io per project
4646
# Endpoint = "" # default: derived from [Push].Endpoint
4747
# BatchSize = 5000 # events per batch
48-
# BatchInterval = "5s" # flush interval
48+
# BatchInterval = "30s" # flush interval
4949
# SpoolDir = "" # default: [Push].SpoolDir
5050
# MaxSpoolMB = 200 # WAL disk budget
5151
# UATruncate = 1024 # truncate user-agent at this length
52+
# URITruncate = 2048 # truncate request URI at this length
5253
# ExtraUAPatterns = ["MyCustomCrawler/"] # local additions to the bot list

internal/topsrv/botlog/config.go

Lines changed: 13 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -15,10 +15,16 @@ import (
1515
)
1616

1717
const (
18-
DefaultBatchSize = 5000
19-
DefaultBatchInterval = 5 * time.Second
18+
DefaultBatchSize = 5000
19+
// 30s gives the receiver larger batches on light bot traffic; a 5s
20+
// interval was flushing ~50-event payloads every tick on quiet hosts.
21+
DefaultBatchInterval = 30 * time.Second
2022
DefaultMaxSpoolMB = 200
2123
DefaultUATruncate = 1024
24+
// 2048 covers >99% of legitimate URLs (IE legacy limit was 2083). Bot
25+
// probes routinely send 4-8KB URIs with base64/SQLi payloads — capping
26+
// keeps WAL writes and gatesrv payload size bounded.
27+
DefaultURITruncate = 2048
2228

2329
// ingestPath is the control-plane handler that accepts ndjson bot-log batches.
2430
ingestPath = "/v1/bot-logs"
@@ -32,10 +38,11 @@ type Config struct {
3238
Endpoint string // ingest URL; default: [Push].Endpoint with path replaced by /v1/bot-logs
3339
Token string // Bearer token; required when Enabled
3440
BatchSize int // events per batch; default 5000
35-
BatchInterval string // flush interval as Go duration; default "5s"
41+
BatchInterval string // flush interval as Go duration; default "30s"
3642
SpoolDir string // parent directory; subdir "botlog" is created inside; default = [Push].SpoolDir
3743
MaxSpoolMB int // disk budget for spool subdir; default 200
3844
UATruncate int // max UA length stored per event; default 1024
45+
URITruncate int // max URI length stored per event; default 2048
3946
ExtraUAPatterns []string // local additions to knownBots (substring, case-sensitive)
4047

4148
parsedBatchInterval time.Duration // populated by Validate
@@ -89,6 +96,9 @@ func (c *Config) Validate(push topsrv.PushConfig) error {
8996
if c.UATruncate <= 0 {
9097
c.UATruncate = DefaultUATruncate
9198
}
99+
if c.URITruncate <= 0 {
100+
c.URITruncate = DefaultURITruncate
101+
}
92102
return nil
93103
}
94104

internal/topsrv/botlog/observer.go

Lines changed: 7 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -53,6 +53,7 @@ type Observer struct {
5353
pusher *Pusher
5454
hostname string
5555
uaTruncate int
56+
uriTruncate int
5657
extraPatterns []string
5758

5859
// Resolved at construction from the LogCollector's ExtractFields. -1 when
@@ -68,6 +69,7 @@ func NewObserver(p *Pusher, cfg Config, hostname string, extractFields []string)
6869
pusher: p,
6970
hostname: hostname,
7071
uaTruncate: cfg.UATruncate,
72+
uriTruncate: cfg.URITruncate,
7173
extraPatterns: cfg.ExtraUAPatterns,
7274
idxUA: slices.Index(extractFields, fieldUserAgent),
7375
idxHost: slices.Index(extractFields, fieldHost),
@@ -91,15 +93,16 @@ func (o *Observer) OnLogLine(p *nginx.ParsedLine, _ string) {
9193
}
9294

9395
// Bot-log UI groups by actual URL, not the nginx-metrics-normalized form.
94-
// Fall back to URI if the log format doesn't yield a raw path (legacy
95-
// $uri after rewrite — less precise but still useful).
96-
uri := p.RawPath
96+
// RawURI keeps the query string so HasQueryParams on gatesrv works; the
97+
// normalized URI is the last-resort fallback for log formats that yield
98+
// neither $request nor $uri.
99+
uri := p.RawURI
97100
if uri == "" {
98101
uri = p.URI
99102
}
100103
ev := BuildEvent(time.Now(), o.hostname, Fields{
101104
Status: p.Status,
102-
URI: uri,
105+
URI: truncate(uri, o.uriTruncate),
103106
BodyBytesSent: p.BodyBytesSent,
104107
RequestTime: p.RequestTime,
105108
UpstreamResponseTime: p.UpstreamResponseTime,

internal/topsrv/botlog/observer_test.go

Lines changed: 26 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -75,31 +75,49 @@ func TestObserver_EnqueuesBotEvent(t *testing.T) {
7575
}
7676
}
7777

78-
// Verifies the bot-logs UI fix: Event.URI must carry RawPath (un-normalized
79-
// hit URL), not the cardinality-collapsed ParsedLine.URI.
80-
func TestObserver_UsesRawPathOverURI(t *testing.T) {
78+
// Verifies the bot-logs UI fix: Event.URI must carry RawURI (un-normalized
79+
// hit URL with query string), not the cardinality-collapsed ParsedLine.URI.
80+
func TestObserver_UsesRawURIOverURI(t *testing.T) {
8181
o, p := newObserverPair(t)
8282
pl := &nginx.ParsedLine{
8383
Status: "200",
8484
URI: "/news/:id/:rest",
85-
RawPath: "/news/12345/some-title",
85+
RawURI: "/news/12345/some-title?utm=x",
8686
Extras: [nginx.MaxExtras]string{"GPTBot/1.0", "", "", ""},
8787
NExtras: 1,
8888
}
8989
o.OnLogLine(pl, "")
9090
require.Len(t, p.queue, 1)
9191
ev := <-p.queue
92-
assert.Equal(t, "/news/12345/some-title", ev.URI)
92+
assert.Equal(t, "/news/12345/some-title?utm=x", ev.URI)
9393
}
9494

95-
// When the log format yields no RawPath (legacy $uri after rewrite), Observer
95+
// Pathological bot probes regularly send 4-8KB URIs with base64/SQLi payloads.
96+
// Observer must cap Event.URI at Config.URITruncate before shipping.
97+
func TestObserver_TruncatesURI(t *testing.T) {
98+
o, p := newObserverPair(t)
99+
long := "/probe?p=" + strings.Repeat("A", 5000)
100+
pl := &nginx.ParsedLine{
101+
Status: "200",
102+
URI: "/probe",
103+
RawURI: long,
104+
Extras: [nginx.MaxExtras]string{"GPTBot/1.0", "", "", ""},
105+
NExtras: 1,
106+
}
107+
o.OnLogLine(pl, "")
108+
require.Len(t, p.queue, 1)
109+
ev := <-p.queue
110+
assert.Len(t, ev.URI, DefaultURITruncate)
111+
assert.Equal(t, long[:DefaultURITruncate], ev.URI)
112+
}
113+
114+
// When the log format yields no RawURI (legacy $uri after rewrite), Observer
96115
// must fall back to ParsedLine.URI rather than emit an empty event URI.
97-
func TestObserver_FallsBackToURIWhenRawPathEmpty(t *testing.T) {
116+
func TestObserver_FallsBackToURIWhenRawURIEmpty(t *testing.T) {
98117
o, p := newObserverPair(t)
99118
pl := &nginx.ParsedLine{
100119
Status: "200",
101120
URI: "/news/:id",
102-
RawPath: "",
103121
Extras: [nginx.MaxExtras]string{"GPTBot/1.0", "", "", ""},
104122
NExtras: 1,
105123
}

internal/topsrv/botlog/pusher.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -103,7 +103,7 @@ func isPermanentFailure(err error) bool {
103103
}
104104

105105
// gzipPool reuses gzip writers across flushes — gzip.NewWriter allocates ~256 KB
106-
// of internal buffers, which adds up at 5s flush cadence.
106+
// of internal buffers, which adds up at the default flush cadence.
107107
var gzipPool = sync.Pool{
108108
New: func() any { return gzip.NewWriter(io.Discard) },
109109
}

internal/topsrv/nginx/log.go

Lines changed: 14 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -347,7 +347,7 @@ func (c *LogCollector) parseLine(line string) {
347347
type ParsedLine struct {
348348
Status string
349349
URI string // path normalized for nginx-metrics cardinality (/:id, /:rest)
350-
RawPath string // un-normalized request path (querystring stripped) — for observers that need the actual URL (e.g. botlog)
350+
RawURI string // un-normalized request URI (path + query) — for observers that need the full URL (e.g. botlog)
351351
BodyBytesSent string
352352
RequestTime string
353353
UpstreamResponseTime string
@@ -371,10 +371,10 @@ func (c *LogCollector) parseLineWith(parser *gonx.Parser, line, path string) {
371371

372372
if req, err := entry.Field("request"); err == nil {
373373
p.URI = normalizeURI(req)
374-
p.RawPath = rawPathFromRequest(req)
374+
p.RawURI = rawURIFromRequest(req)
375375
} else if u, err := entry.Field("uri"); err == nil {
376376
p.URI = normalizePath(u)
377-
p.RawPath = stripQuery(u)
377+
p.RawURI = stripQuery(u)
378378
}
379379

380380
for i, f := range c.extractFields {
@@ -408,7 +408,7 @@ func (c *LogCollector) parseJSONLine(line, path string) {
408408
p.UpstreamResponseTime = m["upstream_response_time"]
409409
p.UpstreamCacheStatus = m["upstream_cache_status"]
410410
p.URI = normalizeRequestURI(m["request_uri"], m["request"])
411-
p.RawPath = rawPathFromJSON(m["request_uri"], m["request"])
411+
p.RawURI = rawURIFromJSON(m["request_uri"], m["request"])
412412

413413
for i, f := range c.extractFields {
414414
if i >= len(p.Extras) {
@@ -434,7 +434,7 @@ func (c *LogCollector) parseJSONLine(line, path string) {
434434
UpstreamResponseTime: entry.UpstreamResponseTime,
435435
UpstreamCacheStatus: entry.UpstreamCacheStatus,
436436
URI: normalizeRequestURI(entry.RequestURI, entry.Request),
437-
RawPath: rawPathFromJSON(entry.RequestURI, entry.Request),
437+
RawURI: rawURIFromJSON(entry.RequestURI, entry.Request),
438438
}
439439

440440
c.finishLine(&p, path)
@@ -475,24 +475,23 @@ func normalizeRequestURI(requestURI, request string) string {
475475
return ""
476476
}
477477

478-
// rawPathFromRequest extracts the un-normalized path from "$request" (e.g.
479-
// "GET /news/12345/title HTTP/1.1") with the querystring stripped. Returns ""
480-
// if request is malformed.
481-
func rawPathFromRequest(request string) string {
478+
// rawURIFromRequest extracts the un-normalized request URI (path + query) from
479+
// "$request" (e.g. "GET /news/12345?utm=x HTTP/1.1"). Returns "" if malformed.
480+
func rawURIFromRequest(request string) string {
482481
parts := strings.SplitN(request, " ", 3)
483482
if len(parts) < 2 {
484483
return ""
485484
}
486-
return stripQuery(parts[1])
485+
return parts[1]
487486
}
488487

489-
// rawPathFromJSON picks request_uri (preferred — already path-only in most
490-
// log_formats) and falls back to parsing $request. Querystring is stripped.
491-
func rawPathFromJSON(requestURI, request string) string {
488+
// rawURIFromJSON picks request_uri (already carries query string from nginx)
489+
// and falls back to parsing $request. Querystring is preserved.
490+
func rawURIFromJSON(requestURI, request string) string {
492491
if requestURI != "" {
493-
return stripQuery(requestURI)
492+
return requestURI
494493
}
495-
return rawPathFromRequest(request)
494+
return rawURIFromRequest(request)
496495
}
497496

498497
func stripQuery(p string) string {

internal/topsrv/nginx/nginx_test.go

Lines changed: 47 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -115,15 +115,15 @@ type recordingObserver struct {
115115
}
116116

117117
type recordedLine struct {
118-
status string
119-
uri string
120-
rawPath string
121-
ua string
122-
path string
118+
status string
119+
uri string
120+
rawURI string
121+
ua string
122+
path string
123123
}
124124

125125
func (r *recordingObserver) OnLogLine(p *ParsedLine, path string) {
126-
rl := recordedLine{status: p.Status, uri: p.URI, rawPath: p.RawPath, path: path}
126+
rl := recordedLine{status: p.Status, uri: p.URI, rawURI: p.RawURI, path: path}
127127
if r.uaIdx >= 0 && r.uaIdx < p.NExtras {
128128
rl.ua = p.Extras[r.uaIdx]
129129
}
@@ -164,15 +164,16 @@ func TestLogCollectorObserver(t *testing.T) {
164164
assert.EqualValues(t, 0, c.reqCount, "no timing field → no histogram update")
165165
}
166166

167-
// Verifies the URI vs RawPath split: nginx-metrics keep the normalized form
168-
// (cardinality control), observers like botlog get the actual hit URL.
169-
func TestParsedLine_RawPathUnnormalized(t *testing.T) {
167+
// Verifies the URI / RawURI split: nginx-metrics keep the normalized form
168+
// (cardinality control), observers like botlog get the full hit URL with
169+
// query string from RawURI.
170+
func TestParsedLine_RawURIUnnormalized(t *testing.T) {
170171
cases := []struct {
171-
name string
172-
setup func(c *LogCollector)
173-
feed func(c *LogCollector)
174-
wantURI string
175-
wantRawPath string
172+
name string
173+
setup func(c *LogCollector)
174+
feed func(c *LogCollector)
175+
wantURI string
176+
wantRawURI string
176177
}{
177178
{
178179
name: "text/$request with numeric segment",
@@ -184,8 +185,8 @@ func TestParsedLine_RawPathUnnormalized(t *testing.T) {
184185
`1.2.3.4 [11/Apr/2026:17:15:23 +0300] "GET /news/12345/title?utm=x HTTP/1.1" 200 1234 "Bot/1"`,
185186
"/var/log/nginx/access.log")
186187
},
187-
wantURI: "/news/:id/:rest",
188-
wantRawPath: "/news/12345/title",
188+
wantURI: "/news/:id/:rest",
189+
wantRawURI: "/news/12345/title?utm=x",
189190
},
190191
{
191192
name: "JSON request_uri with querystring",
@@ -196,8 +197,8 @@ func TestParsedLine_RawPathUnnormalized(t *testing.T) {
196197
c.ParseJSONLine(`{"status":"200","body_bytes_sent":"100","request_time":"0.1",` +
197198
`"request_uri":"/series/777/episodes?page=2","upstream_response_time":""}`)
198199
},
199-
wantURI: "/series/:id/:rest",
200-
wantRawPath: "/series/777/episodes",
200+
wantURI: "/series/:id/:rest",
201+
wantRawURI: "/series/777/episodes?page=2",
201202
},
202203
{
203204
name: "JSON with extra-labels path (map unmarshal)",
@@ -209,8 +210,33 @@ func TestParsedLine_RawPathUnnormalized(t *testing.T) {
209210
c.ParseJSONLine(`{"status":"200","body_bytes_sent":"100","request_time":"0.1",` +
210211
`"request_uri":"/user/42/comments","http_user_agent":"Bot/1"}`)
211212
},
212-
wantURI: "/user/:id/:rest",
213-
wantRawPath: "/user/42/comments",
213+
wantURI: "/user/:id/:rest",
214+
wantRawURI: "/user/42/comments",
215+
},
216+
{
217+
// Percent-encoded chars in query must survive verbatim so the
218+
// gatesrv side can decode params (e.g. utm_term=hello%20world).
219+
name: "text/$request with percent-encoded query",
220+
setup: func(c *LogCollector) {
221+
c.AddObserver(&recordingObserver{})
222+
},
223+
feed: func(c *LogCollector) {
224+
c.parseLine(`10.0.0.1 [01/Jan/2026:00:00:00 +0000] "GET /search?q=hello%20world&p=a%2Fb HTTP/1.1" 200 100 "Bot/1"`)
225+
},
226+
wantURI: "/search",
227+
wantRawURI: "/search?q=hello%20world&p=a%2Fb",
228+
},
229+
{
230+
name: "JSON request_uri preserves percent-encoded query",
231+
setup: func(c *LogCollector) {
232+
c.AddObserver(&recordingObserver{})
233+
},
234+
feed: func(c *LogCollector) {
235+
c.ParseJSONLine(`{"status":"200","body_bytes_sent":"100","request_time":"0.1",` +
236+
`"request_uri":"/api?token=ab%3Dcd%26ef"}`)
237+
},
238+
wantURI: "/api",
239+
wantRawURI: "/api?token=ab%3Dcd%26ef",
214240
},
215241
}
216242
for _, tc := range cases {
@@ -224,7 +250,7 @@ func TestParsedLine_RawPathUnnormalized(t *testing.T) {
224250
rec := c.observers[0].(*recordingObserver)
225251
require.Len(t, rec.lines, 1)
226252
assert.Equal(t, tc.wantURI, rec.lines[0].uri, "URI must be normalized for nginx-metrics")
227-
assert.Equal(t, tc.wantRawPath, rec.lines[0].rawPath, "RawPath must be the raw request path (querystring stripped)")
253+
assert.Equal(t, tc.wantRawURI, rec.lines[0].rawURI, "RawURI must be the raw request URI (path + query)")
228254
})
229255
}
230256
}

0 commit comments

Comments
 (0)