Logger: Add feature toggle for errors in HTTP request logs (#64425)
This commit is contained in:
Emil Tullstedt
@@ -1,111 +0,0 @@
|
||||
// Copyright 2013 Martini Authors
|
||||
// Copyright 2014 Unknwon
|
||||
//
|
||||
// Licensed under the Apache License, Version 2.0 (the "License"): you may
|
||||
// not use this file except in compliance with the License. You may obtain
|
||||
// a copy of the License at
|
||||
//
|
||||
// http://www.apache.org/licenses/LICENSE-2.0
|
||||
//
|
||||
// Unless required by applicable law or agreed to in writing, software
|
||||
// distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
|
||||
// WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
|
||||
// License for the specific language governing permissions and limitations
|
||||
// under the License.
|
||||
|
||||
package middleware
|
||||
|
||||
import (
|
||||
"net/http"
|
||||
"net/url"
|
||||
"time"
|
||||
|
||||
"github.com/grafana/grafana/pkg/infra/log"
|
||||
"github.com/grafana/grafana/pkg/services/contexthandler"
|
||||
contextmodel "github.com/grafana/grafana/pkg/services/contexthandler/model"
|
||||
"github.com/grafana/grafana/pkg/services/featuremgmt"
|
||||
"github.com/grafana/grafana/pkg/setting"
|
||||
"github.com/grafana/grafana/pkg/web"
|
||||
)
|
||||
|
||||
func Logger(cfg *setting.Cfg) web.Middleware {
|
||||
return func(next http.Handler) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
start := time.Now()
|
||||
|
||||
// we have to init the context with the counter here to update the request
|
||||
r = r.WithContext(log.InitCounter(r.Context()))
|
||||
// put the start time on context so we can measure it later.
|
||||
r = r.WithContext(log.InitstartTime(r.Context(), time.Now()))
|
||||
|
||||
rw := web.Rw(w, r)
|
||||
next.ServeHTTP(rw, r)
|
||||
|
||||
timeTaken := time.Since(start) / time.Millisecond
|
||||
duration := time.Since(start).String()
|
||||
ctx := contexthandler.FromContext(r.Context())
|
||||
if ctx != nil && ctx.PerfmonTimer != nil {
|
||||
ctx.PerfmonTimer.Observe(float64(timeTaken))
|
||||
}
|
||||
|
||||
status := rw.Status()
|
||||
if status == 200 || status == 304 {
|
||||
if !cfg.RouterLogging {
|
||||
return
|
||||
}
|
||||
}
|
||||
|
||||
if ctx != nil {
|
||||
logParams := []interface{}{
|
||||
"method", r.Method,
|
||||
"path", r.URL.Path,
|
||||
"status", status,
|
||||
"remote_addr", ctx.RemoteAddr(),
|
||||
"time_ms", int64(timeTaken),
|
||||
"duration", duration,
|
||||
"size", rw.Size(),
|
||||
"referer", SanitizeURL(ctx, r.Referer()),
|
||||
}
|
||||
|
||||
if cfg.IsFeatureToggleEnabled(featuremgmt.FlagDatabaseMetrics) {
|
||||
logParams = append(logParams, "db_call_count", log.TotalDBCallCount(ctx.Req.Context()))
|
||||
}
|
||||
|
||||
if handler, exist := routeOperationName(ctx.Req); exist {
|
||||
logParams = append(logParams, "handler", handler)
|
||||
}
|
||||
|
||||
if status >= 500 {
|
||||
ctx.Logger.Error("Request Completed", logParams...)
|
||||
} else {
|
||||
ctx.Logger.Info("Request Completed", logParams...)
|
||||
}
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
var sensitiveQueryStrings = [...]string{
|
||||
"auth_token",
|
||||
}
|
||||
|
||||
func SanitizeURL(ctx *contextmodel.ReqContext, s string) string {
|
||||
if s == "" {
|
||||
return s
|
||||
}
|
||||
|
||||
u, err := url.ParseRequestURI(s)
|
||||
if err != nil {
|
||||
ctx.Logger.Warn("Received invalid referer in request headers, removed for log forgery prevention")
|
||||
return ""
|
||||
}
|
||||
|
||||
// strip out sensitive query strings
|
||||
values := u.Query()
|
||||
for _, query := range sensitiveQueryStrings {
|
||||
values.Del(query)
|
||||
}
|
||||
u.RawQuery = values.Encode()
|
||||
|
||||
return u.String()
|
||||
}
|
||||
@@ -1,58 +0,0 @@
|
||||
package middleware
|
||||
|
||||
import (
|
||||
"testing"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
|
||||
"github.com/grafana/grafana/pkg/infra/log"
|
||||
contextmodel "github.com/grafana/grafana/pkg/services/contexthandler/model"
|
||||
)
|
||||
|
||||
func Test_sanitizeURL(t *testing.T) {
|
||||
type args struct {
|
||||
ctx *contextmodel.ReqContext
|
||||
s string
|
||||
}
|
||||
tests := []struct {
|
||||
name string
|
||||
args args
|
||||
want string
|
||||
}{
|
||||
{
|
||||
name: "Receiving empty string should return it",
|
||||
args: args{
|
||||
ctx: &contextmodel.ReqContext{
|
||||
Logger: log.New("test.logger"),
|
||||
},
|
||||
s: "",
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Receiving valid URL string should return it parsed",
|
||||
args: args{
|
||||
ctx: &contextmodel.ReqContext{
|
||||
Logger: log.New("test.logger"),
|
||||
},
|
||||
s: "https://grafana.com/",
|
||||
},
|
||||
want: "https://grafana.com/",
|
||||
},
|
||||
{
|
||||
name: "Receiving invalid URL string should return empty string",
|
||||
args: args{
|
||||
ctx: &contextmodel.ReqContext{
|
||||
Logger: log.New("test.logger"),
|
||||
},
|
||||
s: "this is not a valid URL",
|
||||
},
|
||||
want: "",
|
||||
},
|
||||
}
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
assert.Equalf(t, tt.want, SanitizeURL(tt.args.ctx, tt.args.s), "sanitizeURL(%v, %v)", tt.args.ctx, tt.args.s)
|
||||
})
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,174 @@
|
||||
// Copyright 2013 Martini Authors
|
||||
// Copyright 2014 Unknwon
|
||||
//
|
||||
// Licensed under the Apache License, Version 2.0 (the "License"): you may
|
||||
// not use this file except in compliance with the License. You may obtain
|
||||
// a copy of the License at
|
||||
//
|
||||
// http://www.apache.org/licenses/LICENSE-2.0
|
||||
//
|
||||
// Unless required by applicable law or agreed to in writing, software
|
||||
// distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
|
||||
// WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
|
||||
// License for the specific language governing permissions and limitations
|
||||
// under the License.
|
||||
|
||||
package loggermw
|
||||
|
||||
import (
|
||||
"errors"
|
||||
"fmt"
|
||||
"net/http"
|
||||
"net/url"
|
||||
"time"
|
||||
|
||||
"github.com/grafana/grafana/pkg/middleware"
|
||||
|
||||
"github.com/grafana/grafana/pkg/util/errutil"
|
||||
|
||||
"github.com/grafana/grafana/pkg/infra/log"
|
||||
"github.com/grafana/grafana/pkg/services/contexthandler"
|
||||
contextmodel "github.com/grafana/grafana/pkg/services/contexthandler/model"
|
||||
"github.com/grafana/grafana/pkg/services/featuremgmt"
|
||||
"github.com/grafana/grafana/pkg/setting"
|
||||
"github.com/grafana/grafana/pkg/web"
|
||||
)
|
||||
|
||||
type Logger interface {
|
||||
Middleware() web.Middleware
|
||||
}
|
||||
|
||||
type loggerImpl struct {
|
||||
cfg *setting.Cfg
|
||||
flags featuremgmt.FeatureToggles
|
||||
}
|
||||
|
||||
func Provide(
|
||||
cfg *setting.Cfg,
|
||||
flags featuremgmt.FeatureToggles,
|
||||
) Logger {
|
||||
return &loggerImpl{
|
||||
cfg: cfg,
|
||||
flags: flags,
|
||||
}
|
||||
}
|
||||
|
||||
func (l *loggerImpl) Middleware() web.Middleware {
|
||||
return func(next http.Handler) http.Handler {
|
||||
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
||||
start := time.Now()
|
||||
|
||||
// we have to init the context with the counter here to update the request
|
||||
r = r.WithContext(log.InitCounter(r.Context()))
|
||||
// put the start time on context so we can measure it later.
|
||||
r = r.WithContext(log.InitstartTime(r.Context(), time.Now()))
|
||||
|
||||
if l.flags.IsEnabled(featuremgmt.FlagUnifiedRequestLog) {
|
||||
r = r.WithContext(errutil.SetUnifiedLogging(r.Context()))
|
||||
}
|
||||
|
||||
rw := web.Rw(w, r)
|
||||
next.ServeHTTP(rw, r)
|
||||
|
||||
duration := time.Since(start)
|
||||
timeTaken := duration / time.Millisecond
|
||||
ctx := contexthandler.FromContext(r.Context())
|
||||
if ctx != nil && ctx.PerfmonTimer != nil {
|
||||
ctx.PerfmonTimer.Observe(float64(timeTaken))
|
||||
}
|
||||
|
||||
if ctx != nil {
|
||||
logParams, logger := l.prepareLogParams(ctx, duration)
|
||||
logger.LogFunc(ctx.Logger)("Request Completed", logParams...)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func (l *loggerImpl) prepareLogParams(c *contextmodel.ReqContext, duration time.Duration) ([]any, errutil.LogLevel) {
|
||||
rw := c.Resp
|
||||
r := c.Req
|
||||
|
||||
status := rw.Status()
|
||||
lvl := errutil.LevelInfo
|
||||
|
||||
switch {
|
||||
case status == http.StatusOK, status == http.StatusNotModified:
|
||||
if !l.cfg.RouterLogging {
|
||||
lvl = errutil.LevelNever
|
||||
}
|
||||
case status >= http.StatusInternalServerError:
|
||||
lvl = errutil.LevelError
|
||||
}
|
||||
|
||||
logParams := []any{
|
||||
"method", r.Method,
|
||||
"path", r.URL.Path,
|
||||
"status", status,
|
||||
"remote_addr", c.RemoteAddr(),
|
||||
"time_ms", int64(duration / time.Millisecond),
|
||||
"duration", duration.String(),
|
||||
"size", rw.Size(),
|
||||
}
|
||||
|
||||
referer, err := SanitizeURL(r.Referer())
|
||||
// We add an empty referer when there's a parsing error, hence this is before the err check.
|
||||
logParams = append(logParams, "referer", referer)
|
||||
if err != nil {
|
||||
logParams = append(logParams, "refererParsingErr", fmt.Errorf("received invalid referer in request headers, removed for log forgery prevention: %w", err))
|
||||
lvl = lvl.HighestOf(errutil.LevelWarn)
|
||||
}
|
||||
|
||||
if l.flags.IsEnabled(featuremgmt.FlagDatabaseMetrics) {
|
||||
logParams = append(logParams, "db_call_count", log.TotalDBCallCount(c.Req.Context()))
|
||||
}
|
||||
|
||||
if handler, exist := middleware.RouteOperationName(c.Req); exist {
|
||||
logParams = append(logParams, "handler", handler)
|
||||
}
|
||||
|
||||
logParams = append(logParams, errorLogParams(c.Error)...)
|
||||
|
||||
return logParams, lvl
|
||||
}
|
||||
|
||||
func errorLogParams(err error) []any {
|
||||
if err == nil {
|
||||
return nil
|
||||
}
|
||||
|
||||
var gfErr errutil.Error
|
||||
if !errors.As(err, &gfErr) {
|
||||
return []any{"error", err.Error()}
|
||||
}
|
||||
|
||||
return []any{
|
||||
"errorReason", gfErr.Reason,
|
||||
"errorMessageID", gfErr.MessageID,
|
||||
"error", gfErr.LogMessage,
|
||||
}
|
||||
}
|
||||
|
||||
var sensitiveQueryStrings = [...]string{
|
||||
"auth_token",
|
||||
}
|
||||
|
||||
func SanitizeURL(s string) (string, error) {
|
||||
if s == "" {
|
||||
return s, nil
|
||||
}
|
||||
|
||||
u, err := url.ParseRequestURI(s)
|
||||
if err != nil {
|
||||
return "", fmt.Errorf("failed to sanitize URL")
|
||||
}
|
||||
|
||||
// strip out sensitive query strings
|
||||
values := u.Query()
|
||||
for _, query := range sensitiveQueryStrings {
|
||||
values.Del(query)
|
||||
}
|
||||
u.RawQuery = values.Encode()
|
||||
|
||||
return u.String(), nil
|
||||
}
|
||||
@@ -0,0 +1,213 @@
|
||||
package loggermw
|
||||
|
||||
import (
|
||||
"fmt"
|
||||
"net/http"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
|
||||
contextmodel "github.com/grafana/grafana/pkg/services/contexthandler/model"
|
||||
"github.com/grafana/grafana/pkg/services/featuremgmt"
|
||||
"github.com/grafana/grafana/pkg/setting"
|
||||
"github.com/grafana/grafana/pkg/util/errutil"
|
||||
"github.com/grafana/grafana/pkg/web"
|
||||
)
|
||||
|
||||
func Test_sanitizeURL(t *testing.T) {
|
||||
tests := []struct {
|
||||
name string
|
||||
input string
|
||||
want string
|
||||
expectError bool
|
||||
}{
|
||||
{
|
||||
name: "Receiving empty string should return it",
|
||||
input: "",
|
||||
want: "",
|
||||
},
|
||||
{
|
||||
name: "Receiving valid URL string should return it parsed",
|
||||
input: "https://grafana.com/",
|
||||
want: "https://grafana.com/",
|
||||
},
|
||||
{
|
||||
name: "Receiving invalid URL string should return empty string",
|
||||
input: "this is not a valid URL",
|
||||
want: "",
|
||||
expectError: true,
|
||||
},
|
||||
}
|
||||
for _, tt := range tests {
|
||||
t.Run(tt.name, func(t *testing.T) {
|
||||
url, err := SanitizeURL(tt.input)
|
||||
if tt.expectError {
|
||||
assert.Error(t, err)
|
||||
} else {
|
||||
assert.NoError(t, err)
|
||||
}
|
||||
assert.Equalf(t, tt.want, url, "SanitizeURL(%v)", tt.input)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func Test_prepareLog(t *testing.T) {
|
||||
type opts struct {
|
||||
Features []any
|
||||
RouterLogging bool
|
||||
}
|
||||
|
||||
grafanaFlavoredErr := errutil.NewBase(errutil.StatusNotFound, "test.notFound").Errorf("got error")
|
||||
|
||||
tests := []struct {
|
||||
name string
|
||||
opts opts
|
||||
req *http.Request
|
||||
response web.ResponseWriter
|
||||
duration time.Duration
|
||||
error error
|
||||
|
||||
expectFields map[string]any
|
||||
expectAbsence map[string]struct{}
|
||||
expectedLevel errutil.LogLevel
|
||||
}{
|
||||
{
|
||||
name: "base case",
|
||||
req: mustRequest(http.NewRequest(http.MethodGet, "/", nil)),
|
||||
response: mockResponseWriter{},
|
||||
|
||||
expectFields: map[string]any{
|
||||
"method": "GET",
|
||||
"path": "/",
|
||||
"status": 0,
|
||||
"remote_addr": "",
|
||||
"time_ms": 0,
|
||||
"duration": "0s",
|
||||
"size": 0,
|
||||
"referer": "",
|
||||
},
|
||||
expectAbsence: map[string]struct{}{
|
||||
"error": {},
|
||||
"db_call_count": {},
|
||||
},
|
||||
},
|
||||
{
|
||||
name: "base case",
|
||||
req: mustRequest(http.NewRequest(http.MethodGet, "/", nil)),
|
||||
response: mockResponseWriter{},
|
||||
|
||||
expectFields: map[string]any{
|
||||
"method": "GET",
|
||||
"path": "/",
|
||||
"status": 0,
|
||||
"remote_addr": "",
|
||||
"time_ms": 0,
|
||||
"duration": "0s",
|
||||
"size": 0,
|
||||
"referer": "",
|
||||
},
|
||||
expectAbsence: map[string]struct{}{
|
||||
"error": {},
|
||||
"db_call_count": {},
|
||||
},
|
||||
expectedLevel: errutil.LevelInfo,
|
||||
},
|
||||
{
|
||||
name: "regular Go error",
|
||||
req: mustRequest(http.NewRequest(http.MethodGet, "/", nil)),
|
||||
response: mockResponseWriter{
|
||||
status: http.StatusInternalServerError,
|
||||
},
|
||||
error: fmt.Errorf("got an error"),
|
||||
|
||||
expectFields: map[string]any{
|
||||
"status": http.StatusInternalServerError,
|
||||
"error": "got an error",
|
||||
},
|
||||
expectAbsence: map[string]struct{}{
|
||||
"errorReason": {},
|
||||
"errorMessageID": {},
|
||||
},
|
||||
expectedLevel: errutil.LevelError,
|
||||
},
|
||||
{
|
||||
name: "Grafana-style error",
|
||||
req: mustRequest(http.NewRequest(http.MethodGet, "/", nil)),
|
||||
response: mockResponseWriter{
|
||||
status: http.StatusNotFound,
|
||||
},
|
||||
error: grafanaFlavoredErr,
|
||||
expectFields: map[string]any{
|
||||
"status": http.StatusNotFound,
|
||||
"error": "got error",
|
||||
"errorReason": errutil.StatusNotFound,
|
||||
"errorMessageID": "test.notFound",
|
||||
},
|
||||
expectedLevel: errutil.LevelInfo,
|
||||
},
|
||||
}
|
||||
|
||||
for _, tc := range tests {
|
||||
t.Run(tc.name, func(t *testing.T) {
|
||||
cfg := setting.NewCfg()
|
||||
cfg.RouterLogging = tc.opts.RouterLogging
|
||||
l := Provide(cfg, featuremgmt.WithFeatures(tc.opts.Features...))
|
||||
|
||||
service, ok := l.(*loggerImpl)
|
||||
require.Truef(t, ok, "expected service to be of type (*loggerImpl), got (%T)", l)
|
||||
|
||||
c := &contextmodel.ReqContext{
|
||||
Context: &web.Context{
|
||||
Req: tc.req,
|
||||
Resp: tc.response,
|
||||
},
|
||||
Error: tc.error,
|
||||
}
|
||||
|
||||
logs, level := service.prepareLogParams(c, tc.duration)
|
||||
|
||||
require.Zero(t, len(logs)%2, "Each key must have an accompanying value")
|
||||
kv := map[any]any{}
|
||||
for i := 0; i < len(logs); i += 2 {
|
||||
kv[logs[i]] = logs[i+1]
|
||||
}
|
||||
|
||||
for key, val := range tc.expectFields {
|
||||
assert.Contains(t, kv, key)
|
||||
if val != nil {
|
||||
assert.EqualValues(t, val, kv[key])
|
||||
}
|
||||
}
|
||||
for key := range tc.expectAbsence {
|
||||
assert.NotContains(t, kv, key)
|
||||
}
|
||||
|
||||
if tc.expectedLevel != "" {
|
||||
assert.Equal(t, tc.expectedLevel, level)
|
||||
}
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
func mustRequest(r *http.Request, err error) *http.Request {
|
||||
if err != nil {
|
||||
panic(fmt.Errorf("expected no error when creating request, got: %w", err))
|
||||
}
|
||||
return r
|
||||
}
|
||||
|
||||
type mockResponseWriter struct {
|
||||
web.ResponseWriter
|
||||
|
||||
status int
|
||||
size int
|
||||
}
|
||||
|
||||
func (m mockResponseWriter) Status() int {
|
||||
return m.status
|
||||
}
|
||||
func (m mockResponseWriter) Size() int {
|
||||
return m.size
|
||||
}
|
||||
@@ -63,7 +63,7 @@ func RequestMetrics(features featuremgmt.FeatureToggles) web.Middleware {
|
||||
|
||||
handler := "unknown"
|
||||
// TODO: do not depend on web.Context from the future
|
||||
if routeOperation, exists := routeOperationName(web.FromContext(r.Context()).Req); exists {
|
||||
if routeOperation, exists := RouteOperationName(web.FromContext(r.Context()).Req); exists {
|
||||
handler = routeOperation
|
||||
} else {
|
||||
// if grafana does not recognize the handler and returns 404 we should register it as `notfound`
|
||||
|
||||
@@ -34,7 +34,7 @@ func TestCanGetRouteNameFromContext(t *testing.T) {
|
||||
|
||||
assert.NoError(t, err)
|
||||
|
||||
handler, _ := routeOperationName(req)
|
||||
handler, _ := RouteOperationName(req)
|
||||
assert.Equal(t, tc.expected, handler)
|
||||
}
|
||||
}
|
||||
@@ -46,13 +46,13 @@ func TestOperationNameCanOnlyBeSetOnce(t *testing.T) {
|
||||
req = addRouteNameToContext(req, "first")
|
||||
|
||||
// check that the operation name is set correctly
|
||||
value, exists := routeOperationName(req)
|
||||
value, exists := RouteOperationName(req)
|
||||
assert.True(t, exists, "route name should exist")
|
||||
assert.Equal(t, "first", value)
|
||||
|
||||
// check that it cannot be overwritten
|
||||
req = addRouteNameToContext(req, "second")
|
||||
value, exists = routeOperationName(req)
|
||||
value, exists = RouteOperationName(req)
|
||||
assert.True(t, exists, "route name should exist")
|
||||
assert.Equal(t, "first", value)
|
||||
}
|
||||
|
||||
@@ -33,7 +33,7 @@ func ProvideRouteOperationName(name string) web.Handler {
|
||||
|
||||
func addRouteNameToContext(req *http.Request, operationName string) *http.Request {
|
||||
// don't set route name if it's set
|
||||
if _, exists := routeOperationName(req); exists {
|
||||
if _, exists := RouteOperationName(req); exists {
|
||||
return req
|
||||
}
|
||||
|
||||
@@ -55,8 +55,8 @@ var unnamedHandlers = []struct {
|
||||
{handler: "/debug/pprof-handlers", pathPattern: regexp.MustCompile("^/debug/pprof")},
|
||||
}
|
||||
|
||||
// routeOperationName receives the route operation name from context, if set.
|
||||
func routeOperationName(req *http.Request) (string, bool) {
|
||||
// RouteOperationName receives the route operation name from context, if set.
|
||||
func RouteOperationName(req *http.Request) (string, bool) {
|
||||
if val := req.Context().Value(routeOperationNameKey); val != nil {
|
||||
op, ok := val.(string)
|
||||
return op, ok
|
||||
@@ -90,7 +90,7 @@ func RequestTracing(tracer tracing.Tracer) web.Middleware {
|
||||
// Only call span.Finish when a route operation name have been set,
|
||||
// meaning that not set the span would not be reported.
|
||||
// TODO: do not depend on web.Context from the future
|
||||
if routeOperation, exists := routeOperationName(web.FromContext(req.Context()).Req); exists {
|
||||
if routeOperation, exists := RouteOperationName(web.FromContext(req.Context()).Req); exists {
|
||||
defer span.End()
|
||||
span.SetName(fmt.Sprintf("HTTP %s %s", req.Method, routeOperation))
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user