Initial setup for Request Logging in HTTP in the server side

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.

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() 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.

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() 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),

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"
@@ -97,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.").
@@ -176,6 +179,7 @@ func registerRule(m map[string]setupFunc, app *kingpin.Application) {
 			logger,
 			reg,
 			tracer,
+			*requestLoggingDecision,
 			reload,
 			lset,
 			*alertmgrs,
@@ -264,6 +268,7 @@ func runRule(
 	logger log.Logger,
 	reg *prometheus.Registry,
 	tracer opentracing.Tracer,
+	requestLoggingDecision string,
 	reloadSignal <-chan struct{},
 	lset labels.Labels,
 	alertmgrURLs []string,
@@ -586,11 +591,17 @@ func runRule(
 
 		ins := extpromhttp.NewInstrumentationMiddleware(reg)
 
+		// Configure Request Logging for HTTP calls.
+		opts := []logging.Option{logging.WithDecider(func() logging.Decision {
+			return logging.LogDecision[requestLoggingDecision]
+		})}
+		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),

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() logging.Decision {
+			return logging.NoLogCall
+		})}
+		logMiddleware := logging.NewHTTPServerMiddleware(logger, opts...)
+
+		api.Register(router.WithPrefix("/api/v1"), tracer, logger, ins, logMiddleware)
 
 		srv.Handle("/", router)
 

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.

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=<file-path>
                                  Path to YAML file that contains object store
                                  configuration. See format details:

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
 }

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()

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))
 }

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))

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

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()
+
+		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,
+	}
+}