Skip to content

Commit f8ebb09

Browse files
moshloopmoshloop
committed
feat(http): enhance http logging with context-aware access logs and formatters
Adds context-aware HTTP logging via request context, new access log middleware with single-line output, form URL encoded formatter for request bodies, NO_COLOR environment variable support, and improved request/response logging configuration through TraceConfigFromString for flexible trace levels.
1 parent 11fd585 commit f8ebb09

11 files changed

Lines changed: 502 additions & 37 deletions

File tree

‎console/console.go‎

Lines changed: 23 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,8 @@ package console
22

33
import (
44
"fmt"
5+
"os"
6+
"strings"
57

68
"github.com/flanksource/commons/is"
79
"github.com/flanksource/commons/logger"
@@ -49,9 +51,29 @@ var (
4951
)
5052

5153
var (
52-
isTTY = is.TTY()
54+
isTTY = is.TTY() && !IsNoColor()
5355
)
5456

57+
func IsNoColor() bool {
58+
if os.Getenv("NO_COLOR") != "" {
59+
return true
60+
}
61+
if v := strings.ToLower(os.Getenv("COLOR")); v == "no" || v == "false" {
62+
return true
63+
}
64+
if os.Getenv("TERM") == "dumb" {
65+
return true
66+
}
67+
68+
// also scan os.Args for --no-color in case env vars are not set but the flag is used (e.g., in tests)
69+
for _, arg := range os.Args[1:] {
70+
if arg != "--no-color=false" && (arg == "--no-color" || arg == "-no-color") {
71+
return true
72+
}
73+
}
74+
return false
75+
}
76+
5577
func ColorOff() {
5678
isTTY = false
5779
}

‎context/context.go‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -154,6 +154,29 @@ type Context struct {
154154
tracer trace.Tracer
155155
}
156156

157+
type loggerKey struct{}
158+
159+
func (c Context) GetLogger() logger.Logger {
160+
if c.Logger != nil {
161+
return c.Logger
162+
}
163+
return logger.GetLogger()
164+
}
165+
166+
func (c Context) Value(key any) any {
167+
if _, ok := key.(loggerKey); ok {
168+
return c.Logger
169+
}
170+
return c.Context.Value(key)
171+
}
172+
173+
func LoggerFromContext(ctx gocontext.Context) logger.Logger {
174+
if l, ok := ctx.Value(loggerKey{}).(logger.Logger); ok && l != nil {
175+
return l
176+
}
177+
return logger.GetLogger()
178+
}
179+
157180
func (c Context) String() string {
158181
s := []string{}
159182
if c.IsTrace() {

‎go.sum‎

Lines changed: 153 additions & 0 deletions
Large diffs are not rendered by default.

‎http/client.go‎

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -517,7 +517,15 @@ func (c *Client) AWSEndpoint(endpoint string) *Client {
517517
// })
518518
func (c *Client) OAuth(config middlewares.OauthConfig) *Client {
519519
if c.harCollector != nil {
520-
config.TokenTransport = c.harCollector.Middleware()
520+
existing := config.TokenTransport
521+
harMiddleware := c.harCollector.Middleware()
522+
if existing != nil {
523+
config.TokenTransport = func(rt http.RoundTripper) http.RoundTripper {
524+
return existing(harMiddleware(rt))
525+
}
526+
} else {
527+
config.TokenTransport = harMiddleware
528+
}
521529
}
522530
c.Use(middlewares.NewOauthTransport(config).RoundTripper)
523531
return c

‎http/middlewares/accesslog.go‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
package middlewares
2+
3+
import (
4+
"fmt"
5+
"net/http"
6+
"time"
7+
)
8+
9+
func NewAccessLog() Middleware {
10+
return func(rt http.RoundTripper) http.RoundTripper {
11+
return RoundTripperFunc(func(req *http.Request) (*http.Response, error) {
12+
start := time.Now()
13+
resp, err := rt.RoundTrip(req)
14+
elapsed := time.Since(start)
15+
if err != nil {
16+
fmt.Printf("%s %s error %s\n", req.Method, req.URL, elapsed.Truncate(time.Millisecond))
17+
return nil, err
18+
}
19+
fmt.Printf("%s %s %d %s\n", req.Method, req.URL, resp.StatusCode, elapsed.Truncate(time.Millisecond))
20+
return resp, nil
21+
})
22+
}
23+
}

‎http/middlewares/logger.go‎

Lines changed: 136 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -1,27 +1,148 @@
11
package middlewares
22

33
import (
4+
"bytes"
5+
"encoding/json"
6+
"fmt"
7+
"io"
48
"net/http"
9+
"net/url"
10+
"strings"
11+
"time"
512

13+
"github.com/flanksource/clicky"
14+
"github.com/flanksource/clicky/api"
15+
"github.com/flanksource/commons/console"
16+
commonsCtx "github.com/flanksource/commons/context"
617
"github.com/flanksource/commons/logger"
718
"github.com/flanksource/commons/logger/httpretty"
819
)
920

10-
func NewLogger(config TraceConfig) Middleware {
11-
l := &httpretty.Logger{
12-
Time: config.Timing,
13-
TLS: config.TLS,
14-
RequestHeader: config.Headers,
15-
RequestBody: config.Body,
16-
ResponseHeader: config.ResponseHeaders,
17-
ResponseBody: config.Body,
18-
Auth: config.Auth,
19-
Colors: true, // erase line if you don't like colors
20-
Formatters: []httpretty.Formatter{&httpretty.JSONFormatter{}},
21-
}
22-
23-
l.SkipHeader(logger.SensitiveHeaders)
21+
type jsonFormatter struct{}
22+
23+
func (j *jsonFormatter) Match(mediatype string) bool {
24+
return strings.Contains(mediatype, "json")
25+
}
26+
27+
func (j *jsonFormatter) Format(w io.Writer, src []byte) error {
28+
if !json.Valid(src) {
29+
if err := json.Unmarshal(src, &json.RawMessage{}); err != nil {
30+
return err
31+
}
32+
}
33+
var indented bytes.Buffer
34+
if err := json.Indent(&indented, src, "", " "); err != nil {
35+
return err
36+
}
37+
fmt.Fprint(w, api.CodeBlock("json", indented.String()).ANSI())
38+
return nil
39+
}
40+
41+
type formURLEncodedFormatter struct{}
42+
43+
func (f *formURLEncodedFormatter) Match(mediatype string) bool {
44+
return mediatype == "application/x-www-form-urlencoded"
45+
}
46+
47+
func (f *formURLEncodedFormatter) Format(w io.Writer, src []byte) error {
48+
values, err := url.ParseQuery(string(src))
49+
if err != nil {
50+
return err
51+
}
52+
m := make(map[string]string)
53+
for k, v := range values {
54+
m[k] = strings.Join(v, ",")
55+
}
56+
fmt.Fprint(w, clicky.Map(m).ANSI())
57+
return nil
58+
}
59+
60+
func getLogger(req *http.Request) logger.Logger {
61+
if req == nil || req.Context() == nil {
62+
return logger.GetLogger()
63+
}
64+
return commonsCtx.LoggerFromContext(req.Context())
65+
}
66+
67+
func newContextLogger(config TraceConfig) Middleware {
68+
return func(rt http.RoundTripper) http.RoundTripper {
69+
l := &httpretty.Logger{
70+
TLS: config.TLS,
71+
RequestHeader: config.Headers,
72+
RequestBody: config.Body,
73+
ResponseHeader: config.ResponseHeaders,
74+
ResponseBody: config.Response,
75+
Auth: config.Auth,
76+
Colors: true,
77+
Formatters: []httpretty.Formatter{&jsonFormatter{}, &formURLEncodedFormatter{}},
78+
}
79+
l.SkipHeader(logger.SensitiveHeaders)
80+
81+
var buf bytes.Buffer
82+
l.SetOutput(&buf)
83+
inner := l.RoundTripper(rt)
84+
85+
return RoundTripperFunc(func(req *http.Request) (*http.Response, error) {
86+
buf.Reset()
87+
start := time.Now()
88+
resp, err := inner.RoundTrip(req)
89+
elapsed := time.Since(start)
90+
if buf.Len() > 0 {
91+
msg := buf.String()
92+
if config.Timing {
93+
suffix := ""
94+
if resp != nil {
95+
suffix = fmt.Sprintf(" %d", resp.StatusCode)
96+
} else if err != nil {
97+
suffix = " error"
98+
}
99+
suffix += fmt.Sprintf(" %s", elapsed.Truncate(time.Millisecond))
100+
101+
lines := strings.Split(msg, "\n")
102+
for i, line := range lines {
103+
if strings.Contains(line, req.Method) {
104+
lines[i] = strings.TrimRight(line, "\r\n") + suffix
105+
break
106+
}
107+
}
108+
msg = strings.Join(lines, "\n")
109+
}
110+
getLogger(req).Infof(strings.TrimSpace(msg))
111+
}
112+
return resp, err
113+
})
114+
}
115+
}
116+
117+
func statusColor(code int) func(string, ...interface{}) string {
118+
if code >= 200 && code < 300 {
119+
return console.Greenf
120+
} else if code >= 400 {
121+
return console.Redf
122+
}
123+
return console.Yellowf
124+
}
125+
126+
func newContextAccessLog() Middleware {
24127
return func(rt http.RoundTripper) http.RoundTripper {
25-
return logger.NewHttpLogger(logger.GetLogger(), rt)
128+
return RoundTripperFunc(func(req *http.Request) (*http.Response, error) {
129+
start := time.Now()
130+
resp, err := rt.RoundTrip(req)
131+
elapsed := time.Since(start)
132+
log := getLogger(req)
133+
if err != nil {
134+
log.Infof("%s %s %s %s", console.Bluef(req.Method), console.Yellowf("%s", req.URL), console.Redf("error"), elapsed.Truncate(time.Millisecond))
135+
return nil, err
136+
}
137+
log.Infof("%s %s %s %s", console.Bluef(req.Method), console.Yellowf("%s", req.URL), statusColor(resp.StatusCode)("%d", resp.StatusCode), elapsed.Truncate(time.Millisecond))
138+
return resp, nil
139+
})
140+
}
141+
}
142+
143+
func NewLogger(config TraceConfig) Middleware {
144+
if config.AccessLog {
145+
return newContextAccessLog()
26146
}
147+
return newContextLogger(config)
27148
}

‎http/middlewares/trace.go‎

Lines changed: 81 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,8 +4,10 @@ import (
44
"bytes"
55
"io"
66
netHttp "net/http"
7+
"strings"
78

89
"github.com/flanksource/commons/logger"
10+
"github.com/flanksource/commons/properties"
911
"go.opentelemetry.io/otel"
1012
"go.opentelemetry.io/otel/attribute"
1113
"go.opentelemetry.io/otel/codes"
@@ -58,6 +60,85 @@ type TraceConfig struct {
5860

5961
// Auth controls whether auth middleware (AWS SigV4, OAuth) logs trace messages
6062
Auth bool
63+
64+
// AccessLog enables single-line access log output: METHOD URL STATUS DURATION
65+
AccessLog bool
66+
}
67+
68+
var traceAll = TraceConfig{
69+
MaxBodyLength: 4096,
70+
Body: true,
71+
Response: true,
72+
QueryParam: true,
73+
Headers: true,
74+
ResponseHeaders: true,
75+
TLS: true,
76+
Timing: true,
77+
Auth: true,
78+
}
79+
80+
var traceHeaders = TraceConfig{
81+
QueryParam: true,
82+
Headers: true,
83+
ResponseHeaders: true,
84+
Timing: true,
85+
Auth: true,
86+
}
87+
88+
func TraceConfigFromString(s string) TraceConfig {
89+
switch s {
90+
case "access":
91+
return TraceConfig{AccessLog: true}
92+
case "debug", "headers":
93+
return traceHeaders
94+
case "body":
95+
config := traceHeaders
96+
config.Body = true
97+
return config
98+
case "trace", "all", "response":
99+
return traceAll
100+
}
101+
102+
config := TraceConfig{}
103+
if strings.Contains(s, "all") {
104+
config = traceAll
105+
}
106+
if strings.Contains(s, "headers") {
107+
config.Headers = true
108+
}
109+
if strings.Contains(s, "body") {
110+
config.Body = true
111+
}
112+
if strings.Contains(s, "response") {
113+
config.Response = true
114+
}
115+
if strings.Contains(s, "responseHeaders") {
116+
config.ResponseHeaders = true
117+
}
118+
if strings.Contains(s, "queryParam") {
119+
config.QueryParam = true
120+
}
121+
if strings.Contains(s, "tls") {
122+
config.TLS = true
123+
}
124+
if strings.Contains(s, "timing") {
125+
config.Timing = true
126+
}
127+
if strings.Contains(s, "auth") {
128+
config.Auth = true
129+
}
130+
if strings.Contains(s, "access") {
131+
config.AccessLog = true
132+
}
133+
if properties.On(false, "http.body.disabled") {
134+
config.Body = false
135+
config.Response = false
136+
}
137+
if properties.On(false, "http.headers.disabled") {
138+
config.Headers = false
139+
config.ResponseHeaders = false
140+
}
141+
return config
61142
}
62143

63144
type traceTransport struct {

‎logger/default.go‎

Lines changed: 1 addition & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -205,14 +205,7 @@ func IsTraceEnabled() bool {
205205
return currentLogger.IsTraceEnabled()
206206
}
207207

208-
// IsLevelEnabled returns true if the specified verbosity level is enabled.
209-
//
210-
// Example:
211-
//
212-
// if logger.IsLevelEnabled(3) {
213-
// // Perform expensive operation only if logging at level 3
214-
// }
215-
func IsLevelEnabled(level int) bool {
208+
func IsLevelEnabled(level any) bool {
216209
return currentLogger.V(level).Enabled()
217210
}
218211

0 commit comments

Comments
 (0)