[TT-2539] added access/transaction logs

.gitignore

@@ -50,6 +50,7 @@ session_state_gen_test.go
 __pycache__/
 tyk.test
 tyk-gateway.pid
+*.go-e
 
 tyk_linux_*
 /dist/

cli/linter/schema.json

@@ -638,6 +638,15 @@
       "type": "string",
       "enum": ["", "debug", "info", "warn", "error"]
     },
+    "access_logs": {
+      "type": ["object", "null"],
+      "additionalProperties": false,
+      "properties": {
+        "enabled": {
+          "type": "boolean"
+        }
+      }
+    },
     "enable_http_profiler": {
       "type": "boolean"
     },

config/config.go

@@ -246,6 +246,12 @@ type AnalyticsConfigConfig struct {
 	SerializerType string `json:"serializer_type"`
 }
 
+// AccessLogsConfig defines the type of transactions logs printed to stdout
+type AccessLogsConfig struct {
+	// Enable the transaction logs. Default: false
+	Enabled bool `json:"enabled"`
+}
+
 type HealthCheckConfig struct {
 	// Setting this value to `true` will enable the health-check endpoint on /Tyk/health.
 	EnableHealthChecks bool `json:"enable_health_checks"`
@@ -953,6 +959,10 @@ type Config struct {
 	// If not set or left empty, it will default to `info`.
 	LogLevel string `json:"log_level"`
 
+	// You can configure the transaction logs to be turned on
+	// If not set or left empty, it will default to 'false'
+	AccessLogs AccessLogsConfig `json:"access_logs"`
+
 	// Section for configuring OpenTracing support
 	// Deprecated: use OpenTelemetry instead.
 	Tracer Tracer `json:"tracing"`

gateway/handler_error.go

@@ -12,6 +12,11 @@ import (
 	"strings"
 	"time"
 
+	"github.com/sirupsen/logrus"
+
+	"github.com/TykTechnologies/tyk/internal/httputil"
+	"github.com/TykTechnologies/tyk/storage"
+
 	"github.com/TykTechnologies/tyk/apidef"
 
 	"github.com/TykTechnologies/tyk-pump/analytics"
@@ -87,6 +92,25 @@ type TemplateExecutor interface {
 	Execute(wr io.Writer, data interface{}) error
 }
 
+func (e *ErrorHandler) recordAccessLog(log *logrus.Logger, req *http.Request, resp *http.Response) {
+	// Don't print the full token, handle as obfuscated key or hashed key for security reasons
+	hashKeys := e.Gw.GetConfig().HashKeys
+	token := ctxGetAuthToken(req)
+
+	if !hashKeys {
+		token = e.Gw.obfuscateKey(token)
+	} else {
+		token = storage.HashKey(token, hashKeys)
+	}
+
+	accessLog := httputil.NewAccessLogRecord(e.Spec.APIID, token, e.Spec.OrgID)
+	accessLog.WithLatency(&analytics.Latency{})
+	accessLog.WithRequest(req)
+	accessLog.WithResponse(resp)
+
+	log.WithFields(accessLog.Fields()).Info()
+}
+
 // HandleError is the actual error handler and will store the error details in analytics if analytics processing is enabled.
 func (e *ErrorHandler) HandleError(w http.ResponseWriter, r *http.Request, errMsg string, errCode int, writeResponse bool) {
 	defer e.Base().UpdateRequestSession(r)
@@ -311,6 +335,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(log, r, response)
+	}
+
 	// Report in health check
 	reportHealthValue(e.Spec, BlockedRequestLog, "-1")
 }

gateway/handler_error_test.go

@@ -9,6 +9,8 @@ import (
 	"strings"
 	"testing"
 
+	"github.com/TykTechnologies/tyk/config"
+
 	"github.com/TykTechnologies/tyk/header"
 	"github.com/TykTechnologies/tyk/test"
 )
@@ -122,3 +124,52 @@ func TestHandleDefaultErrorJSON(t *testing.T) {
 	})
 
 }
+
+func BenchmarkErrorLogTransaction(b *testing.B) {
+	b.Run("AccessLogs enabled with Hashkeys set to true", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = true
+			globalConf.AccessLogs.Enabled = true
+		}
+		benchmarkErrorLogTransaction(b, conf)
+
+	})
+	b.Run("AccessLogs enabled with Hashkeys set to false", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = false
+			globalConf.AccessLogs.Enabled = true
+		}
+		benchmarkErrorLogTransaction(b, conf)
+	})
+
+	b.Run("AccessLogs disabled with Hashkeys set to true", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = true
+			globalConf.AccessLogs.Enabled = false
+		}
+		benchmarkErrorLogTransaction(b, conf)
+	})
+
+	b.Run("AccessLogs disabled with Hashkeys set to false", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = false
+			globalConf.AccessLogs.Enabled = false
+		}
+		benchmarkErrorLogTransaction(b, conf)
+	})
+}
+
+func benchmarkErrorLogTransaction(b *testing.B, conf func(globalConf *config.Config)) {
+	b.ReportAllocs()
+	b.Helper()
+	b.ResetTimer()
+
+	ts := StartTest(conf)
+	defer ts.Close()
+
+	for i := 0; i < b.N; i++ {
+		ts.Run(b, test.TestCase{
+			Code: http.StatusNotFound,
+		})
+	}
+}

gateway/handler_success.go

@@ -10,7 +10,10 @@ import (
 	"strings"
 	"time"
 
+	"github.com/sirupsen/logrus"
+
 	graphqlinternal "github.com/TykTechnologies/tyk/internal/graphql"
+	"github.com/TykTechnologies/tyk/storage"
 
 	"github.com/TykTechnologies/tyk/apidef"
 	"github.com/TykTechnologies/tyk/internal/httputil"
@@ -120,6 +123,25 @@ func getSessionTags(session *user.SessionState) []string {
 	return tags
 }
 
+func (s *SuccessHandler) recordAccessLog(latency analytics.Latency, log *logrus.Logger, req *http.Request, resp *http.Response) {
+	// Don't print the full token, handle as obfuscated key or hashed key for security reasons
+	hashKeys := s.Gw.GetConfig().HashKeys
+	token := ctxGetAuthToken(req)
+
+	if !hashKeys {
+		token = s.Gw.obfuscateKey(token)
+	} else {
+		token = storage.HashKey(token, hashKeys)
+	}
+
+	accessLog := httputil.NewAccessLogRecord(s.Spec.APIID, token, s.Spec.OrgID)
+	accessLog.WithLatency(&latency)
+	accessLog.WithRequest(req)
+	accessLog.WithResponse(resp)
+
+	log.WithFields(accessLog.Fields()).Info()
+}
+
 func recordGraphDetails(rec *analytics.AnalyticsRecord, r *http.Request, resp *http.Response, spec *APISpec) {
 	if !spec.GraphQL.Enabled || spec.GraphQL.ExecutionMode == apidef.GraphQLExecutionModeSubgraph {
 		return
@@ -382,8 +404,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(latency, log, r, resp.Response)
+		}
 	}
 	log.Debug("Done proxy")
+
 	return nil
 }
 

gateway/handler_success_test.go

@@ -326,3 +326,58 @@ func TestAnalyticsIgnoreSubgraph(t *testing.T) {
 	)
 	assert.NoError(t, err)
 }
+
+func BenchmarkSuccessLogTransaction(b *testing.B) {
+	b.Run("AccessLogs enabled with Hashkeys set to true", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = true
+			globalConf.AccessLogs.Enabled = true
+		}
+		benchmarkSuccessLogTransaction(b, conf)
+
+	})
+	b.Run("AccessLogs enabled with Hashkeys set to false", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = false
+			globalConf.AccessLogs.Enabled = true
+		}
+		benchmarkSuccessLogTransaction(b, conf)
+	})
+	b.Run("AccessLogs disabled with Hashkeys set to true", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = true
+			globalConf.AccessLogs.Enabled = false
+		}
+		benchmarkSuccessLogTransaction(b, conf)
+	})
+	b.Run("AccessLogs disabled with Hashkeys set to false", func(b *testing.B) {
+		conf := func(globalConf *config.Config) {
+			globalConf.HashKeys = false
+			globalConf.AccessLogs.Enabled = false
+		}
+		benchmarkSuccessLogTransaction(b, conf)
+	})
+}
+
+func benchmarkSuccessLogTransaction(b *testing.B, conf func(globalConf *config.Config)) {
+	b.ReportAllocs()
+	b.Helper()
+	b.ResetTimer()
+
+	ts := StartTest(conf)
+	defer ts.Close()
+
+	API := BuildAPI(func(spec *APISpec) {
+		spec.Name = "test-api"
+		spec.APIID = "test-api-id"
+		spec.Proxy.ListenPath = "/"
+	})[0]
+
+	ts.Gw.LoadAPI(API)
+
+	for i := 0; i < b.N; i++ {
+		ts.Run(b, test.TestCase{
+			Code: http.StatusOK,
+		})
+	}
+}

internal/httputil/access_log.go

@@ -0,0 +1,71 @@
+package httputil
+
+import (
+	"net/http"
+	"net/url"
+
+	"github.com/TykTechnologies/tyk/request"
+
+	"github.com/sirupsen/logrus"
+
+	"github.com/TykTechnologies/tyk-pump/analytics"
+)
+
+// AccessLogRecord is a representation of a transaction log in the Gateway
+type AccessLogRecord logrus.Fields
+
+// NewAccessLogRecord returns an AccessLogRecord object
+func NewAccessLogRecord(apiID string, apiKey string, orgId string) *AccessLogRecord {
+	a := &AccessLogRecord{
+		"APIID":  apiID,
+		"APIKey": apiKey,
+		"OrgID":  orgId,
+		"prefix": "access-log",
+	}
+
+	return a
+}
+
+// WithLatency sets the latency of the AccessLogRecord
+func (a *AccessLogRecord) WithLatency(latency *analytics.Latency) *AccessLogRecord {
+	if latency != nil {
+		(*a)["TotalLatency"] = latency.Total
+		(*a)["UpstreamLatency"] = latency.Upstream
+	}
+	return a
+}
+
+// WithRequest sets the request of the AccessLogRecord
+func (a *AccessLogRecord) WithRequest(req *http.Request) *AccessLogRecord {
+	if req != nil {
+		(*a)["ClientIP"] = request.RealIP(req)
+		(*a)["ClientRemoteAddr"] = req.RemoteAddr
+		(*a)["Host"] = req.Host
+		(*a)["Method"] = req.Method
+		(*a)["Proto"] = req.Proto
+		(*a)["RequestURI"] = req.RequestURI
+		(*a)["UpstreamAddress"] = (&url.URL{
+			Scheme:   req.URL.Scheme,
+			Host:     req.URL.Host,
+			Path:     req.URL.Path,
+			RawQuery: req.URL.RawQuery,
+		}).String()
+		(*a)["UpstreamPath"] = req.URL.Path
+		(*a)["UpstreamURI"] = req.URL.RequestURI()
+		(*a)["UserAgent"] = req.UserAgent()
+	}
+	return a
+}
+
+// WithResponse sets the request of the AccessLogRecord
+func (a *AccessLogRecord) WithResponse(resp *http.Response) *AccessLogRecord {
+	if resp != nil {
+		(*a)["StatusCode"] = resp.StatusCode
+	}
+	return a
+}
+
+// Fields converts the AccessLogRecord as a logrus.Fields object
+func (a *AccessLogRecord) Fields() logrus.Fields {
+	return logrus.Fields(*a)
+}