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..11c7abb48ef 100644 --- a/config/config.go +++ b/config/config.go @@ -251,6 +251,31 @@ 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 defaults to empty which prints the default log. + // Set this value to determine which fields will be printed in the access log. + // Example: ["..."]. + // + // 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. + // - `latency_total` will include the total latency 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. + // - `status` will include the response status code. + // - `upstream_address` will include the upstream address (scheme, host and path) + // - `upstream_latency` will include the upstream latency of the request. + // - `use_agent` will include the user agent of the request. + 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 +1038,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..7f49fed3a44 100644 --- a/gateway/handler_error.go +++ b/gateway/handler_error.go @@ -313,6 +313,13 @@ func (e *ErrorHandler) HandleError(w http.ResponseWriter, r *http.Request, errMs log.WithError(err).Error("could not store analytic record") } } + + // Print the transaction logs for error situations if enabled. Success transaction + // logs will be handled by the "handler_success.go" + if e.Spec.GlobalConfig.AccessLogs.Enabled { + e.recordAccessLog(r, response, nil) + } + // Report in health check reportHealthValue(e.Spec, BlockedRequestLog, "-1") } diff --git a/gateway/handler_success.go b/gateway/handler_success.go index b7a901afcb4..e7d1ff3b964 100644 --- a/gateway/handler_success.go +++ b/gateway/handler_success.go @@ -388,8 +388,15 @@ 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) + + // Don't print a transaction log there is no "resp", that indicates an error. + // In error situations, transaction log is already printed by "handler_error.go" + if s.Spec.GlobalConfig.AccessLogs.Enabled { + s.recordAccessLog(r, resp.Response, &latency) + } } log.Debug("Done proxy") + return nil } diff --git a/gateway/middleware.go b/gateway/middleware.go index 52c1b9cf840..7e37e64d81a 100644 --- a/gateway/middleware.go +++ b/gateway/middleware.go @@ -10,9 +10,13 @@ import ( "io/ioutil" "net/http" "strconv" + "strings" "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 +435,55 @@ func (t *BaseMiddleware) ApplyPolicies(session *user.SessionState) error { return store.Apply(session) } +// recordAccessLog is only used for Success/Error handler +func (t *BaseMiddleware) recordAccessLog(req *http.Request, resp *http.Response, latency *analytics.Latency) { + hashKeys := t.Gw.GetConfig().HashKeys + accessLog := accesslog.NewRecord() + allowedFields := t.Gw.GetConfig().AccessLogs.Template + fields := accessLog.Fields() + + // Set the access log fields + accessLog.WithApiKey(req, hashKeys, t.Gw.obfuscateKey) + accessLog.WithClientIP(req) + accessLog.WithRemoteAddr(req) + accessLog.WithHost(req) + accessLog.WithLatencyTotal(latency) + accessLog.WithMethod(req) + accessLog.WithPath(req) + accessLog.WithProtocol(req) + accessLog.WithStatus(resp) + accessLog.WithUpstreamAddress(req) + accessLog.WithUpstreamLatency(latency) + accessLog.WithUserAgent(req) + + // Check for template config + if isValidAccessLogTemplate(allowedFields) { + // Filter based on custom log template + t.logger.Debug("Using CUSTOM access log template") + filteredFields := accesslog.Filter(&fields, allowedFields) + t.Logger().WithFields(*filteredFields).Info() + } else { + // Default access log + t.logger.Debug("Using DEFAULT access log template") + t.Logger().WithFields(fields).Info() + } +} + +func isValidAccessLogTemplate(template []string) bool { + // Check if template is empty + if len(template) == 0 { + return false + } + + // Check if there is at least one non-empty config string + for _, conf := range template { + if strings.TrimSpace(conf) != "" { + return true + } + } + return false +} + 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/access_log.go b/internal/httputil/accesslog/access_log.go new file mode 100644 index 00000000000..20a96948ef2 --- /dev/null +++ b/internal/httputil/accesslog/access_log.go @@ -0,0 +1,170 @@ +package accesslog + +import ( + "net/http" + "net/url" + "strings" + + "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 { + if req != nil { + token := ctx.GetAuthToken(req) + if !hashKeys { + a.fields["api_key"] = obfuscate(token) + } else { + a.fields["api_key"] = crypto.HashKey(token, hashKeys) + } + } + return a +} + +// WithClientIP sets the client ip of the Record. +func (a *Record) WithClientIP(req *http.Request) *Record { + if req != nil { + a.fields["client_ip"] = request.RealIP(req) + } + return a +} + +// WithHost sets the host of the Record. +func (a *Record) WithHost(req *http.Request) *Record { + if req != nil { + a.fields["host"] = req.Host + } + return a +} + +// WithLatencyTotal sets the total latency of the Record. +func (a *Record) WithLatencyTotal(latency *analytics.Latency) *Record { + if latency != nil { + a.fields["latency_total"] = latency.Total + } + return a +} + +// WithMethod sets the request method of the Record. +func (a *Record) WithMethod(req *http.Request) *Record { + if req != nil { + a.fields["method"] = req.Method + } + return a +} + +// WithRemoteAddr sets the client remote address of the Record. +func (a *Record) WithRemoteAddr(req *http.Request) *Record { + if req != nil { + a.fields["remote_addr"] = req.RemoteAddr + } + return a +} + +// WithPath sets the path of the Record. +func (a *Record) WithPath(req *http.Request) *Record { + if req != nil { + a.fields["path"] = req.URL.Path + } + return a +} + +// WithProtocol sets the request protocol of the Record. +func (a *Record) WithProtocol(req *http.Request) *Record { + if req != nil { + a.fields["protocol"] = req.Proto + } + return a +} + +// WithStatus sets the response status of the Record. +func (a *Record) WithStatus(resp *http.Response) *Record { + if resp != nil { + a.fields["status"] = resp.StatusCode + } + return a +} + +// WithUpstreamAddress sets the upstream address of the Record. +func (a *Record) WithUpstreamAddress(req *http.Request) *Record { + if req != nil { + // Default upstream address + upstreamAddress := &url.URL{ + Scheme: req.URL.Scheme, + Host: req.URL.Host, + Path: req.URL.Path, + } + + a.fields["upstream_address"] = upstreamAddress.String() + } + return a +} + +// WithUpstreamLatency sets the upstream latency of the Record. +func (a *Record) WithUpstreamLatency(latency *analytics.Latency) *Record { + if latency != nil { + a.fields["upstream_latency"] = latency.Upstream + } + return a +} + +// WithUserAgent sets the user agent of the Record. +func (a *Record) WithUserAgent(req *http.Request) *Record { + if req != nil { + a.fields["user_agent"] = req.UserAgent() + } + return a +} + +// Fields returns a logrus.Fields intended for logging. +func (a *Record) Fields() logrus.Fields { + return a.fields +} + +// Filter filters the input logrus fields and retains only the allowed fields. +func Filter(in *logrus.Fields, allowedFields []string) *logrus.Fields { + // Create a map to quickly check if a field is allowed. + allowed := make(map[string]struct{}, len(allowedFields)) + for _, field := range allowedFields { + allowed[strings.ToLower(field)] = struct{}{} + } + + // Create a new logrus.Fields to store the filtered fields. + filtered := logrus.Fields{} + + // Add the "prefix" field by default, if it exists in the input + if prefix, exists := (*in)["prefix"]; exists { + filtered["prefix"] = prefix + } + + // Filter keys based on config + for key, value := range *in { + if _, exists := allowed[strings.ToLower(key)]; exists { + filtered[key] = value + } + } + + return &filtered +} diff --git a/internal/httputil/accesslog/access_log_test.go b/internal/httputil/accesslog/access_log_test.go new file mode 100644 index 00000000000..6efb55890c6 --- /dev/null +++ b/internal/httputil/accesslog/access_log_test.go @@ -0,0 +1,50 @@ +package accesslog + +import ( + "net/http" + "net/http/httptest" + "testing" + + "github.com/TykTechnologies/tyk-pump/analytics" + + "github.com/TykTechnologies/tyk/request" + + "github.com/stretchr/testify/assert" +) + +func TestNewRecord(t *testing.T) { + record := NewRecord().Fields() + + assert.Equal(t, "access-log", record["prefix"]) + assert.NotNil(t, record["prefix"]) +} + +func TestNewRecordField(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 := NewRecord().WithClientIP(req).WithRemoteAddr(req).WithHost(req).WithLatencyTotal(latency).WithMethod(req).WithPath(req).WithProtocol(req).WithStatus(resp).WithUpstreamAddress(req).WithUpstreamLatency(latency).WithUserAgent(req).Fields() + + assert.Equal(t, "access-log", record["prefix"]) + assert.Equal(t, request.RealIP(req), record["client_ip"]) + assert.Equal(t, "0.0.0.0", record["remote_addr"]) + assert.Equal(t, "example.com", record["host"]) + assert.Equal(t, int64(99), record["latency_total"]) + assert.Equal(t, http.MethodGet, record["method"]) + assert.Equal(t, "/path", record["path"]) + assert.Equal(t, "HTTP/1.1", record["protocol"]) + assert.Equal(t, http.StatusOK, record["status"]) + assert.Equal(t, "http://example.com/path", record["upstream_address"]) + assert.Equal(t, int64(101), record["upstream_latency"]) + assert.Equal(t, "user-agent", record["user_agent"]) +} diff --git a/tests/benchmark/access_log_test.go b/tests/benchmark/access_log_test.go new file mode 100644 index 00000000000..0549ef5ca4b --- /dev/null +++ b/tests/benchmark/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) + }) + } +}