diff --git a/cli/linter/schema.json b/cli/linter/schema.json index 40d8f3b50fc..8310b6fbd88 100644 --- a/cli/linter/schema.json +++ b/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" }, diff --git a/config/config.go b/config/config.go index 3dd104aab0f..693d0f5cfbe 100644 --- a/config/config.go +++ b/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"` diff --git a/gateway/handler_error.go b/gateway/handler_error.go index e448ff2cfc1..2d5a9bcd799 100644 --- a/gateway/handler_error.go +++ b/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") } diff --git a/gateway/handler_success.go b/gateway/handler_success.go index b7a901afcb4..a6b7c3adddf 100644 --- a/gateway/handler_success.go +++ b/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 } diff --git a/gateway/middleware.go b/gateway/middleware.go index 52c1b9cf840..33a0a2fe5c4 100644 --- a/gateway/middleware.go +++ b/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 diff --git a/internal/httputil/Taskfile.yml b/internal/httputil/Taskfile.yml index 8434634a752..1ee8627008a 100644 --- a/internal/httputil/Taskfile.yml +++ b/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" diff --git a/internal/httputil/accesslog/filter.go b/internal/httputil/accesslog/filter.go new file mode 100644 index 00000000000..6ff3e0c244b --- /dev/null +++ b/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 +} diff --git a/internal/httputil/accesslog/filter_test.go b/internal/httputil/accesslog/filter_test.go new file mode 100644 index 00000000000..8135b051286 --- /dev/null +++ b/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) +} diff --git a/internal/httputil/accesslog/record.go b/internal/httputil/accesslog/record.go new file mode 100644 index 00000000000..4810f2cd53a --- /dev/null +++ b/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) +} diff --git a/internal/httputil/accesslog/record_test.go b/internal/httputil/accesslog/record_test.go new file mode 100644 index 00000000000..58d10f24115 --- /dev/null +++ b/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) +} diff --git a/tests/accesslog/access_log_test.go b/tests/accesslog/access_log_test.go new file mode 100644 index 00000000000..0549ef5ca4b --- /dev/null +++ b/tests/accesslog/access_log_test.go @@ -0,0 +1,85 @@ +package accesslog_test + +import ( + "net/http" + "testing" + + "github.com/TykTechnologies/tyk/config" + "github.com/TykTechnologies/tyk/gateway" + "github.com/TykTechnologies/tyk/test" +) + +// accessLogTestCase defines the test inputs. +type accessLogTestCase struct { + name string + hashKeys bool + accessLogsEnabled bool + statusCode int +} + +// accessLogTestCases define test cases in a table to reduce repetition. +func accessLogTestCases(status int) []accessLogTestCase { + return []accessLogTestCase{ + {"AccessLogs enabled with Hashkeys set to true", true, true, status}, + {"AccessLogs enabled with Hashkeys set to false", false, true, status}, + {"AccessLogs disabled with Hashkeys set to true", true, false, status}, + {"AccessLogs disabled with Hashkeys set to false", false, false, status}, + } +} + +// Setup starts the gateway according to test case settings. +func (tt accessLogTestCase) Setup(tb testing.TB) *gateway.Test { + tb.Helper() + + ts := gateway.StartTest(func(globalConf *config.Config) { + globalConf.HashKeys = tt.hashKeys + globalConf.AccessLogs.Enabled = tt.accessLogsEnabled + }) + tb.Cleanup(ts.Close) + + return ts +} + +// Benchmark runs requests against gateway with the benchmark. +func (tt accessLogTestCase) Benchmark(b *testing.B, ts *gateway.Test) { + b.Helper() + b.ReportAllocs() + b.ResetTimer() + + for i := 0; i < b.N; i++ { + ts.Run(b, test.TestCase{ + Code: tt.statusCode, + }) + } +} + +// BenchmarkAccessLog benchmarks access logs for 200 OK. +func BenchmarkAccessLog(b *testing.B) { + for _, tt := range accessLogTestCases(http.StatusOK) { + tt := tt // capture range variable + b.Run(tt.name, func(b *testing.B) { + ts := tt.Setup(b) + + API := gateway.BuildAPI(func(spec *gateway.APISpec) { + spec.Name = "test-api" + spec.APIID = "test-api-id" + spec.Proxy.ListenPath = "/" + })[0] + ts.Gw.LoadAPI(API) + + tt.Benchmark(b, ts) + }) + } +} + +// BenchmarkAccessLog benchmarks access logs for 404 Not Found. +func BenchmarkAccessLog_Errors(b *testing.B) { + for _, tt := range accessLogTestCases(http.StatusNotFound) { + tt := tt // capture range variable + b.Run(tt.name, func(b *testing.B) { + ts := tt.Setup(b) + + tt.Benchmark(b, ts) + }) + } +}