Skip to content

Commit 940ffca

Browse files
authored
feat: enhance logger (#1113)
* remove lumberjack * add logging mgr * add access/error logger Signed-off-by: James Ranson <james@ranson.org>
1 parent 3a7dce5 commit 940ffca

62 files changed

Lines changed: 5386 additions & 105 deletions

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

README.md

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ Trickster is a fully-featured HTTP Reverse Proxy Cache for HTTP applications lik
3131
* High-performance [Collapsed Forwarding](./docs/collapsed-forwarding.md)
3232
* Best-in-class [Byte Range Request caching and acceleration](./docs/range_request.md).
3333
* [Distributed Tracing](./docs/tracing.md) via OpenTelemetry, supporting OTLP protocol.
34+
* Per-backend [Access and Error Logs](./docs/access-logs.md) with Apache-style customizable formats
3435
* Rules engine for custom request routing and rewriting
3536
* Configurable [maximum request body size](./docs/body.md).
3637

docs/access-logs.md

Lines changed: 164 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,164 @@
1+
# Access and Error Logs
2+
3+
Trickster can write per-backend HTTP access logs and error logs, with
4+
customizable formats, rotation and retention. Both logs are off by default;
5+
each is enabled by configuring its filename.
6+
7+
## Basic Configuration
8+
9+
```yaml
10+
backends:
11+
example1:
12+
provider: rp
13+
origin_url: http://example.com/
14+
access_log:
15+
filename: /var/log/trickster/example1.access.log
16+
error_filename: /var/log/trickster/example1.error.log
17+
```
18+
19+
- The access log receives one line per request handled by the backend and is
20+
written only when `filename` is set.
21+
- The error log receives one line per request whose response status is at or
22+
above `error_threshold` (default `400`) and is written only when
23+
`error_filename` is set. An error-logged request also appears in the access
24+
log when both are configured.
25+
- Two backends may share a filename; they will safely share the underlying
26+
file and its rotation.
27+
- When `instance_id` is set in the main config, it is inserted into log
28+
filenames just as with the application log (e.g., `example1.access.1.log`).
29+
30+
## Log Format
31+
32+
The `format` option accepts either a named preset or a custom format string
33+
using Apache-style `%` tokens, so the well-known conventions from Apache
34+
HTTP Server, Apache Traffic Server, Lighttpd, and similar servers apply
35+
directly.
36+
37+
### Presets
38+
39+
| Name | Description |
40+
| ----- | ----- |
41+
| `common` | NCSA Common Log Format: `%h %l %u %t "%r" %>s %b` |
42+
| `combined` | Apache/Nginx Combined format: `common` + Referer and User-Agent. This is the default. |
43+
| `extended` | `combined` + duration (ms), cache status and backend name |
44+
| `json` | One JSON object per line with a fixed field set (see below) |
45+
46+
### Custom Formats
47+
48+
```yaml
49+
access_log:
50+
filename: /var/log/trickster/example1.access.log
51+
format: '%h %u %t "%r" %>s %b %{ms}T %{cache-status}x'
52+
```
53+
54+
Supported tokens:
55+
56+
| Token | Description |
57+
| ----- | ----- |
58+
| `%h`, `%a` | client IP address |
59+
| `%l` | remote logname (always `-`) |
60+
| `%u` | authenticated username (from HTTP Basic Auth), else `-` |
61+
| `%t` | request start time in CLF format: `[26/Aug/2026:10:30:00 +0000]` |
62+
| `%{sec}t`, `%{msec}t`, `%{usec}t` | request start time as a Unix epoch value |
63+
| `%{LAYOUT}t` | request start time in a custom [Go time layout](https://pkg.go.dev/time#pkg-constants) |
64+
| `%r` | first line of the request: `GET /path?query HTTP/1.1` |
65+
| `%m` | request method |
66+
| `%U` | request URL path |
67+
| `%q` | query string, prefixed with `?`, or empty when none |
68+
| `%H` | request protocol (e.g., `HTTP/1.1`) |
69+
| `%s`, `%>s` | response status code |
70+
| `%b` | response body bytes, or `-` when zero (CLF style) |
71+
| `%B` | response body bytes, numeric |
72+
| `%D` | request duration in microseconds |
73+
| `%T` | request duration in whole seconds |
74+
| `%{us}T`, `%{ms}T`, `%{s}T` | request duration in the given unit |
75+
| `%{Name}i` | request header value |
76+
| `%{Name}o` | response header value |
77+
| `%{Name}c` | request cookie value |
78+
| `%v` | requested virtual host |
79+
| `%p` | listener port that served the request |
80+
| `%A` | listener IP address that served the request |
81+
| `%%` | a literal `%` |
82+
83+
Trickster-specific values use the `%{key}x` extension namespace:
84+
85+
| Token | Description |
86+
| ----- | ----- |
87+
| `%{backend}x` | backend name |
88+
| `%{provider}x` | backend provider type |
89+
| `%{cache-status}x` | cache result (`hit`, `phit`, `kmiss`, ...); see [Cache Status](./caches.md#cache-status) |
90+
| `%{engine}x` | proxy engine that handled the request (e.g., `DeltaProxyCache`) |
91+
| `%{path-config}x` | the matched [path config](./paths.md) path |
92+
93+
Missing values render as `-`. Values derived from the request (like headers
94+
and usernames) are backslash-escaped so they cannot corrupt the log line
95+
structure. Unknown tokens fail validation at startup.
96+
97+
The `json` preset emits these fields per line: `time`, `client_ip`, `user`,
98+
`method`, `path`, `query`, `proto`, `status`, `bytes`, `duration_ms`,
99+
`host`, `referer`, `user_agent`, `backend`, `provider`, `path_config`,
100+
`cache_status`, `engine`.
101+
102+
## Rotation and Retention
103+
104+
Access and error logs are rotated and pruned automatically, using
105+
nginx/logrotate-style numbered archives (`example1.access.log.1.gz` is the
106+
most recent archive, `.2.gz` the next, and so on).
107+
108+
```yaml
109+
access_log:
110+
filename: /var/log/trickster/example1.access.log
111+
rotation:
112+
size: 256MB # rotate when the live file would exceed this size (default 256MB)
113+
interval: 1d # also rotate when the live file is older than this (default off)
114+
retention:
115+
count: 3 # keep at most 3 archives (default 80)
116+
age: 7d # also prune archives older than this (default 7d)
117+
compress: true # gzip archives (default true)
118+
```
119+
120+
- `size` and `interval` may be combined; the log rotates when either
121+
threshold is reached. Setting both to `0` disables rotation.
122+
- Sizes accept `KB`, `MB`, `GB` and `TB` suffixes (binary multiples), or a
123+
plain byte count.
124+
- `retention.count: 0` disables count-based pruning and keeps all archives.
125+
- Writes are buffered for up to one second or 64 KiB. A process or machine
126+
crash can lose the buffered tail; an orderly shutdown flushes it.
127+
- Interval rotation keeps its epoch in a `<filename>.rotation` sidecar so a
128+
restart does not reset the interval clock.
129+
130+
Archives created by older Trickster releases use timestamped lumberjack
131+
names and are not included in numbered-archive retention. They form a bounded
132+
legacy set and may be removed manually after upgrading.
133+
134+
When upgrading from the original logging implementation, note these filename
135+
and retention changes:
136+
137+
- `retention.count: 0` now keeps all archives; configure a positive count to
138+
bound archive retention.
139+
- With `main.instance_id` enabled, filenames without a `.log` suffix now also
140+
include the instance ID (`trickster.out` becomes `trickster.2.out`). Update
141+
log shippers that still follow the unsuffixed filename.
142+
143+
The same `rotation`, `retention` and `compress` options are also available
144+
in the main `logging:` config section to control rotation of the Trickster
145+
application log, with the same defaults.
146+
147+
## Error Log Settings
148+
149+
Each `error_*` option inherits its value from the corresponding access log
150+
option when unset:
151+
152+
```yaml
153+
access_log:
154+
filename: /var/log/trickster/example1.access.log
155+
format: combined
156+
error_filename: /var/log/trickster/example1.error.log
157+
error_format: '' # default: inherits format
158+
error_threshold: 400 # log responses with status >= this (default 400)
159+
error_rotation: # default: inherits rotation
160+
size: 64MB
161+
error_retention: # default: inherits retention
162+
count: 7
163+
error_compress: true # default: inherits compress
164+
```

examples/conf/example.full.yaml

Lines changed: 48 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -392,6 +392,36 @@ backends:
392392
# # default is false
393393
# path_routing_disabled: false
394394

395+
# # access_log configures per-backend HTTP access and error logging. Both logs are off by default and
396+
# # are each enabled by setting their filename. See docs/access-logs.md for all options and format tokens
397+
# access_log:
398+
# # filename enables the access log (one line per request served by this backend)
399+
# filename: /var/log/trickster/example.access.log
400+
# # format is a named preset (common, combined, extended, json) or a custom Apache-style
401+
# # %-token format string. default is combined
402+
# format: combined
403+
# # rotation controls when the log is rotated; a rotation occurs when either threshold is reached
404+
# rotation:
405+
# # size rotates the log when the live file would exceed this size. default is 256MB
406+
# size: 256MB
407+
# # interval rotates the log when the live file is older than this. default is 0 (off)
408+
# interval: 1d
409+
# # retention controls how many rotated archives (example.access.log.1.gz, .2.gz, ...) are kept
410+
# retention:
411+
# # count is the maximum archives kept; 0 is unlimited. default is 80
412+
# count: 3
413+
# # age prunes archives older than this. default is 7d
414+
# age: 7d
415+
# # compress gzips rotated archives. default is true
416+
# compress: true
417+
# # error_filename enables the error log, receiving requests whose response status is >= error_threshold
418+
# error_filename: /var/log/trickster/example.error.log
419+
# # error_threshold is the minimum response status code written to the error log. default is 400
420+
# error_threshold: 400
421+
# # error_format, error_rotation, error_retention and error_compress override the error log's
422+
# # behaviors; each inherits from the corresponding access log option above when unset
423+
# error_format: ''
424+
395425
# # rule_name provides the name of the rule config to be used by this backend.
396426
# # This is only effective if the provider is rule
397427
# rule_name: example-rule
@@ -888,3 +918,21 @@ backends:
888918
# # log_file defines the file location to store logs. These will be auto-rolled and maintained for you.
889919
# # not specifying a log_file (this is the default behavior) will print logs to STDOUT
890920
# log_file: /some/path/to/trickster.log
921+
922+
# # rotation controls when the log file is rotated; a rotation occurs when either threshold is reached.
923+
# # rotated archives are kept alongside the live file as trickster.log.1.gz, .2.gz, etc.
924+
# rotation:
925+
# # size rotates the log when the live file would exceed this size. default is 256MB
926+
# size: 256MB
927+
# # interval rotates the log when the live file is older than this. default is 0 (off)
928+
# interval: 1d
929+
930+
# # retention controls how many rotated archives are kept
931+
# retention:
932+
# # count is the maximum archives kept; 0 is unlimited. default is 80
933+
# count: 80
934+
# # age prunes archives older than this. default is 7d
935+
# age: 7d
936+
937+
# # compress gzips rotated archives. default is true
938+
# compress: true

go.mod

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,6 @@ require (
3737
golang.org/x/sync v0.22.0
3838
google.golang.org/grpc v1.83.0
3939
google.golang.org/protobuf v1.36.12
40-
gopkg.in/natefinch/lumberjack.v2 v2.2.1
4140
pgregory.net/rapid v1.3.0
4241
vitess.io/vitess v0.24.2
4342
)

go.sum

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1098,8 +1098,6 @@ gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8
10981098
gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk=
10991099
gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q=
11001100
gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI=
1101-
gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc=
1102-
gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=
11031101
gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
11041102
gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
11051103
gopkg.in/yaml.v2 v2.2.4/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=

integration/go.mod

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -90,5 +90,4 @@ require (
9090
google.golang.org/genproto/googleapis/rpc v0.0.0-20260810153831-ec0a7760b754 // indirect
9191
google.golang.org/grpc v1.83.0 // indirect
9292
google.golang.org/protobuf v1.36.12 // indirect
93-
gopkg.in/natefinch/lumberjack.v2 v2.2.1 // indirect
9493
)

integration/go.sum

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -662,8 +662,6 @@ gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8
662662
gopkg.in/check.v1 v1.0.0-20180628173108-788fd7840127/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
663663
gopkg.in/check.v1 v1.0.0-20190902080502-41f04d3bba15/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0=
664664
gopkg.in/errgo.v2 v2.1.0/go.mod h1:hNsd1EY+bozCKY1Ytp96fpM3vjJbqLJn88ws8XvfDNI=
665-
gopkg.in/natefinch/lumberjack.v2 v2.2.1 h1:bBRl1b0OH9s/DuPhuXpNl+VtCaJXFZ5/uEFST95x9zc=
666-
gopkg.in/natefinch/lumberjack.v2 v2.2.1/go.mod h1:YD8tP3GAjkrDg1eZH7EGmyESg/lsYskCTPBJVb9jqSc=
667665
gopkg.in/yaml.v2 v2.2.1/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
668666
gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=
669667
gopkg.in/yaml.v2 v2.2.4/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI=

pkg/backends/alb/client_test.go

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -652,8 +652,7 @@ func TestValidateAndStartUserRouterErrors(t *testing.T) {
652652
t.Fatal(err)
653653
}
654654
err = cl.validateAndStartUserRouter(backends.Backends{"tenant-a": member}, nil)
655-
var credErr *errors.InvalidALBOptionsError
656-
if !goerrors.As(err, &credErr) {
655+
if _, ok := goerrors.AsType[*errors.InvalidALBOptionsError](err); !ok {
657656
t.Fatalf("validateAndStartUserRouter() = %v, want InvalidALBOptionsError", err)
658657
}
659658
want := errors.NewErrInvalidUserRouterCreds("ur-edge")

pkg/backends/alb/errors/errors_test.go

Lines changed: 4 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -25,8 +25,7 @@ import (
2525
func TestNewErrInvalidALBOptions(t *testing.T) {
2626
t.Parallel()
2727
err := NewErrInvalidALBOptions("backend1")
28-
var e *InvalidALBOptionsError
29-
if !errors.As(err, &e) {
28+
if _, ok := errors.AsType[*InvalidALBOptionsError](err); !ok {
3029
t.Fatalf("expected *InvalidALBOptionsError, got %T", err)
3130
}
3231
if !strings.Contains(err.Error(), "backend1") {
@@ -37,8 +36,7 @@ func TestNewErrInvalidALBOptions(t *testing.T) {
3736
func TestNewErrInvalidPoolMemberName(t *testing.T) {
3837
t.Parallel()
3938
err := NewErrInvalidPoolMemberName("alb1", "missing")
40-
var e *InvalidALBOptionsError
41-
if !errors.As(err, &e) {
39+
if _, ok := errors.AsType[*InvalidALBOptionsError](err); !ok {
4240
t.Fatalf("expected *InvalidALBOptionsError, got %T", err)
4341
}
4442
msg := err.Error()
@@ -50,8 +48,7 @@ func TestNewErrInvalidPoolMemberName(t *testing.T) {
5048
func TestNewErrInvalidBackendName(t *testing.T) {
5149
t.Parallel()
5250
err := NewErrInvalidBackendName("alb1", "bad")
53-
var e *InvalidALBOptionsError
54-
if !errors.As(err, &e) {
51+
if _, ok := errors.AsType[*InvalidALBOptionsError](err); !ok {
5552
t.Fatalf("expected *InvalidALBOptionsError, got %T", err)
5653
}
5754
msg := err.Error()
@@ -63,8 +60,7 @@ func TestNewErrInvalidBackendName(t *testing.T) {
6360
func TestNewErrInvalidUserRouterCreds(t *testing.T) {
6461
t.Parallel()
6562
err := NewErrInvalidUserRouterCreds("alb1")
66-
var e *InvalidALBOptionsError
67-
if !errors.As(err, &e) {
63+
if _, ok := errors.AsType[*InvalidALBOptionsError](err); !ok {
6864
t.Fatalf("expected *InvalidALBOptionsError, got %T", err)
6965
}
7066
if !strings.Contains(err.Error(), "alb1") {

pkg/backends/alb/mech/ur/options/options_test.go

Lines changed: 2 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -80,8 +80,7 @@ func TestValidate(t *testing.T) {
8080
if err == nil {
8181
t.Fatal("expected invalid default backend error")
8282
}
83-
var ie *InvalidUserRouterOptionsError
84-
if !errors.As(err, &ie) {
83+
if _, ok := errors.AsType[*InvalidUserRouterOptionsError](err); !ok {
8584
t.Fatalf("Validate() = %T, want InvalidUserRouterOptionsError", err)
8685
}
8786

@@ -131,8 +130,7 @@ func TestNewErrInvalidUserRouterOptions(t *testing.T) {
131130
t.Parallel()
132131

133132
err := NewErrInvalidUserRouterOptions("edge")
134-
var ie *InvalidUserRouterOptionsError
135-
if !errors.As(err, &ie) {
133+
if _, ok := errors.AsType[*InvalidUserRouterOptionsError](err); !ok {
136134
t.Fatalf("error type = %T, want InvalidUserRouterOptionsError", err)
137135
}
138136
}

0 commit comments

Comments
 (0)