Skip to content

Commit 6a585b0

Browse files
sergeyfastsergeyfast
authored
Cover custom log_format URI variables in botlog (#10)
- Extract resolveURI helper walking the nginx URI variables in priority order: $request_uri, $request, $uri (+ $args / $query_string). Single source of truth for both gonx text path and JSON map path; closure-based accessor stays stack-allocated - Add joinPathArgs to recombine $uri and $args from log_formats that split path and query across two fields (key=value style) - Always strip query before normalizePath so utm/session params cannot reach Prometheus uri labels even if an operator logs $request_uri under the "uri" field name - Cover the new branches: separate $uri/$args, $query_string alias, $request_uri directly, hybrid combined + key=value with internal rewrite, comma-rich query strings, base64 token URLs, and the metric-URI-stays-clean invariant
1 parent db79202 commit 6a585b0

2 files changed

Lines changed: 167 additions & 9 deletions

File tree

‎internal/topsrv/nginx/log.go‎

Lines changed: 51 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -369,13 +369,10 @@ func (c *LogCollector) parseLineWith(parser *gonx.Parser, line, path string) {
369369
p.UpstreamResponseTime, _ = entry.Field("upstream_response_time")
370370
p.UpstreamCacheStatus, _ = entry.Field("upstream_cache_status")
371371

372-
if req, err := entry.Field("request"); err == nil {
373-
p.URI = normalizeURI(req)
374-
p.RawURI = rawURIFromRequest(req)
375-
} else if u, err := entry.Field("uri"); err == nil {
376-
p.URI = normalizePath(u)
377-
p.RawURI = stripQuery(u)
378-
}
372+
p.URI, p.RawURI = resolveURI(func(name string) string {
373+
v, _ := entry.Field(name)
374+
return v
375+
})
379376

380377
for i, f := range c.extractFields {
381378
if i >= len(p.Extras) {
@@ -407,8 +404,7 @@ func (c *LogCollector) parseJSONLine(line, path string) {
407404
p.RequestTime = m["request_time"]
408405
p.UpstreamResponseTime = m["upstream_response_time"]
409406
p.UpstreamCacheStatus = m["upstream_cache_status"]
410-
p.URI = normalizeRequestURI(m["request_uri"], m["request"])
411-
p.RawURI = rawURIFromJSON(m["request_uri"], m["request"])
407+
p.URI, p.RawURI = resolveURI(func(name string) string { return m[name] })
412408

413409
for i, f := range c.extractFields {
414410
if i >= len(p.Extras) {
@@ -501,6 +497,52 @@ func stripQuery(p string) string {
501497
return p
502498
}
503499

500+
// resolveURI walks the nginx URI variables an operator might log in priority
501+
// order — $request_uri (path+query, as received), then $request (combined
502+
// "METHOD URI HTTP"), then $uri (+ optional $args/$query_string for splits).
503+
// Returns the normalized URI (for metrics cardinality) and the un-normalized
504+
// RawURI (full path + query) for botlog. get returns "" for absent fields.
505+
func resolveURI(get func(string) string) (uri, rawURI string) {
506+
if v := get("request_uri"); v != "" && v != "-" {
507+
return normalizePath(stripQuery(v)), v
508+
}
509+
if v := get("request"); v != "" && v != "-" {
510+
return normalizeURI(v), rawURIFromRequest(v)
511+
}
512+
if v := get("uri"); v != "" && v != "-" {
513+
args := get("args")
514+
if args == "" || args == "-" {
515+
args = get("query_string")
516+
}
517+
// stripQuery on the metric URI is defensive — nginx $uri is path-only
518+
// per spec, but operators occasionally log $request_uri under the
519+
// "uri" field name and query strings must never reach metric labels.
520+
metricURI := normalizePath(stripQuery(v))
521+
if args != "" && args != "-" {
522+
return metricURI, joinPathArgs(v, args)
523+
}
524+
// No separate args field — preserve v verbatim so RawURI keeps any
525+
// accidental query string the operator's format carried through.
526+
return metricURI, v
527+
}
528+
return "", ""
529+
}
530+
531+
// joinPathArgs reattaches a separate $args / $query_string value onto an
532+
// $uri path. nginx's $uri is path-only and $args is the raw query string
533+
// without a leading '?'; some operators log them as distinct fields, which
534+
// strips the query unless we rejoin them here. stripQuery on path is
535+
// defensive — guards against operators who log $request_uri under the
536+
// "uri" field name by mistake.
537+
func joinPathArgs(path, args string) string {
538+
path = stripQuery(path)
539+
args = strings.TrimPrefix(args, "?")
540+
if args == "" || args == "-" {
541+
return path
542+
}
543+
return path + "?" + args
544+
}
545+
504546
// recordLine updates all metric accumulators from a parsed log line. Must not be called concurrently.
505547
func (c *LogCollector) recordLine(p *ParsedLine) { //nolint:gocognit,nestif
506548
c.mu.Lock()

‎internal/topsrv/nginx/nginx_test.go‎

Lines changed: 116 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@ import (
1212
"time"
1313

1414
"github.com/prometheus/client_golang/prometheus"
15+
"github.com/satyrius/gonx"
1516
"github.com/stretchr/testify/assert"
1617
"github.com/stretchr/testify/require"
1718
"github.com/vmkteam/embedlog"
@@ -238,6 +239,121 @@ func TestParsedLine_RawURIUnnormalized(t *testing.T) {
238239
wantURI: "/api",
239240
wantRawURI: "/api?token=ab%3Dcd%26ef",
240241
},
242+
{
243+
// Key=value log_format with separate $uri and $args fields.
244+
// Without joining, RawURI would be path-only and gatesrv-side
245+
// HasQueryParams stays false (the original bug).
246+
name: "text key=value with separate $uri and $args",
247+
setup: func(c *LogCollector) {
248+
c.defaultParser = gonx.NewParser(`time="$time_iso8601" host="$host" uriPath="$uri" uriQuery="$args" httpStatus=$status bodyBytesSent=$body_bytes_sent`)
249+
c.AddObserver(&recordingObserver{})
250+
},
251+
feed: func(c *LogCollector) {
252+
c.parseLine(`time="2026-05-12T12:09:45+03:00" host="en.example.com" uriPath="/movies/catalog/" uriQuery="page=11051" httpStatus=404 bodyBytesSent=11496`)
253+
},
254+
wantURI: "/movies/catalog/",
255+
wantRawURI: "/movies/catalog/?page=11051",
256+
},
257+
{
258+
// Empty $args (the common case — most requests have no query).
259+
// RawURI must NOT carry a trailing '?'.
260+
name: "text key=value with empty $args",
261+
setup: func(c *LogCollector) {
262+
c.defaultParser = gonx.NewParser(`host="$host" uriPath="$uri" uriQuery="$args" httpStatus=$status bodyBytesSent=$body_bytes_sent`)
263+
c.AddObserver(&recordingObserver{})
264+
},
265+
feed: func(c *LogCollector) {
266+
c.parseLine(`host="x.example" uriPath="/about/" uriQuery="" httpStatus=200 bodyBytesSent=100`)
267+
},
268+
wantURI: "/about/",
269+
wantRawURI: "/about/",
270+
},
271+
{
272+
// $query_string is an alias of $args; some operators prefer it.
273+
name: "text key=value with $query_string instead of $args",
274+
setup: func(c *LogCollector) {
275+
c.defaultParser = gonx.NewParser(`host="$host" uriPath="$uri" qs="$query_string" httpStatus=$status bodyBytesSent=$body_bytes_sent`)
276+
c.AddObserver(&recordingObserver{})
277+
},
278+
feed: func(c *LogCollector) {
279+
c.parseLine(`host="x.example" uriPath="/search" qs="q=hello" httpStatus=200 bodyBytesSent=100`)
280+
},
281+
wantURI: "/search",
282+
wantRawURI: "/search?q=hello",
283+
},
284+
{
285+
// $request_uri carries the original path+query, URL-encoded as
286+
// received. Formats that log it directly need no rejoining.
287+
name: "text key=value with $request_uri directly",
288+
setup: func(c *LogCollector) {
289+
c.defaultParser = gonx.NewParser(`host="$host" reqUri="$request_uri" httpStatus=$status bodyBytesSent=$body_bytes_sent`)
290+
c.AddObserver(&recordingObserver{})
291+
},
292+
feed: func(c *LogCollector) {
293+
c.parseLine(`host="x.example" reqUri="/news/12345/title?utm=x" httpStatus=200 bodyBytesSent=100`)
294+
},
295+
wantURI: "/news/:id/:rest",
296+
wantRawURI: "/news/12345/title?utm=x",
297+
},
298+
{
299+
// Hybrid format: "$request" + ru="$request_uri" + u="$uri".
300+
// $request_uri wins so we ship what the client actually requested,
301+
// not the post-rewrite $uri pointing at the FastCGI dispatcher.
302+
name: "hybrid combined + key=value, internal rewrite",
303+
setup: func(c *LogCollector) {
304+
c.defaultParser = gonx.NewParser(`$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" rt="$request_time" "$http_user_agent" "$http_x_forwarded_for" h="$host" sn="$server_name" ru="$request_uri" u="$uri"`)
305+
c.AddObserver(&recordingObserver{})
306+
},
307+
feed: func(c *LogCollector) {
308+
c.parseLine(`192.0.2.9 - - [12/May/2026:00:00:30 +0000] "GET /events.ics HTTP/2.0" 200 900 "-" rt="0.098" "iOS/17.1 (21B74) dataaccessd/1.0" "-" h="example.com" sn="example.com" ru="/events.ics" u="/dispatch.php"`)
309+
},
310+
wantURI: "/events.ics",
311+
wantRawURI: "/events.ics",
312+
},
313+
{
314+
// Same hybrid format with a long query containing commas — gonx
315+
// must not get confused by literal commas inside the quoted value.
316+
name: "hybrid format with comma-rich query string",
317+
setup: func(c *LogCollector) {
318+
c.defaultParser = gonx.NewParser(`$remote_addr - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" rt="$request_time" "$http_user_agent" "$http_x_forwarded_for" h="$host" sn="$server_name" ru="$request_uri" u="$uri"`)
319+
c.AddObserver(&recordingObserver{})
320+
},
321+
feed: func(c *LogCollector) {
322+
c.parseLine(`192.0.2.5 - - [12/May/2026:00:00:23 +0000] "GET /shared/minify.php?hash&files=/a.js,/b.js,/c.js HTTP/2.0" 200 80612 "https://example.com/" rt="0.004" "Mozilla/5.0" "-" h="example.com" sn="example.com" ru="/shared/minify.php?hash&files=/a.js,/b.js,/c.js" u="/shared/minify.php"`)
323+
},
324+
wantURI: "/shared/:file.php",
325+
wantRawURI: "/shared/minify.php?hash&files=/a.js,/b.js,/c.js",
326+
},
327+
{
328+
// Operator misconfiguration: $request_uri logged under "uri" field
329+
// name. RawURI keeps the query (that's the point); metric URI must
330+
// be query-free — otherwise utm/session params blow up cardinality.
331+
name: "metric URI stays query-free even if $uri field carries query",
332+
setup: func(c *LogCollector) {
333+
c.defaultParser = gonx.NewParser(`host="$host" uriPath="$uri" httpStatus=$status bodyBytesSent=$body_bytes_sent`)
334+
c.AddObserver(&recordingObserver{})
335+
},
336+
feed: func(c *LogCollector) {
337+
c.parseLine(`host="x.example" uriPath="/news/12345?utm_source=tg&utm_campaign=spring" httpStatus=200 bodyBytesSent=100`)
338+
},
339+
wantURI: "/news/:id",
340+
wantRawURI: "/news/12345?utm_source=tg&utm_campaign=spring",
341+
},
342+
{
343+
// JSON map path with a base64-like signed URL (file CDN style):
344+
// "/get/<token>==,<numeric-id>/<asset-path>". RawURI ships verbatim;
345+
// metric URI collapses the token+id and truncates deep paths.
346+
name: "JSON map path with base64 token in request_uri",
347+
setup: func(c *LogCollector) {
348+
c.extractFields = []string{"http_user_agent"}
349+
c.AddObserver(&recordingObserver{uaIdx: 0})
350+
},
351+
feed: func(c *LogCollector) {
352+
c.ParseJSONLine(`{"status":"200","body_bytes_sent":"123456789","request_time":"42.000","request_uri":"/get/AbCdEf01234567_HiJkLmNo-PqRs==,1234567890/category/asset/files/example.zip","http_user_agent":"Mozilla/5.0"}`)
353+
},
354+
wantURI: "/get/:token/:rest",
355+
wantRawURI: "/get/AbCdEf01234567_HiJkLmNo-PqRs==,1234567890/category/asset/files/example.zip",
356+
},
241357
}
242358
for _, tc := range cases {
243359
t.Run(tc.name, func(t *testing.T) {

0 commit comments

Comments
 (0)