[TT-2539] Transaction logs

cli/linter/schema.json

@@ -662,6 +662,18 @@
       "type": "string",
       "enum": ["", "standard", "json"]
     },
+    "access_logs": {
+      "type": ["object", "null"],
+      "additionalProperties": false,
+      "properties": {
+        "enabled": {
+          "type": "boolean"
+        },
+        "template": {
+          "type": ["object", "null"]
+        }
+      }
+    },
     "enable_http_profiler": {
       "type": "boolean"
     },

config/config.go

@@ -251,6 +251,33 @@ type AnalyticsConfigConfig struct {
 	SerializerType string `json:"serializer_type"`
 }
 
+// AccessLogsConfig defines the type of transactions logs printed to stdout.
+type AccessLogsConfig struct {
+	// Enabled controls enabling the transaction logs. Default: false.
+	Enabled bool `json:"enabled"`
+
+	// Template configures which fields to log into the access log.
+	// If unconfigured, all fields listed will be logged.
+	//
+	// Example: ["client_ip", "path"].
+	//
+	// Template Options:
+	//
+	// - `api_key` will include they obfuscated or hashed key.
+	// - `client_ip` will include the ip of the request.
+	// - `host` will include the host of the request.
+	// - `method` will include the request method.
+	// - `path` will include the path of the request.
+	// - `protocol` will include the protocol of the request.
+	// - `remote_addr` will include the remote address of the request.
+	// - `upstream_address` will include the upstream address (scheme, host and path)
+	// - `upstream_latency` will include the upstream latency of the request.
+	// - `latency_total` will include the total latency of the request.
+	// - `user_agent` will include the user agent of the request.
+	// - `status` will include the response status code.
+	Template []string `json:"template"`
+}
+
 type HealthCheckConfig struct {
 	// Setting this value to `true` will enable the health-check endpoint on /Tyk/health.
 	EnableHealthChecks bool `json:"enable_health_checks"`
@@ -1013,6 +1040,10 @@ type Config struct {
 	// If not set or left empty, it will default to `standard`.
 	LogFormat string `json:"log_format"`
 
+	// AccessLogs configures the output for access logs.
+	// If not configured, the access log is disabled.
+	AccessLogs AccessLogsConfig `json:"access_logs"`
+
 	// Section for configuring OpenTracing support
 	// Deprecated: use OpenTelemetry instead.
 	Tracer Tracer `json:"tracing"`

gateway/handler_error.go

@@ -313,6 +313,9 @@ func (e *ErrorHandler) HandleError(w http.ResponseWriter, r *http.Request, errMs
 			log.WithError(err).Error("could not store analytic record")
 		}
 	}
+
+	e.RecordAccessLog(r, response, analytics.Latency{})
+
 	// Report in health check
 	reportHealthValue(e.Spec, BlockedRequestLog, "-1")
 }

gateway/handler_success.go

@@ -388,8 +388,10 @@ func (s *SuccessHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) *http
 			Upstream: int64(DurationToMillisecond(resp.UpstreamLatency)),
 		}
 		s.RecordHit(r, latency, resp.Response.StatusCode, resp.Response, false)
+		s.RecordAccessLog(r, resp.Response, latency)
 	}
 	log.Debug("Done proxy")
+
 	return nil
 }
 

gateway/middleware.go

@@ -13,6 +13,9 @@ import (
 	"sync"
 	"time"
 
+	"github.com/TykTechnologies/tyk-pump/analytics"
+	"github.com/TykTechnologies/tyk/internal/httputil/accesslog"
+
 	"github.com/gocraft/health"
 	"github.com/justinas/alice"
 	"github.com/paulbellamy/ratecounter"
@@ -431,6 +434,30 @@ func (t *BaseMiddleware) ApplyPolicies(session *user.SessionState) error {
 	return store.Apply(session)
 }
 
+// RecordAccessLog is used for Success/Error handler logging.
+// It emits a log entry with populated access log fields.
+func (t *BaseMiddleware) RecordAccessLog(req *http.Request, resp *http.Response, latency analytics.Latency) {
+	if !t.Spec.GlobalConfig.AccessLogs.Enabled {
+		return
+	}
+
+	gw := t.Gw
+	gwConfig := gw.GetConfig()
+
+	hashKeys := gwConfig.HashKeys
+	allowedFields := gwConfig.AccessLogs.Template
+
+	// Set the access log fields
+	accessLog := accesslog.NewRecord()
+	accessLog.WithApiKey(req, hashKeys, gw.obfuscateKey)
+	accessLog.WithRequest(req, latency)
+	accessLog.WithResponse(resp)
+
+	logFields := accessLog.Fields(allowedFields)
+
+	t.Logger().WithFields(logFields).Info()
+}
+
 func copyAllowedURLs(input []user.AccessSpec) []user.AccessSpec {
 	if input == nil {
 		return nil

internal/httputil/Taskfile.yml

@@ -3,13 +3,14 @@ version: "3"
 
 vars:
   testArgs: -v
+  coverpkg: ./...,github.com/TykTechnologies/tyk/internal/httputil/...
 
 tasks:
   test:
     desc: "Run tests (requires redis)"
     cmds:
       - task: fmt
-      - go test {{.testArgs}} -count=1 -cover -coverprofile=rate.cov -coverpkg=./... ./...
+      - go test {{.testArgs}} -count=1 -cover -coverprofile=rate.cov -coverpkg={{.coverpkg}} ./...
 
   bench:
     desc: "Run benchmarks"

internal/httputil/accesslog/filter.go

@@ -0,0 +1,35 @@
+package accesslog
+
+import (
+	"github.com/sirupsen/logrus"
+)
+
+// Filter filters the input logrus fields and retains only the allowed fields.
+// The function is case sensitive so keys have to match the case exactly.
+func Filter(in logrus.Fields, allowedFields []string) logrus.Fields {
+	if len(allowedFields) == 0 {
+		return in
+	}
+
+	// Create a map to quickly check if a field is allowed.
+	allowed := make(map[string]struct{}, len(allowedFields))
+	for _, field := range allowedFields {
+		allowed[field] = struct{}{}
+	}
+
+	result := make(logrus.Fields, len(allowedFields))
+
+	// Add the "prefix" field by default, if it exists in the input
+	if prefix, exists := in["prefix"]; exists {
+		result["prefix"] = prefix
+	}
+
+	// Filter keys based on config
+	for key, value := range in {
+		if _, exists := allowed[key]; exists {
+			result[key] = value
+		}
+	}
+
+	return result
+}

internal/httputil/accesslog/filter_test.go

@@ -0,0 +1,27 @@
+package accesslog_test
+
+import (
+	"testing"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+
+	"github.com/TykTechnologies/tyk/internal/httputil/accesslog"
+)
+
+func TestFilter(t *testing.T) {
+	in := logrus.Fields{
+		"a": "b",
+		"b": "c",
+		"c": "d",
+	}
+
+	got := accesslog.Filter(in, []string{"a", "c"})
+
+	want := logrus.Fields{
+		"a": "b",
+		"c": "d",
+	}
+
+	assert.Equal(t, want, got)
+}

internal/httputil/accesslog/record.go

@@ -0,0 +1,74 @@
+package accesslog
+
+import (
+	"net/http"
+	"net/url"
+
+	"github.com/sirupsen/logrus"
+
+	"github.com/TykTechnologies/tyk/ctx"
+	"github.com/TykTechnologies/tyk/internal/crypto"
+	"github.com/TykTechnologies/tyk/request"
+
+	"github.com/TykTechnologies/tyk-pump/analytics"
+)
+
+// Record is a representation of a transaction log in the Gateway.
+type Record struct {
+	fields logrus.Fields
+}
+
+// NewRecord returns a Record object.
+func NewRecord() *Record {
+	fields := logrus.Fields{
+		"prefix": "access-log",
+	}
+	return &Record{
+		fields: fields,
+	}
+}
+
+// WithApiKey sets the access token from the request under APIKey.
+// The access token is obfuscated, or hashed depending on passed arguments.
+func (a *Record) WithApiKey(req *http.Request, hashKeys bool, obfuscate func(string) string) *Record {
+	token := ctx.GetAuthToken(req)
+	if !hashKeys {
+		a.fields["api_key"] = obfuscate(token)
+	} else {
+		a.fields["api_key"] = crypto.HashKey(token, hashKeys)
+	}
+	return a
+}
+
+// WithRequest fills fields from the http request.
+func (a *Record) WithRequest(req *http.Request, latency analytics.Latency) *Record {
+	upstreamAddress := &url.URL{
+		Scheme: req.URL.Scheme,
+		Host:   req.URL.Host,
+		Path:   req.URL.Path,
+	}
+
+	// Keep the sort in sync with config.AccessLog.Template godoc.
+	a.fields["client_ip"] = request.RealIP(req)
+	a.fields["host"] = req.Host
+	a.fields["latency_total"] = latency.Total
+	a.fields["method"] = req.Method
+	a.fields["path"] = req.URL.Path
+	a.fields["protocol"] = req.Proto
+	a.fields["remote_addr"] = req.RemoteAddr
+	a.fields["upstream_address"] = upstreamAddress.String()
+	a.fields["upstream_latency"] = latency.Upstream
+	a.fields["user_agent"] = req.UserAgent()
+	return a
+}
+
+// WithResponse fills response details into the log fields.
+func (a *Record) WithResponse(resp *http.Response) *Record {
+	a.fields["status"] = resp.StatusCode
+	return a
+}
+
+// Fields returns a logrus.Fields intended for logging.
+func (a *Record) Fields(allowedKeys []string) logrus.Fields {
+	return Filter(a.fields, allowedKeys)
+}

internal/httputil/accesslog/record_test.go

@@ -0,0 +1,53 @@
+package accesslog_test
+
+import (
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+
+	"github.com/TykTechnologies/tyk/internal/httputil/accesslog"
+	"github.com/TykTechnologies/tyk/request"
+
+	"github.com/TykTechnologies/tyk-pump/analytics"
+)
+
+func TestRecord(t *testing.T) {
+	latency := analytics.Latency{
+		Total:    99,
+		Upstream: 101,
+	}
+
+	req := httptest.NewRequest(http.MethodGet, "http://example.com/path?userid=1", nil)
+	req.RemoteAddr = "0.0.0.0"
+	req.Header.Set("User-Agent", "user-agent")
+
+	resp := &http.Response{
+		StatusCode: http.StatusOK,
+	}
+
+	record := accesslog.NewRecord()
+	record.WithRequest(req, latency)
+	record.WithResponse(resp)
+
+	got := record.Fields(nil)
+
+	want := logrus.Fields{
+		"prefix":           "access-log",
+		"client_ip":        request.RealIP(req),
+		"remote_addr":      "0.0.0.0",
+		"host":             "example.com",
+		"latency_total":    int64(99),
+		"method":           http.MethodGet,
+		"path":             "/path",
+		"protocol":         "HTTP/1.1",
+		"status":           http.StatusOK,
+		"upstream_address": "http://example.com/path",
+		"upstream_latency": int64(101),
+		"user_agent":       "user-agent",
+	}
+
+	assert.Equal(t, want, got)
+}