Revert "Revert "[TT-2539] added access/transaction logs" (#6524)"

This reverts commit 3e435cc.

.gitignore

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

cli/linter/schema.json

@@ -662,6 +662,15 @@
       "type": "string",
       "enum": ["", "standard", "json"]
     },
+    "access_logs": {
+      "type": ["object", "null"],
+      "additionalProperties": false,
+      "properties": {
+        "enabled": {
+          "type": "boolean"
+        }
+      }
+    },
     "enable_http_profiler": {
       "type": "boolean"
     },

config/config.go

@@ -250,6 +250,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"`
@@ -1009,6 +1015,10 @@ type Config struct {
 	// If not set or left empty, it will default to `standard`.
 	LogFormat string `json:"log_format"`
 
+	// 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

@@ -311,6 +311,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_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,9 +10,8 @@ import (
 	"strings"
 	"time"
 
-	graphqlinternal "github.com/TykTechnologies/tyk/internal/graphql"
-
 	"github.com/TykTechnologies/tyk/apidef"
+	graphqlinternal "github.com/TykTechnologies/tyk/internal/graphql"
 	"github.com/TykTechnologies/tyk/internal/httputil"
 
 	"github.com/TykTechnologies/tyk-pump/analytics"
@@ -382,8 +381,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/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,
+		})
+	}
+}

gateway/middleware.go

@@ -12,8 +12,11 @@ import (
 	"strconv"
 	"time"
 
+	"github.com/TykTechnologies/tyk-pump/analytics"
+
 	"github.com/TykTechnologies/tyk/internal/cache"
 	"github.com/TykTechnologies/tyk/internal/event"
+	"github.com/TykTechnologies/tyk/internal/httputil/accesslog"
 	"github.com/TykTechnologies/tyk/internal/otel"
 	"github.com/TykTechnologies/tyk/internal/policy"
 	"github.com/TykTechnologies/tyk/rpc"
@@ -376,6 +379,19 @@ 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(t.Spec.APIID, t.Spec.OrgID)
+	accessLog.WithAuthToken(req, hashKeys, t.Gw.obfuscateKey)
+	accessLog.WithLatency(latency)
+	accessLog.WithRequest(req)
+	accessLog.WithResponse(resp)
+
+	t.Logger().WithFields(accessLog.Fields()).Info()
+}
+
 func copyAllowedURLs(input []user.AccessSpec) []user.AccessSpec {
 	if input == nil {
 		return nil

internal/crypto/hash.go

@@ -0,0 +1,53 @@
+package crypto
+
+import (
+	"crypto/sha256"
+	"encoding/hex"
+	"fmt"
+	"hash"
+
+	"github.com/TykTechnologies/murmur3"
+)
+
+const (
+	HashSha256    = "sha256"
+	HashMurmur32  = "murmur32"
+	HashMurmur64  = "murmur64"
+	HashMurmur128 = "murmur128"
+)
+
+func hashFunction(algorithm string) (hash.Hash, error) {
+	switch algorithm {
+	case HashSha256:
+		return sha256.New(), nil
+	case HashMurmur64:
+		return murmur3.New64(), nil
+	case HashMurmur128:
+		return murmur3.New128(), nil
+	case "", HashMurmur32:
+		return murmur3.New32(), nil
+	default:
+		return murmur3.New32(), fmt.Errorf("Unknown key hash function: %s. Falling back to murmur32.", algorithm)
+	}
+}
+
+func HashStr(in string, withAlg ...string) string {
+	var algo string
+	if len(withAlg) > 0 && withAlg[0] != "" {
+		algo = withAlg[0]
+	} else {
+		algo = TokenHashAlgo(in)
+	}
+
+	h, _ := hashFunction(algo)
+	h.Write([]byte(in))
+	return hex.EncodeToString(h.Sum(nil))
+}
+
+func HashKey(in string, hashKey bool) string {
+	if !hashKey {
+		// Not hashing? Return the raw key
+		return in
+	}
+	return HashStr(in)
+}

internal/crypto/token.go

@@ -0,0 +1,83 @@
+package crypto
+
+import (
+	"encoding/base64"
+	"encoding/hex"
+	"fmt"
+	"strings"
+
+	"github.com/buger/jsonparser"
+
+	"github.com/TykTechnologies/tyk/internal/uuid"
+)
+
+// `{"` in base64
+const B64JSONPrefix = "ey"
+
+const DefaultHashAlgorithm = "murmur64"
+
+const MongoBsonIdLength = 24
+
+// GenerateToken generates a token.
+// If hashing algorithm is empty, it uses legacy key generation.
+func GenerateToken(orgID, keyID, hashAlgorithm string) (string, error) {
+	if keyID == "" {
+		keyID = uuid.NewHex()
+	}
+
+	if hashAlgorithm != "" {
+		_, err := hashFunction(hashAlgorithm)
+		if err != nil {
+			hashAlgorithm = DefaultHashAlgorithm
+		}
+
+		jsonToken := fmt.Sprintf(`{"org":"%s","id":"%s","h":"%s"}`, orgID, keyID, hashAlgorithm)
+		return base64.StdEncoding.EncodeToString([]byte(jsonToken)), err
+	}
+
+	// Legacy keys
+	return orgID + keyID, nil
+}
+
+func TokenHashAlgo(token string) string {
+	// Legacy tokens not b64 and not JSON records
+	if strings.HasPrefix(token, B64JSONPrefix) {
+		if jsonToken, err := base64.StdEncoding.DecodeString(token); err == nil {
+			hashAlgo, _ := jsonparser.GetString(jsonToken, "h")
+			return hashAlgo
+		}
+	}
+
+	return ""
+}
+
+func TokenID(token string) (id string, err error) {
+	jsonToken, err := base64.StdEncoding.DecodeString(token)
+	if err != nil {
+		return "", err
+	}
+
+	return jsonparser.GetString(jsonToken, "id")
+}
+
+func TokenOrg(token string) string {
+	if strings.HasPrefix(token, B64JSONPrefix) {
+		if jsonToken, err := base64.StdEncoding.DecodeString(token); err == nil {
+			// Checking error in case if it is a legacy tooken which just by accided has the same b64JSON prefix
+			if org, err := jsonparser.GetString(jsonToken, "org"); err == nil {
+				return org
+			}
+		}
+	}
+
+	// 24 is mongo bson id length
+	if len(token) > MongoBsonIdLength {
+		newToken := token[:MongoBsonIdLength]
+		_, err := hex.DecodeString(newToken)
+		if err == nil {
+			return newToken
+		}
+	}
+
+	return ""
+}

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}} ./...
 
   bench:
     desc: "Run benchmarks"