From c7fda81e7119f53fa202a299564567e835b35a8c Mon Sep 17 00:00:00 2001 From: Yash Sharma Date: Thu, 9 Jul 2020 14:28:03 +0530 Subject: [PATCH 1/4] Add Request Logging in Thanos for HTTP Calls in server side Review changes * Rename the logging middleware * Renamed bunch of files Signed-off-by: Yash Sharma Registered the request logging in query component Signed-off-by: Yash Sharma Modified the middleware to use the go-kit levels * Also altered the middleware API to use logging when called, rather than at time of registration Signed-off-by: Yash Sharma Remove option to log the request details into a log file Signed-off-by: Yash Sharma Made the logger a part of the logger middleware Signed-off-by: Yash Sharma Added some changes to use logger implicitly Signed-off-by: Yash Sharma Removed logging from the query UI Signed-off-by: Yash Sharma Added Request Logging in rule component * Removed request logging from the bucket component Signed-off-by: Yash Sharma Fixed a bug of multiple logging * Due to adding of contextual fields in the implicit logger. * Now we create a copy of the implicit logger before adding the contextual fields, so that every time we get a fresh set of loggers Signed-off-by: Yash Sharma Suggestions from reviewers * Renamed response_writer.go to utils.go * Moved all interfaces to option.go Signed-off-by: Yash Sharma renamed files and added a util file for serving http utilities Signed-off-by: Yash Sharma added copyright headers Signed-off-by: Yash Sharma Added a changelog Signed-off-by: Yash Sharma Added changes as suggested by reviewer * Rename ServerMiddleware to HTTPServerMiddleware * Add comments Signed-off-by: Yash Sharma added protocol field and curated the start message Signed-off-by: Yash Sharma nitpickings of request logger Signed-off-by: Yash Sharma added some changes to request logging http Signed-off-by: Yash Sharma nitpickings * changed the name of package_http to utils * made the postcall method private Signed-off-by: Yash Sharma More Nitpickings * Changed the level of logging from Info to Debug * Used contextual logging as less as possible * Return the protocol embedded in the constructor itself * Removed the logging of the request body Signed-off-by: Yash Sharma Added some more fields for making it compatible to grpc logging Signed-off-by: Yash Sharma Nitpickings * Renamed ResponseWriter with ResponseWriterWithStatus * Remove an unused function * nitpickings Signed-off-by: Yash Sharma Modified the Decision function to ENUM based decider * Currently 3 types of logging is enabled - * NoLogCall * LogStartAndFinishCall * LogFinishCall Signed-off-by: Yash Sharma changelog nits Signed-off-by: Yash Sharma added a flag in querier Signed-off-by: Yash Sharma nitpickings Signed-off-by: Yash Sharma --- CHANGELOG.md | 3 +- cmd/thanos/compact.go | 8 ++- cmd/thanos/query.go | 13 +++- cmd/thanos/rule.go | 9 ++- cmd/thanos/tools_bucket.go | 10 +++- pkg/api/api.go | 9 ++- pkg/api/api_test.go | 4 +- pkg/api/blocks/v1.go | 7 ++- pkg/api/query/v1.go | 7 ++- pkg/api/rule/v1.go | 7 ++- pkg/logging/http.go | 65 ++++++++++++++++++++ pkg/logging/options.go | 120 +++++++++++++++++++++++++++++++++++++ pkg/server/http/utils.go | 32 ++++++++++ 13 files changed, 276 insertions(+), 18 deletions(-) create mode 100644 pkg/logging/http.go create mode 100644 pkg/logging/options.go create mode 100644 pkg/server/http/utils.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 5dea7f1315..9e20d9eb19 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,7 +27,8 @@ We use *breaking* word for marking changes that are not backward compatible (rel ### Added -- [#2832](https://github.com/thanos-io/thanos/pull/2832) ui: React: Add runtime and build info page. +- [#2849](https://github.com/thanos-io/thanos/pull/2849) Query, Ruler : Added request logging for HTTP server side. +- [#2832](https://github.com/thanos-io/thanos/pull/2832) ui: React: Add runtime and build info page - [#2305](https://github.com/thanos-io/thanos/pull/2305) Receive,Sidecar,Ruler: Propagate correct (stricter) MinTime for no-block TSDBs. - [#2926](https://github.com/thanos-io/thanos/pull/2926) API: Add new blocks HTTP API to serve blocks metadata. The status endpoints (`/api/v1/status/flags`, `/api/v1/status/runtimeinfo` and `/api/v1/status/buildinfo`) are now available on all components with a HTTP API. - [#2892](https://github.com/thanos-io/thanos/pull/2892) Receive: Receiver fails when the initial upload fails. diff --git a/cmd/thanos/compact.go b/cmd/thanos/compact.go index 4810c4ab4d..07383f19a6 100644 --- a/cmd/thanos/compact.go +++ b/cmd/thanos/compact.go @@ -31,6 +31,7 @@ import ( "github.com/thanos-io/thanos/pkg/extflag" "github.com/thanos-io/thanos/pkg/extprom" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" + "github.com/thanos-io/thanos/pkg/logging" "github.com/thanos-io/thanos/pkg/objstore/client" "github.com/thanos-io/thanos/pkg/prober" "github.com/thanos-io/thanos/pkg/runutil" @@ -400,7 +401,12 @@ func runCompact( global.Register(r, ins) api := blocksAPI.NewBlocksAPI(logger, conf.label, flagsMap) - api.Register(r.WithPrefix("/api/v1"), tracer, logger, ins) + // Configure Request Logging for HTTP calls. + opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + return logging.NoLogCall + })} + logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) + api.Register(r.WithPrefix("/api/v1"), tracer, logger, ins, logMiddleware) // Separate fetcher for global view. // TODO(bwplotka): Allow Bucket UI to visualize the state of the block as well. diff --git a/cmd/thanos/query.go b/cmd/thanos/query.go index 4a25cf4dfe..daf5abda5c 100644 --- a/cmd/thanos/query.go +++ b/cmd/thanos/query.go @@ -32,6 +32,7 @@ import ( "github.com/thanos-io/thanos/pkg/extgrpc" "github.com/thanos-io/thanos/pkg/extprom" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" + "github.com/thanos-io/thanos/pkg/logging" "github.com/thanos-io/thanos/pkg/prober" "github.com/thanos-io/thanos/pkg/query" "github.com/thanos-io/thanos/pkg/rules" @@ -61,6 +62,8 @@ func registerQuery(m map[string]setupFunc, app *kingpin.Application) { webExternalPrefix := cmd.Flag("web.external-prefix", "Static prefix for all HTML links and redirect URLs in the UI query web interface. Actual endpoints are still served on / or the web.route-prefix. This allows thanos UI to be served behind a reverse proxy that strips a URL sub-path.").Default("").String() webPrefixHeaderName := cmd.Flag("web.prefix-header", "Name of HTTP request header used for dynamic prefixing of UI links and redirects. This option is ignored if web.external-prefix argument is set. Security risk: enable this option only if a reverse proxy in front of thanos is resetting the header. The --web.prefix-header=X-Forwarded-Prefix option can be useful, for example, if Thanos UI is served via Traefik reverse proxy with PathPrefixStrip option enabled, which sends the stripped prefix value in X-Forwarded-Prefix header. This allows thanos UI to be served on a sub-path.").Default("").String() + requestLoggingDecision := cmd.Flag("log.request.decision", "Request Logging for logging the start and end of requests. LogFinishCall is enabled by default. LogFinishCall : Logs the finish call of the requests. LogStartAndFinishCall : Logs the start and finish call of the requests. NoLogCall : Disable request logging.").Default("LogFinishCall").Enum("NoLogCall", "LogFinishCall", "LogStartAndFinishCall") + queryTimeout := modelDuration(cmd.Flag("query.timeout", "Maximum time to process query by query node."). Default("2m")) @@ -156,6 +159,7 @@ func registerQuery(m map[string]setupFunc, app *kingpin.Application) { logger, reg, tracer, + *requestLoggingDecision, *grpcBindAddr, time.Duration(*grpcGracePeriod), *grpcCert, @@ -201,6 +205,7 @@ func runQuery( logger log.Logger, reg *prometheus.Registry, tracer opentracing.Tracer, + requestLoggingDecision string, grpcBindAddr string, grpcGracePeriod time.Duration, grpcCert string, @@ -401,6 +406,12 @@ func runQuery( router = router.WithPrefix(webRoutePrefix) } + // Configure Request Logging for HTTP calls. + opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + return logging.LogDecision[requestLoggingDecision] + })} + logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) + ins := extpromhttp.NewInstrumentationMiddleware(reg) // TODO(bplotka in PR #513 review): pass all flags, not only the flags needed by prefix rewriting. ui.NewQueryUI(logger, reg, stores, webExternalPrefix, webPrefixHeaderName).Register(router, ins) @@ -422,7 +433,7 @@ func runQuery( maxConcurrentQueries, ) - api.Register(router.WithPrefix("/api/v1"), tracer, logger, ins) + api.Register(router.WithPrefix("/api/v1"), tracer, logger, ins, logMiddleware) srv := httpserver.New(logger, reg, comp, httpProbe, httpserver.WithListen(httpBindAddr), diff --git a/cmd/thanos/rule.go b/cmd/thanos/rule.go index 6539497ae3..8d7cf430ff 100644 --- a/cmd/thanos/rule.go +++ b/cmd/thanos/rule.go @@ -40,6 +40,7 @@ import ( "github.com/thanos-io/thanos/pkg/extprom" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" http_util "github.com/thanos-io/thanos/pkg/http" + "github.com/thanos-io/thanos/pkg/logging" "github.com/thanos-io/thanos/pkg/objstore/client" "github.com/thanos-io/thanos/pkg/prober" "github.com/thanos-io/thanos/pkg/promclient" @@ -586,11 +587,17 @@ func runRule( ins := extpromhttp.NewInstrumentationMiddleware(reg) + // Configure Request Logging for HTTP calls. + opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + return logging.NoLogCall + })} + logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) + // TODO(bplotka in PR #513 review): pass all flags, not only the flags needed by prefix rewriting. ui.NewRuleUI(logger, reg, ruleMgr, alertQueryURL.String(), webExternalPrefix, webPrefixHeaderName).Register(router, ins) api := v1.NewRuleAPI(logger, reg, thanosrules.NewGRPCClient(ruleMgr), ruleMgr, flagsMap) - api.Register(router.WithPrefix("/api/v1"), tracer, logger, ins) + api.Register(router.WithPrefix("/api/v1"), tracer, logger, ins, logMiddleware) srv := httpserver.New(logger, reg, comp, httpProbe, httpserver.WithListen(httpBindAddr), diff --git a/cmd/thanos/tools_bucket.go b/cmd/thanos/tools_bucket.go index 79a11feb86..918f5b0415 100644 --- a/cmd/thanos/tools_bucket.go +++ b/cmd/thanos/tools_bucket.go @@ -33,6 +33,7 @@ import ( "github.com/thanos-io/thanos/pkg/extflag" "github.com/thanos-io/thanos/pkg/extprom" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" + "github.com/thanos-io/thanos/pkg/logging" "github.com/thanos-io/thanos/pkg/objstore" "github.com/thanos-io/thanos/pkg/objstore/client" "github.com/thanos-io/thanos/pkg/prober" @@ -351,7 +352,14 @@ func registerBucketWeb(m map[string]setupFunc, root *kingpin.CmdClause, name str flagsMap := getFlagsMap(cmd.Model().Flags) api := v1.NewBlocksAPI(logger, *label, flagsMap) - api.Register(router.WithPrefix("/api/v1"), tracer, logger, ins) + + // Configure Request Logging for HTTP calls. + opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + return logging.NoLogCall + })} + logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) + + api.Register(router.WithPrefix("/api/v1"), tracer, logger, ins, logMiddleware) srv.Handle("/", router) diff --git a/pkg/api/api.go b/pkg/api/api.go index f63671ac71..5c7356054f 100644 --- a/pkg/api/api.go +++ b/pkg/api/api.go @@ -35,6 +35,8 @@ import ( "github.com/prometheus/common/version" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" + "github.com/thanos-io/thanos/pkg/logging" + "github.com/thanos-io/thanos/pkg/server/http/middleware" "github.com/thanos-io/thanos/pkg/tracing" ) @@ -142,8 +144,8 @@ func NewBaseAPI(logger log.Logger, flagsMap map[string]string) *BaseAPI { } // Register registers the common API endpoints. -func (api *BaseAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware) { - instr := GetInstr(tracer, logger, ins) +func (api *BaseAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware, logMiddleware *logging.HTTPServerMiddleware) { + instr := GetInstr(tracer, logger, ins, logMiddleware) r.Options("/*path", instr("options", api.options)) @@ -196,6 +198,7 @@ func GetInstr( tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware, + logMiddleware *logging.HTTPServerMiddleware, ) InstrFunc { instr := func(name string, f ApiFunc) http.HandlerFunc { hf := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { @@ -208,7 +211,7 @@ func GetInstr( w.WriteHeader(http.StatusNoContent) } }) - return ins.NewHandler(name, tracing.HTTPMiddleware(tracer, name, logger, gziphandler.GzipHandler(hf))) + return ins.NewHandler(name, logMiddleware.HTTPMiddleware(name, tracing.HTTPMiddleware(tracer, name, logger, gziphandler.GzipHandler(middleware.RequestID(hf))))) } return instr } diff --git a/pkg/api/api_test.go b/pkg/api/api_test.go index f02d258870..69219f455e 100644 --- a/pkg/api/api_test.go +++ b/pkg/api/api_test.go @@ -30,6 +30,7 @@ import ( "github.com/prometheus/common/route" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" + "github.com/thanos-io/thanos/pkg/logging" "github.com/thanos-io/thanos/pkg/testutil" ) @@ -112,7 +113,8 @@ func TestRespondError(t *testing.T) { func TestOptionsMethod(t *testing.T) { r := route.New() api := &BaseAPI{} - api.Register(r, &opentracing.NoopTracer{}, log.NewNopLogger(), extpromhttp.NewNopInstrumentationMiddleware()) + logMiddleware := logging.NewHTTPServerMiddleware(log.NewNopLogger()) + api.Register(r, &opentracing.NoopTracer{}, log.NewNopLogger(), extpromhttp.NewNopInstrumentationMiddleware(), logMiddleware) s := httptest.NewServer(r) defer s.Close() diff --git a/pkg/api/blocks/v1.go b/pkg/api/blocks/v1.go index 49e32ebbd1..d881f3d68e 100644 --- a/pkg/api/blocks/v1.go +++ b/pkg/api/blocks/v1.go @@ -13,6 +13,7 @@ import ( "github.com/thanos-io/thanos/pkg/api" "github.com/thanos-io/thanos/pkg/block/metadata" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" + "github.com/thanos-io/thanos/pkg/logging" ) // BlocksAPI is a very simple API used by Thanos Block Viewer. @@ -41,10 +42,10 @@ func NewBlocksAPI(logger log.Logger, label string, flagsMap map[string]string) * } } -func (bapi *BlocksAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware) { - bapi.baseAPI.Register(r, tracer, logger, ins) +func (bapi *BlocksAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware, logMiddleware *logging.HTTPServerMiddleware) { + bapi.baseAPI.Register(r, tracer, logger, ins, logMiddleware) - instr := api.GetInstr(tracer, logger, ins) + instr := api.GetInstr(tracer, logger, ins, logMiddleware) r.Get("/blocks", instr("blocks", bapi.blocks)) } diff --git a/pkg/api/query/v1.go b/pkg/api/query/v1.go index 25861a8a1e..7cc30675b2 100644 --- a/pkg/api/query/v1.go +++ b/pkg/api/query/v1.go @@ -43,6 +43,7 @@ import ( "github.com/thanos-io/thanos/pkg/extprom" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" "github.com/thanos-io/thanos/pkg/gate" + "github.com/thanos-io/thanos/pkg/logging" "github.com/thanos-io/thanos/pkg/query" "github.com/thanos-io/thanos/pkg/rules" "github.com/thanos-io/thanos/pkg/rules/rulespb" @@ -105,10 +106,10 @@ func NewQueryAPI( } // Register the API's endpoints in the given router. -func (qapi *QueryAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware) { - qapi.baseAPI.Register(r, tracer, logger, ins) +func (qapi *QueryAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware, logMiddleware *logging.HTTPServerMiddleware) { + qapi.baseAPI.Register(r, tracer, logger, ins, logMiddleware) - instr := api.GetInstr(tracer, logger, ins) + instr := api.GetInstr(tracer, logger, ins, logMiddleware) r.Get("/query", instr("query", qapi.query)) r.Post("/query", instr("query", qapi.query)) diff --git a/pkg/api/rule/v1.go b/pkg/api/rule/v1.go index 00d97ed08d..436cc49f4c 100644 --- a/pkg/api/rule/v1.go +++ b/pkg/api/rule/v1.go @@ -13,6 +13,7 @@ import ( "github.com/thanos-io/thanos/pkg/api" qapi "github.com/thanos-io/thanos/pkg/api/query" extpromhttp "github.com/thanos-io/thanos/pkg/extprom/http" + "github.com/thanos-io/thanos/pkg/logging" "github.com/thanos-io/thanos/pkg/rules" "github.com/thanos-io/thanos/pkg/rules/rulespb" ) @@ -47,10 +48,10 @@ func NewRuleAPI( } } -func (rapi *RuleAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware) { - rapi.baseAPI.Register(r, tracer, logger, ins) +func (rapi *RuleAPI) Register(r *route.Router, tracer opentracing.Tracer, logger log.Logger, ins extpromhttp.InstrumentationMiddleware, logMiddleware *logging.HTTPServerMiddleware) { + rapi.baseAPI.Register(r, tracer, logger, ins, logMiddleware) - instr := api.GetInstr(tracer, logger, ins) + instr := api.GetInstr(tracer, logger, ins, logMiddleware) r.Get("/alerts", instr("alerts", func(r *http.Request) (interface{}, []error, *api.ApiError) { return struct{ Alerts []*rulespb.AlertInstance }{Alerts: rapi.alerts.Active()}, nil, nil diff --git a/pkg/logging/http.go b/pkg/logging/http.go new file mode 100644 index 0000000000..3606b86c87 --- /dev/null +++ b/pkg/logging/http.go @@ -0,0 +1,65 @@ +// Copyright (c) The Thanos Authors. +// Licensed under the Apache License 2.0. + +package logging + +import ( + "fmt" + + "net/http" + "time" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/level" + httputil "github.com/thanos-io/thanos/pkg/server/http" +) + +type HTTPServerMiddleware struct { + opts *options + logger log.Logger +} + +func (m *HTTPServerMiddleware) preCall(start time.Time) { + level.Debug(m.logger).Log("http.start_time", start.String(), "msg", "started call") +} + +func (m *HTTPServerMiddleware) postCall(name string, start time.Time, wrapped *httputil.ResponseWriterWithStatus, r *http.Request) { + status := wrapped.Status() + logger := log.With(m.logger, "http.method", name, "http.request.id", r.Header.Get("X-Request-ID"), "http.code", fmt.Sprintf("%d", status), + "http.time_ms", fmt.Sprintf("%v", durationToMilliseconds(time.Since(start)))) + + if status >= 500 && status < 600 { + logger = log.With(logger, "http.error", fmt.Sprintf("%v", status)) + } + m.opts.levelFunc(logger, status).Log("msg", "finished call") +} + +func (m *HTTPServerMiddleware) HTTPMiddleware(name string, next http.Handler) http.HandlerFunc { + return func(w http.ResponseWriter, r *http.Request) { + wrapped := httputil.WrapResponseWriterWithStatus(w) + start := time.Now() + decision := m.opts.shouldLog(name) + + switch decision { + case NoLogCall: + next.ServeHTTP(w, r) + + case LogStartAndFinishCall: + m.preCall(start) + next.ServeHTTP(wrapped, r) + m.postCall(name, start, wrapped, r) + + case LogFinishCall: + next.ServeHTTP(wrapped, r) + m.postCall(name, start, wrapped, r) + } + } +} + +func NewHTTPServerMiddleware(logger log.Logger, opts ...Option) *HTTPServerMiddleware { + o := evaluateOpt(opts) + return &HTTPServerMiddleware{ + logger: log.With(logger, "protocol", "http", "http.component", "server"), + opts: o, + } +} diff --git a/pkg/logging/options.go b/pkg/logging/options.go new file mode 100644 index 0000000000..49e11e13f0 --- /dev/null +++ b/pkg/logging/options.go @@ -0,0 +1,120 @@ +// Copyright (c) The Thanos Authors. +// Licensed under the Apache License 2.0. + +package logging + +import ( + "fmt" + "time" + + "github.com/go-kit/kit/log" + "github.com/go-kit/kit/log/level" +) + +// Decision defines rules for enabling start and end of logging. +type Decision int + +const ( + // NoLogCall - Logging is disabled. + NoLogCall Decision = iota + // LogFinishCall - Only finish logs of request is enabled. + LogFinishCall + // LogStartAndFinishCall - Logging of start and end of request is enabled. + LogStartAndFinishCall +) + +var defaultOptions = &options{ + shouldLog: DefaultDeciderMethod, + codeFunc: DefaultErrorToCode, + levelFunc: DefaultCodeToLevel, + durationFieldFunc: DurationToTimeMillisFields, +} + +func evaluateOpt(opts []Option) *options { + optCopy := &options{} + *optCopy = *defaultOptions + optCopy.levelFunc = DefaultCodeToLevel + for _, o := range opts { + o(optCopy) + } + return optCopy +} + +// WithDecider customizes the function for deciding if the HTTP Middlewares/Tripperwares should log. +func WithDecider(f Decider) Option { + return func(o *options) { + o.shouldLog = f + } +} + +// WithLevels customizes the function for mapping HTTP response codes and interceptor log level statements. +func WithLevels(f CodeToLevel) Option { + return func(o *options) { + o.levelFunc = f + } +} + +// Interface for the additional methods. + +// Types for the Options. +type Option func(*options) + +// Fields represents logging fields. It has to have even number of elements (pairs). +type Fields []string + +// ErrorToCode function determines the error code of the error +// for the http response. +type ErrorToCode func(err error) int + +func DefaultErrorToCode(_ error) int { + return 500 +} + +// Decider function defines rules for suppressing the logging. +type Decider func(fullMethodName string) Decision + +// DefaultDeciderMethod is the default implementation of decider to see if you should log the call +// by default this is set to LogStartAndFinishCall. +func DefaultDeciderMethod(_ string) Decision { + return LogStartAndFinishCall +} + +// CodeToLevel function defines the mapping between HTTP Response codes to log levels for server side. +type CodeToLevel func(logger log.Logger, code int) log.Logger + +// DurationToFields function defines how to produce duration fields for logging. +type DurationToFields func(duration time.Duration) Fields + +type options struct { + levelFunc CodeToLevel + shouldLog Decider + codeFunc ErrorToCode + durationFieldFunc DurationToFields +} + +// DefaultCodeToLevel is the helper mapper that maps HTTP Response codes to log levels. +func DefaultCodeToLevel(logger log.Logger, code int) log.Logger { + if code >= 200 && code < 300 { + return level.Debug(logger) + } + if code >= 400 && code < 500 { + return level.Debug(logger) + } + return level.Error(logger) +} + +// DurationToTimeMillisFields converts the duration to milliseconds and uses the key `http.time_ms`. +func DurationToTimeMillisFields(duration time.Duration) Fields { + return Fields{"http.time_ms", fmt.Sprintf("%v", durationToMilliseconds(duration))} +} + +func durationToMilliseconds(duration time.Duration) float32 { + return float32(duration.Nanoseconds()/1000) / 1000 +} + +// LogDecision defines mapping of flag options to the logging decision. +var LogDecision = map[string]Decision{ + "NoLogCall": NoLogCall, + "LogFinishCall": LogFinishCall, + "LogStartAndFinishCall": LogStartAndFinishCall, +} diff --git a/pkg/server/http/utils.go b/pkg/server/http/utils.go new file mode 100644 index 0000000000..d8da1dc3c5 --- /dev/null +++ b/pkg/server/http/utils.go @@ -0,0 +1,32 @@ +// Copyright (c) The Thanos Authors. +// Licensed under the Apache License 2.0. + +package http + +import "net/http" + +// ResponseWriterWithStatus wraps around http.ResponseWriter to capture the status code of the response. +type ResponseWriterWithStatus struct { + http.ResponseWriter + status int + isHeaderWritten bool +} + +// WrapResponseWriterWithStatus wraps the http.ResponseWriter for extracting status. +func WrapResponseWriterWithStatus(w http.ResponseWriter) *ResponseWriterWithStatus { + return &ResponseWriterWithStatus{ResponseWriter: w} +} + +// Status returns http response status. +func (r *ResponseWriterWithStatus) Status() int { + return r.status +} + +// WriteHeader writes the header. +func (r *ResponseWriterWithStatus) WriteHeader(code int) { + if !r.isHeaderWritten { + r.status = code + r.ResponseWriter.WriteHeader(code) + r.isHeaderWritten = true + } +} From ac45a5e765ed91ce71998ba06ed14da8a03bd0b0 Mon Sep 17 00:00:00 2001 From: Yash Sharma Date: Thu, 6 Aug 2020 14:12:21 +0530 Subject: [PATCH 2/4] nitpickings Signed-off-by: Yash Sharma --- docs/components/query.md | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/docs/components/query.md b/docs/components/query.md index ec304229a7..94d7fe2fa7 100644 --- a/docs/components/query.md +++ b/docs/components/query.md @@ -357,6 +357,13 @@ Flags: stripped prefix value in X-Forwarded-Prefix header. This allows thanos UI to be served on a sub-path. + --log.request.decision=LogFinishCall + Request Logging for logging the start and end + of requests. LogFinishCall is enabled by + default. LogFinishCall : Logs the finish call + of the requests. LogStartAndFinishCall : Logs + the start and finish call of the requests. + NoLogCall : Disable request logging. --query.timeout=2m Maximum time to process query by query node. --query.max-concurrent=20 Maximum number of queries processed concurrently by query node. From ce902d24250cc4e0619b02682be861a8e35f84f9 Mon Sep 17 00:00:00 2001 From: Yash Sharma Date: Thu, 6 Aug 2020 14:17:17 +0530 Subject: [PATCH 3/4] Added flags for request logging in ruler Signed-off-by: Yash Sharma --- cmd/thanos/rule.go | 6 +++++- docs/components/rule.md | 7 +++++++ 2 files changed, 12 insertions(+), 1 deletion(-) diff --git a/cmd/thanos/rule.go b/cmd/thanos/rule.go index 8d7cf430ff..f05e74d0a6 100644 --- a/cmd/thanos/rule.go +++ b/cmd/thanos/rule.go @@ -98,6 +98,8 @@ func registerRule(m map[string]setupFunc, app *kingpin.Application) { webExternalPrefix := cmd.Flag("web.external-prefix", "Static prefix for all HTML links and redirect URLs in the UI query web interface. Actual endpoints are still served on / or the web.route-prefix. This allows thanos UI to be served behind a reverse proxy that strips a URL sub-path.").Default("").String() webPrefixHeaderName := cmd.Flag("web.prefix-header", "Name of HTTP request header used for dynamic prefixing of UI links and redirects. This option is ignored if web.external-prefix argument is set. Security risk: enable this option only if a reverse proxy in front of thanos is resetting the header. The --web.prefix-header=X-Forwarded-Prefix option can be useful, for example, if Thanos UI is served via Traefik reverse proxy with PathPrefixStrip option enabled, which sends the stripped prefix value in X-Forwarded-Prefix header. This allows thanos UI to be served on a sub-path.").Default("").String() + requestLoggingDecision := cmd.Flag("log.request.decision", "Request Logging for logging the start and end of requests. LogFinishCall is enabled by default. LogFinishCall : Logs the finish call of the requests. LogStartAndFinishCall : Logs the start and finish call of the requests. NoLogCall : Disable request logging.").Default("LogFinishCall").Enum("NoLogCall", "LogFinishCall", "LogStartAndFinishCall") + objStoreConfig := regCommonObjStoreFlags(cmd, "", false) queries := cmd.Flag("query", "Addresses of statically configured query API servers (repeatable). The scheme may be prefixed with 'dns+' or 'dnssrv+' to detect query API servers through respective DNS lookups."). @@ -177,6 +179,7 @@ func registerRule(m map[string]setupFunc, app *kingpin.Application) { logger, reg, tracer, + *requestLoggingDecision, reload, lset, *alertmgrs, @@ -265,6 +268,7 @@ func runRule( logger log.Logger, reg *prometheus.Registry, tracer opentracing.Tracer, + requestLoggingDecision string, reloadSignal <-chan struct{}, lset labels.Labels, alertmgrURLs []string, @@ -589,7 +593,7 @@ func runRule( // Configure Request Logging for HTTP calls. opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { - return logging.NoLogCall + return logging.LogDecision[requestLoggingDecision] })} logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) diff --git a/docs/components/rule.md b/docs/components/rule.md index 5c4ceb2eb9..bd488223e8 100644 --- a/docs/components/rule.md +++ b/docs/components/rule.md @@ -349,6 +349,13 @@ Flags: stripped prefix value in X-Forwarded-Prefix header. This allows thanos UI to be served on a sub-path. + --log.request.decision=LogFinishCall + Request Logging for logging the start and end + of requests. LogFinishCall is enabled by + default. LogFinishCall : Logs the finish call + of the requests. LogStartAndFinishCall : Logs + the start and finish call of the requests. + NoLogCall : Disable request logging. --objstore.config-file= Path to YAML file that contains object store configuration. See format details: From 3d8b96f3e211cc3cb16e26fd1bcf60f773455978 Mon Sep 17 00:00:00 2001 From: Yash Sharma Date: Thu, 6 Aug 2020 18:57:12 +0530 Subject: [PATCH 4/4] remove method name from the decider Signed-off-by: Yash Sharma --- cmd/thanos/compact.go | 2 +- cmd/thanos/query.go | 2 +- cmd/thanos/rule.go | 2 +- cmd/thanos/tools_bucket.go | 2 +- pkg/logging/http.go | 2 +- pkg/logging/options.go | 5 +++-- 6 files changed, 8 insertions(+), 7 deletions(-) diff --git a/cmd/thanos/compact.go b/cmd/thanos/compact.go index 07383f19a6..4837c0accb 100644 --- a/cmd/thanos/compact.go +++ b/cmd/thanos/compact.go @@ -402,7 +402,7 @@ func runCompact( api := blocksAPI.NewBlocksAPI(logger, conf.label, flagsMap) // Configure Request Logging for HTTP calls. - opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + opts := []logging.Option{logging.WithDecider(func() logging.Decision { return logging.NoLogCall })} logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) diff --git a/cmd/thanos/query.go b/cmd/thanos/query.go index daf5abda5c..ebaa68c236 100644 --- a/cmd/thanos/query.go +++ b/cmd/thanos/query.go @@ -407,7 +407,7 @@ func runQuery( } // Configure Request Logging for HTTP calls. - opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + opts := []logging.Option{logging.WithDecider(func() logging.Decision { return logging.LogDecision[requestLoggingDecision] })} logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) diff --git a/cmd/thanos/rule.go b/cmd/thanos/rule.go index f05e74d0a6..950ea0a02c 100644 --- a/cmd/thanos/rule.go +++ b/cmd/thanos/rule.go @@ -592,7 +592,7 @@ func runRule( ins := extpromhttp.NewInstrumentationMiddleware(reg) // Configure Request Logging for HTTP calls. - opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + opts := []logging.Option{logging.WithDecider(func() logging.Decision { return logging.LogDecision[requestLoggingDecision] })} logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) diff --git a/cmd/thanos/tools_bucket.go b/cmd/thanos/tools_bucket.go index 918f5b0415..9c46ce435f 100644 --- a/cmd/thanos/tools_bucket.go +++ b/cmd/thanos/tools_bucket.go @@ -354,7 +354,7 @@ func registerBucketWeb(m map[string]setupFunc, root *kingpin.CmdClause, name str api := v1.NewBlocksAPI(logger, *label, flagsMap) // Configure Request Logging for HTTP calls. - opts := []logging.Option{logging.WithDecider(func(_ string) logging.Decision { + opts := []logging.Option{logging.WithDecider(func() logging.Decision { return logging.NoLogCall })} logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...) diff --git a/pkg/logging/http.go b/pkg/logging/http.go index 3606b86c87..db5ee12527 100644 --- a/pkg/logging/http.go +++ b/pkg/logging/http.go @@ -38,7 +38,7 @@ func (m *HTTPServerMiddleware) HTTPMiddleware(name string, next http.Handler) ht return func(w http.ResponseWriter, r *http.Request) { wrapped := httputil.WrapResponseWriterWithStatus(w) start := time.Now() - decision := m.opts.shouldLog(name) + decision := m.opts.shouldLog() switch decision { case NoLogCall: diff --git a/pkg/logging/options.go b/pkg/logging/options.go index 49e11e13f0..0e4bb89847 100644 --- a/pkg/logging/options.go +++ b/pkg/logging/options.go @@ -71,11 +71,12 @@ func DefaultErrorToCode(_ error) int { } // Decider function defines rules for suppressing the logging. -type Decider func(fullMethodName string) Decision +// TODO : Add the method name as a parameter in case we want to log based on method names. +type Decider func() Decision // DefaultDeciderMethod is the default implementation of decider to see if you should log the call // by default this is set to LogStartAndFinishCall. -func DefaultDeciderMethod(_ string) Decision { +func DefaultDeciderMethod() Decision { return LogStartAndFinishCall }