[TT-2539] Transaction logs (#6841)

### **User description** <details open> <summary><a href="https://tyktech.atlassian.net/browse/TT-2539" title="TT-2539" target="_blank">TT-2539</a></summary> <br /> <table> <tr> <th>Summary</th> <td>Transaction/Access Logs</td> </tr> <tr> <th>Type</th> <td> <img alt="Story" src="https://tyktech.atlassian.net/rest/api/2/universal_avatar/view/type/issuetype/avatar/10315?size=medium" /> Story </td> </tr> <tr> <th>Status</th> <td>In Dev</td> </tr> <tr> <th>Points</th> <td>N/A</td> </tr> <tr> <th>Labels</th> <td><a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20A%20ORDER%20BY%20created%20DESC" title="A">A</a>, <a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20America's%20ORDER%20BY%20created%20DESC" title="America's">America's</a>, <a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20CSE%20ORDER%20BY%20created%20DESC" title="CSE">CSE</a>, <a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20Gold%20ORDER%20BY%20created%20DESC" title="Gold">Gold</a>, <a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20QA_Fail%20ORDER%20BY%20created%20DESC" title="QA_Fail">QA_Fail</a>, <a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20customer_request%20ORDER%20BY%20created%20DESC" title="customer_request">customer_request</a>, <a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20innersource%20ORDER%20BY%20created%20DESC" title="innersource">innersource</a>, <a href="https://tyktech.atlassian.net/issues?jql=project%20%3D%20TT%20AND%20labels%20%3D%20jira_escalated%20ORDER%20BY%20created%20DESC" title="jira_escalated">jira_escalated</a></td> </tr> </table> </details>  --- ### **FR Jira Ticket**  https://tyktech.atlassian.net/browse/TT-2539 ## Description  - Added the `TYK_GW_ACCESSLOGS_ENABLED` Gateway config option - The Tyk Gateway will determine to print access logs to STDOUT for both success and error handling situations - If the `TYK_GW_ACCESSLOGS_ENABLED` is set to `true` then the Gateway will print access logs to STDOUT - If the `TYK_GW_ACCESSLOGS_ENABLED` is set to `false` then the Gateway will not print access logs to STDOUT - Added the `TYK_GW_ACCESSLOGS_TEMPLATE` Gateway config option - If the `TYK_GW_ACCESSLOGS_TEMPLATE` is contains the following options below then the Custom Log Template will be used to print out the access logs - `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. Note that this feature is off by default and that the `AccessLog` struct only contains the more common elements. Below are some examples of an access log ``` time="Jan 20 11:10:57" level=debug msg="Using CUSTOM access log template" api_id=bbcde1bde9a946af4695bb53b615de93 api_name=httpbin org_id=678e6771247d80fd2c435bf3 time="Jan 20 11:10:57" level=info api_id=bbcde1bde9a946af4695bb53b615de93 api_key=82ebbc4b34021b9f api_name=httpbin client_ip="::1" client_remote_addr="[::1]:65000" host="localhost:8080" method=GET org_id=678e6771247d80fd2c435bf3 prefix=access-log protocol=HTTP/1.1 request_url=/get status_code=200 total_latency=116 upstream_address="http://httpbin.org/get" upstream_latency=115 user_agent=PostmanRuntime/7.43.0 ``` ## Related Issue     ## Motivation and Context  Today the Tyk Gateway does not print access logs for success API calls but instead only for error API calls. Providing access logs for both scenarios within the Tyk Gateway is extremely valuable especially if you are monitoring logs, capturing analytics or even debugging. Providing the option to turn on or off the Tyk Gateway access logs will provide clients more insights in for API calls in regards to success and error situations. ## How This Has Been Tested     - Manual testing - Unit testing - Performance testing/benchmarks ## Screenshots (if appropriate) ## Types of changes  - [ ] Bug fix (non-breaking change which fixes an issue) - [x] New feature (non-breaking change which adds functionality) - [ ] Breaking change (fix or feature that would cause existing functionality to change) - [ ] Refactoring or add test (improvements in base code or adds test coverage to functionality) ## Checklist    - [ ] I ensured that the documentation is up to date - [ ] I explained why this PR updates go.mod in detail with reasoning why it's required - [ ] I would like a code coverage CI quality gate exception and have explained why ___ ### **PR Type** Enhancement, Tests ___ ### **Description** - Introduced a new `AccessLogsConfig` for transaction logging. - Added functionality to log access details for success and error handlers. - Implemented a new `accesslog` package for structured logging. - Enhanced test coverage with unit and benchmark tests for access logs. ___ ### **Changes walkthrough** 📝 <table><thead><tr><th></th><th align="left">Relevant files</th></tr></thead><tbody><tr><td><strong>Enhancement</strong></td><td><details><summary>5 files</summary><table> <tr> <td><strong>config.go</strong><dd><code>Added `AccessLogsConfig` for transaction logging configuration.</code></dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-fe44f09c4d5977b5f5eaea29170b6a0748819c9d02271746a20d81a5f3efca17">+29/-0</a>    </td> </tr> <tr> <td><strong>handler_error.go</strong><dd><code>Added access log handling for error responses.</code>                      </dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-d3b05530ad23401f3b8f33bb1a467cd807a29a6b09c7430d01d069f626b20f77">+7/-0</a>      </td> </tr> <tr> <td><strong>handler_success.go</strong><dd><code>Added access log handling for successful responses.</code>            </dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-45135957493eca37f2e3e9a81079577777133c53b27cf95ea2ff0329c05bd006">+7/-0</a>      </td> </tr> <tr> <td><strong>middleware.go</strong><dd><code>Implemented `recordAccessLog` for structured transaction logging.</code></dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-703054910891a4db633eca0f42ed779d6b4fa75cd9b3aa4c503e681364201c1b">+53/-0</a>    </td> </tr> <tr> <td><strong>access_log.go</strong><dd><code>Introduced `accesslog` package for structured access log handling.</code></dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-39a7ae68c9608f8e05ab9207081cb3be248d00d68a5a2412304b83b2340401b7">+170/-0</a>  </td> </tr> </table></details></td></tr><tr><td><strong>Tests</strong></td><td><details><summary>2 files</summary><table> <tr> <td><strong>access_log_test.go</strong><dd><code>Added unit tests for `accesslog` package.</code>                                </dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-7e171bde9a23d0039c5dd0c1f0718a1da2dcf93211f997ce8798d4a9a14450f0">+50/-0</a>    </td> </tr> <tr> <td><strong>access_log_test.go</strong><dd><code>Added benchmark tests for access log performance.</code>                </dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-cf5779a4d01913d259d6e27cb951393a37fd06a003c5fc5b992238eafbb6c4b8">+85/-0</a>    </td> </tr> </table></details></td></tr><tr><td><strong>Configuration changes</strong></td><td><details><summary>2 files</summary><table> <tr> <td><strong>schema.json</strong><dd><code>Updated schema to include `access_logs` configuration.</code>      </dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-103cec746d3e61d391c5a67c171963f66fea65d651d704d5540e60aa5d574f46">+12/-0</a>    </td> </tr> <tr> <td><strong>Taskfile.yml</strong><dd><code>Updated test coverage configuration for `accesslog` package.</code></dd></td> <td><a href="https://github.com/TykTechnologies/tyk/pull/6841/files#diff-31877aaad48d3baf442aa52077c28b873df2f2ac6c70941d409261460d7c3c8e">+2/-1</a>      </td> </tr> </table></details></td></tr></tr></tbody></table> ___ > 💡 **PR-Agent usage**: Comment `/help "your question"` on any pull request to receive relevant information --------- Co-authored-by: Long Le <[email protected]> Co-authored-by: Tit Petric <[email protected]> Co-authored-by: Tit Petric <[email protected]>
TykTechnologies · Jan 22, 2025 · 5a9c0ff · 5a9c0ff
1 parent 68a2deb
commit 5a9c0ff
Show file tree

Hide file tree

Showing 11 changed files with 351 additions and 1 deletion.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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)
+}