misc performance optimizations

1. Replace chained withFields to use a single WithFields
2. check for debug log enabled before invoking debug logs
3. store request logger in the context to minimize amount of instantiation calls.

Author: sedkis

ctx/ctx.go

@@ -53,6 +53,7 @@ const (
 	CacheOptions
 	OASDefinition
 	SelfLooping
+	RequestLogger
 )
 
 func ctxSetSession(r *http.Request, s *user.SessionState, scheduleUpdate bool, hashKey bool) {

gateway/api.go

@@ -3381,6 +3381,19 @@ func ctxGetRequestStatus(r *http.Request) (stat RequestStatus) {
 	return
 }
 
+func ctxSetRequestLogger(r *http.Request, logger *logrus.Entry) {
+	setCtxValue(r, ctx.RequestLogger, logger)
+}
+
+func ctxGetRequestLogger(r *http.Request) *logrus.Entry {
+	if v := r.Context().Value(ctx.RequestLogger); v != nil {
+		if logger, ok := v.(*logrus.Entry); ok {
+			return logger
+		}
+	}
+	return nil
+}
+
 var createOauthClientSecret = func() string {
 	secret := uuid.New()
 	return base64.StdEncoding.EncodeToString([]byte(secret))

gateway/log_helpers.go

@@ -65,3 +65,18 @@ func (gw *Gateway) getExplicitLogEntryForRequest(logger *logrus.Entry, path stri
 	}
 	return logger.WithFields(fields)
 }
+
+// getOrCreateRequestLogger returns a cached logger from the request context
+// or creates a new one if it doesn't exist. This reduces allocations by
+// ensuring the logger is only created once per request instead of once per middleware.
+func (gw *Gateway) getOrCreateRequestLogger(r *http.Request, key string) *logrus.Entry {
+	// Check if logger already exists in context
+	if logger := ctxGetRequestLogger(r); logger != nil {
+		return logger
+	}
+
+	// Create new logger and cache it in context
+	logger := gw.getLogEntryForRequest(logrus.NewEntry(log), r, key, nil)
+	ctxSetRequestLogger(r, logger)
+	return logger
+}

gateway/middleware.go

@@ -161,7 +161,12 @@ func (gw *Gateway) createMiddleware(actualMW TykMiddleware) func(http.Handler) h
 			}
 
 			startTime := time.Now()
-			logger.WithField("ts", startTime.UnixNano()).WithField("mw", mw.Name()).Debug("Started")
+			if logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+				logger.WithFields(logrus.Fields{
+					"ts": startTime.UnixNano(),
+					"mw": mw.Name(),
+				}).Debug("Started")
+			}
 
 			if mw.Base().Spec.CORS.OptionsPassthrough && r.Method == "OPTIONS" {
 				next.ServeHTTP(w, r)
@@ -189,7 +194,13 @@ func (gw *Gateway) createMiddleware(actualMW TykMiddleware) func(http.Handler) h
 					job.TimingKv(eventName+".exec_time", finishTime.Nanoseconds(), meta)
 				}
 
-				logger.WithError(err).WithField("code", errCode).WithField("ns", finishTime.Nanoseconds()).Debug("Finished")
+				if logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+					logger.WithFields(logrus.Fields{
+						"error": err,
+						"code":  errCode,
+						"ns":    finishTime.Nanoseconds(),
+					}).Debug("Finished")
+				}
 				return
 			}
 
@@ -200,7 +211,12 @@ func (gw *Gateway) createMiddleware(actualMW TykMiddleware) func(http.Handler) h
 				job.TimingKv(eventName+".exec_time", finishTime.Nanoseconds(), meta)
 			}
 
-			logger.WithField("code", errCode).WithField("ns", finishTime.Nanoseconds()).Debug("Finished")
+			if logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+				logger.WithFields(logrus.Fields{
+					"code": errCode,
+					"ns":   finishTime.Nanoseconds(),
+				}).Debug("Finished")
+			}
 
 			mw.Base().UpdateRequestSession(r)
 			// Special code, bypasses all other execution
@@ -315,14 +331,8 @@ func (t *BaseMiddleware) Logger() (logger *logrus.Entry) {
 }
 
 func (t *BaseMiddleware) SetRequestLogger(r *http.Request) *logrus.Entry {
-	t.loggerMu.Lock()
-	defer t.loggerMu.Unlock()
-
-	if t.logger == nil {
-		t.logger = logrus.NewEntry(log)
-	}
-	t.logger = t.Gw.getLogEntryForRequest(t.logger, r, ctxGetAuthToken(r), nil)
-	return t.logger
+	// Use context-based logger to avoid shared state mutation and reduce allocations
+	return t.Gw.getOrCreateRequestLogger(r, ctxGetAuthToken(r))
 }
 
 func (t *BaseMiddleware) Init() {}

gateway/middleware_decorators.go

@@ -22,7 +22,10 @@ func withLogger(
 ) tykResponseDecorator {
 
 	return func(origin TykResponseHandler) TykResponseHandler {
-		origin.setLogger(logger.WithField("mw", origin.Name()).WithField("type", "response"))
+		origin.setLogger(logger.WithFields(logrus.Fields{
+			"mw":   origin.Name(),
+			"type": "response",
+		}))
 
 		return &logDecorator{
 			TykResponseHandler: origin,
@@ -51,14 +54,19 @@ func (d *logDecorator) HandleResponse(
 ) error {
 
 	start := time.Now()
-	d.logger().WithField("ts", start.UnixNano()).Debug("Started")
+	logger := d.logger()
+	if logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+		logger.WithField("ts", start.UnixNano()).Debug("Started")
+	}
 
 	if err := d.TykResponseHandler.HandleResponse(writer, response, request, state); err != nil {
 		d.logger().WithField("ns", time.Since(start).Nanoseconds()).WithError(err).Error("Failed to process response")
 		return err
 	}
 
-	d.logger().WithField("ns", time.Since(start).Nanoseconds()).Debug("Finished")
+	if logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+		logger.WithField("ns", time.Since(start).Nanoseconds()).Debug("Finished")
+	}
 
 	return nil
 }

gateway/mw_granular_access.go

@@ -69,7 +69,11 @@ func (m *GranularAccessMiddleware) ProcessRequest(w http.ResponseWriter, r *http
 			// if loglevel is set to debug verbosity increases and all requests are logged,
 			// regardless if an error occured or not.
 			if gwConfig.LogLevel == "debug" || err != nil {
-				logger = logger.WithError(err).WithField("pattern", pattern).WithField("match", match)
+				logger = logger.WithFields(logrus.Fields{
+				"error":   err,
+				"pattern": pattern,
+				"match":   match,
+			})
 				if err != nil {
 					logger.Error("error matching endpoint")
 				} else {

gateway/mw_url_rewrite.go

@@ -536,7 +536,11 @@ func (m *URLRewriteMiddleware) ProcessRequest(w http.ResponseWriter, r *http.Req
 	}
 
 	if err = m.CheckHostRewrite(oldPath, p, r); err != nil {
-		log.WithError(err).WithField("from", oldPath).WithField("to", p).Error("Checking Host rewrite: error parsing URL")
+		log.WithFields(logrus.Fields{
+			"error": err,
+			"from":  oldPath,
+			"to":    p,
+		}).Error("Checking Host rewrite: error parsing URL")
 	}
 
 	newURL, err := url.Parse(p)

gateway/proxy_muxer.go

@@ -206,8 +206,10 @@ func (m *proxyMux) setRouter(port int, protocol string, router *mux.Router, conf
 func (m *proxyMux) handle404(w http.ResponseWriter, r *http.Request) {
 	if m.track404Logs {
 		requestMeta := fmt.Sprintf("%s %s %s", r.Method, r.URL.Path, r.Proto)
-		log.WithField("request", requestMeta).WithField("origin", r.RemoteAddr).
-			Error(http.StatusText(http.StatusNotFound))
+		log.WithFields(logrus.Fields{
+			"request": requestMeta,
+			"origin":  r.RemoteAddr,
+		}).Error(http.StatusText(http.StatusNotFound))
 	}
 
 	w.WriteHeader(http.StatusNotFound)

gateway/reverse_proxy.go

@@ -516,12 +516,16 @@ var hopHeaders = []string{
 
 func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) ProxyResponse {
 	startTime := time.Now()
-	p.logger.WithField("ts", startTime.UnixNano()).Debug("Started")
+	if p.logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+		p.logger.WithField("ts", startTime.UnixNano()).Debug("Started")
+	}
 
 	resp := p.WrappedServeHTTP(rw, req, recordDetail(req, p.TykAPISpec))
 
 	finishTime := time.Since(startTime)
-	p.logger.WithField("ns", finishTime.Nanoseconds()).Debug("Finished")
+	if p.logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+		p.logger.WithField("ns", finishTime.Nanoseconds()).Debug("Finished")
+	}
 
 	// make response body to be nopCloser and re-readable before serve it through chain of middlewares
 	nopCloseResponseBody(resp.Response)
@@ -531,12 +535,16 @@ func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) Prox
 
 func (p *ReverseProxy) ServeHTTPForCache(rw http.ResponseWriter, req *http.Request) ProxyResponse {
 	startTime := time.Now()
-	p.logger.WithField("ts", startTime.UnixNano()).Debug("Started")
+	if p.logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+		p.logger.WithField("ts", startTime.UnixNano()).Debug("Started")
+	}
 
 	resp := p.WrappedServeHTTP(rw, req, true)
 	nopCloseResponseBody(resp.Response)
 	finishTime := time.Since(startTime)
-	p.logger.WithField("ns", finishTime.Nanoseconds()).Debug("Finished")
+	if p.logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+		p.logger.WithField("ns", finishTime.Nanoseconds()).Debug("Finished")
+	}
 
 	return resp
 }
@@ -831,7 +839,9 @@ func (rt *TykRoundTripper) RoundTrip(r *http.Request) (*http.Response, error) {
 			return nil, errors.New("handler could")
 		}
 
-		rt.logger.WithField("looping_url", "tyk://"+r.Host).Debug("Executing request on internal route")
+		if rt.logger.Logger.IsLevelEnabled(logrus.DebugLevel) {
+			rt.logger.WithField("looping_url", "tyk://"+r.Host).Debug("Executing request on internal route")
+		}
 
 		return handleInMemoryLoop(handler, r)
 	}