[TT-2539] added access/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,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"`

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

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
 }
 

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

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/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
+}

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"])
+}