Merge pull request #1305 from PasanT9/trace-header

Improve adapter and enforcer logs

adapter/internal/discovery/xds/ratelimiter_cache.go

@@ -85,7 +85,7 @@ func (r *rateLimitPolicyCache) AddAPILevelRateLimitPolicies(vHosts []string, ada
 			method := operation.GetMethod()
 			if _, ok := apiOperations[path][method]; ok {
 				// Unreachable if the swagger definition is valid
-				loggers.LoggerXds.Warnf("Duplicate API resource HTTP method %q %q in the swagger definition, skipping rate limit policy for the duplicate resource.", path, method)
+				loggers.LoggerXds.Warnf("Duplicate API resource HTTP method %q %q in the swagger definition, skipping rate limit policy for the duplicate resource. API_UUID: %v", path, method, logging.GetValueFromLogContext("API_UUID"))
 				continue
 			}
 
@@ -231,7 +231,7 @@ func (r *rateLimitPolicyCache) updateXdsCache(label string) bool {
 		loggers.LoggerXds.ErrorC(logging.GetErrorByCode(1716, err.Error()))
 		return false
 	}
-	loggers.LoggerXds.Infof("New rate limit cache updated for the label: %q version: %q", label, version)
+	loggers.LoggerXds.Infof("New rate limit cache updated for the label: %q version: %q, API_UUID: %v", label, version, logging.GetValueFromLogContext("API_UUID"))
 	loggers.LoggerXds.Debug("Updated rate limit config: ", rlsConf)
 	return true
 }

adapter/internal/discovery/xds/server.go

@@ -243,6 +243,7 @@ func GetEnforcerThrottleDataCache() wso2_cache.SnapshotCache {
 
 // DeleteAPICREvent deletes API with the given UUID from the given gw environments
 func DeleteAPICREvent(labels []string, apiUUID string, organizationID string) error {
+	logging.SetValueToLogContext("API_UUID", apiUUID)
 	mutexForInternalMapUpdate.Lock()
 	defer mutexForInternalMapUpdate.Unlock()
 
@@ -261,8 +262,8 @@ func DeleteAPICREvent(labels []string, apiUUID string, organizationID string) er
 		}
 		// if no error, update internal vhost maps
 		// error only happens when API not found in deleteAPI func
-		logger.LoggerXds.Infof("Successfully undeployed the API %v under Organization %s and environment %s ",
-			apiIdentifier, organizationID, labels)
+		logger.LoggerXds.Infof("Successfully undeployed the API %v under Organization %s and environment %s, API_UUID: %v ",
+			apiIdentifier, organizationID, labels, logging.GetValueFromLogContext("API_UUID"))
 	}
 	return nil
 }
@@ -271,11 +272,11 @@ func DeleteAPICREvent(labels []string, apiUUID string, organizationID string) er
 func deleteAPI(apiIdentifier string, environments []string, organizationID string) error {
 	if _, orgExists := orgAPIMap[organizationID]; orgExists {
 		if _, apiExists := orgAPIMap[organizationID][apiIdentifier]; !apiExists {
-			logger.LoggerXds.Infof("Unable to delete API: %v from Organization: %v. API Does not exist.", apiIdentifier, organizationID)
+			logger.LoggerXds.Infof("Unable to delete API: %v from Organization: %v. API Does not exist. API_UUID: %v", apiIdentifier, organizationID, logging.GetValueFromLogContext("API_UUID"))
 			return errors.New(constants.NotFound)
 		}
 	} else {
-		logger.LoggerXds.Infof("Unable to delete API: %v from Organization: %v. Organization Does not exist.", apiIdentifier, organizationID)
+		logger.LoggerXds.Infof("Unable to delete API: %v from Organization: %v. Organization Does not exist. API_UUID: %v", apiIdentifier, organizationID, logging.GetValueFromLogContext("API_UUID"))
 		return errors.New(constants.NotFound)
 	}
 
@@ -291,8 +292,8 @@ func deleteAPI(apiIdentifier string, environments []string, organizationID strin
 			if len(toBeKeptEnvs) != 0 {
 				return nil
 			}
-			logger.LoggerXds.Infof("API identifier: %v does not have any gateways. Hence deleting the API from label : %s.",
-				apiIdentifier, val)
+			logger.LoggerXds.Infof("API identifier: %v does not have any gateways. Hence deleting the API from label : %s. API_UUID: %v",
+				apiIdentifier, val, logging.GetValueFromLogContext("API_UUID"))
 			cleanMapResources(apiIdentifier, organizationID, toBeDelEnvs)
 			return nil
 		}
@@ -541,7 +542,7 @@ func updateXdsCache(label string, endpoints []types.Resource, clusters []types.R
 		logger.LoggerXds.ErrorC(logging.GetErrorByCode(1414, errSetSnap.Error()))
 		return false
 	}
-	logger.LoggerXds.Infof("New Router cache updated for the label: " + label + " version: " + fmt.Sprint(version))
+	logger.LoggerXds.Infof("New Router cache updated for the label: " + label + " version: " + fmt.Sprint(version) + ", API_UUID: %v", logging.GetValueFromLogContext("API_UUID"))
 	return true
 }
 
@@ -589,7 +590,7 @@ func UpdateEnforcerApis(label string, apis []types.Resource, version string) {
 	if errSetSnap != nil {
 		logger.LoggerXds.ErrorC(logging.GetErrorByCode(1414, errSetSnap.Error()))
 	}
-	logger.LoggerXds.Infof("New API cache update for the label: " + label + " version: " + fmt.Sprint(version))
+	logger.LoggerXds.Infof("New API cache update for the label: " + label + " version: " + fmt.Sprint(version) + ", API_UUID: %v", logging.GetValueFromLogContext("API_UUID"))
 
 	subAPIs := []*subscription.APIs{}
 	for _, api := range apis {
@@ -673,7 +674,7 @@ func UpdateEnforcerJWTIssuers(jwtIssuers *subscription.JWTIssuerList) {
 
 // UpdateEnforcerAPIList sets new update to the enforcer's Apis
 func UpdateEnforcerAPIList(label string, apis *subscription.APIList) {
-	logger.LoggerXds.Debug("Updating Enforcer API Cache")
+	logger.LoggerXds.Debugf("Updating Enforcer API Cache, API_UUID: %v", logging.GetValueFromLogContext("API_UUID"))
 	apiList := append(enforcerLabelMap[label].apiList, apis)
 
 	version := rand.Intn(maxRandomInt)
@@ -687,7 +688,7 @@ func UpdateEnforcerAPIList(label string, apis *subscription.APIList) {
 		logger.LoggerXds.ErrorC(logging.GetErrorByCode(1414, errSetSnap.Error()))
 	}
 	enforcerLabelMap[label].apiList = apiList
-	logger.LoggerXds.Infof("New API List cache update for the label: " + label + " version: " + fmt.Sprint(version))
+	logger.LoggerXds.Infof("New API List cache update for the label: " + label + " version: " + fmt.Sprint(version) + ", API_UUID: %v", logging.GetValueFromLogContext("API_UUID"))
 }
 
 // UpdateEnforcerApplicationPolicies sets new update to the enforcer's Application Policies
@@ -924,7 +925,7 @@ func UpdateAPICache(vHosts []string, newLabels []string, newlistenersForRoutes [
 		}
 
 		revisionStatus := updateXdsCacheOnAPIChange(oldLabels, newLabels)
-		logger.LoggerXds.Infof("Deployed Revision: %v:%v", apiIdentifier, revisionStatus)
+		logger.LoggerXds.Infof("Deployed Revision: %v:%v, API_UUID: %v", apiIdentifier, revisionStatus, logging.GetValueFromLogContext("API_UUID"))
 	}
 	return nil
 }

adapter/internal/logging/loggin_utils.go

@@ -18,11 +18,16 @@
 package logging
 
 import (
+	"context"
 	"fmt"
 
 	logging "github.com/wso2/apk/adapter/pkg/logging"
 )
 
+var logContext context.Context
+
+type logContextKey string
+
 // GetErrorByCode used to keep error details for error logs
 func GetErrorByCode(code int, args ...interface{}) logging.ErrorDetails {
 	errorLog, ok := Mapper[code]
@@ -36,3 +41,42 @@ func GetErrorByCode(code int, args ...interface{}) logging.ErrorDetails {
 	errorLog.Message = fmt.Sprintf(errorLog.Message, args...)
 	return errorLog
 }
+
+// SetValueToContext used to set the value in the context
+func SetValueToContext(ctx context.Context, key logContextKey, value interface{}) context.Context {
+	return context.WithValue(ctx, key, value)
+}
+
+// GetValueFromContext used to retrieve the value from the context
+func GetValueFromContext(ctx context.Context, key logContextKey) interface{} {
+	return ctx.Value(key)
+}
+
+// InitializeContext used to initialize logContext
+func InitializeContext() {
+	logContext = context.Background()
+}
+
+// SetValueToLogContext used to set values to logContext
+func SetValueToLogContext(key logContextKey, value interface{}) {
+	if logContext == nil {
+		InitializeContext()
+	}
+	logContext = SetValueToContext(logContext, key, value)
+}
+
+// GetValueFromLogContext used to retrieve values from logContext
+func GetValueFromLogContext(key logContextKey) interface{} {
+	if logContext == nil {
+		return nil
+	}
+	return GetValueFromContext(logContext, key)
+}
+
+// RemoveValueFromLogContext used to remove values from logContext
+func RemoveValueFromLogContext(key logContextKey) {
+	if logContext == nil {
+		return
+	}
+	logContext = SetValueToContext(logContext, key, nil)
+}

adapter/internal/oasparser/model/adapter_internal_api.go

@@ -28,6 +28,7 @@ import (
 	"github.com/wso2/apk/adapter/config"
 	"github.com/wso2/apk/adapter/internal/interceptor"
 	logger "github.com/wso2/apk/adapter/internal/loggers"
+	"github.com/wso2/apk/adapter/internal/logging"
 	"github.com/wso2/apk/adapter/internal/oasparser/constants"
 	dpv1alpha1 "github.com/wso2/apk/adapter/internal/operator/apis/dp/v1alpha1"
 )
@@ -363,14 +364,14 @@ func (swagger *AdapterInternalAPI) GetOrganizationID() string {
 func (swagger *AdapterInternalAPI) Validate() error {
 	for _, res := range swagger.resources {
 		if res.endpoints == nil || len(res.endpoints.Endpoints) == 0 {
-			logger.LoggerOasparser.Errorf("No Endpoints are provided for the resources in %s:%s",
-				swagger.title, swagger.version)
+			logger.LoggerOasparser.Errorf("No Endpoints are provided for the resources in %s:%s, API_UUID: %v",
+				swagger.title, swagger.version, logging.GetValueFromLogContext("API_UUID"))
 			return errors.New("no endpoints are provided for the API")
 		}
 		err := res.endpoints.validateEndpointCluster()
 		if err != nil {
-			logger.LoggerOasparser.Errorf("Error while parsing the endpoints of the API %s:%s - %v",
-				swagger.title, swagger.version, err)
+			logger.LoggerOasparser.Errorf("Error while parsing the endpoints of the API %s:%s - %v, API_UUID: %v",
+				swagger.title, swagger.version, err, logging.GetValueFromLogContext("API_UUID"))
 			return err
 		}
 	}

adapter/internal/oasparser/model/http_route.go

@@ -23,6 +23,7 @@ import (
 	"github.com/google/uuid"
 	"github.com/wso2/apk/adapter/config"
 	"github.com/wso2/apk/adapter/internal/loggers"
+	"github.com/wso2/apk/adapter/internal/logging"
 	"github.com/wso2/apk/adapter/internal/oasparser/constants"
 	dpv1alpha1 "github.com/wso2/apk/adapter/internal/operator/apis/dp/v1alpha1"
 	"github.com/wso2/apk/adapter/internal/operator/utils"
@@ -231,7 +232,7 @@ func (swagger *AdapterInternalAPI) SetInfoHTTPRouteCR(httpRoute *gwapiv1b1.HTTPR
 			addOperationLevelInterceptors(&policies, resourceAPIPolicy, httpRouteParams.InterceptorServiceMapping, httpRouteParams.BackendMapping)
 		}
 
-		loggers.LoggerOasparser.Debugf("Calculating auths for API ...")
+		loggers.LoggerOasparser.Debugf("Calculating auths for API ..., API_UUID = %v", logging.GetValueFromLogContext("API_UUID"))
 		apiAuth := getSecurity(resourceAuthScheme)
 		if len(rule.BackendRefs) < 1 {
 			return fmt.Errorf("no backendref were provided")

adapter/internal/operator/main.go

@@ -22,6 +22,7 @@ import (
 
 	"github.com/wso2/apk/adapter/config"
 	"github.com/wso2/apk/adapter/internal/loggers"
+	internalLogging "github.com/wso2/apk/adapter/internal/logging"
 	"github.com/wso2/apk/adapter/internal/management-server/xds"
 	"github.com/wso2/apk/adapter/pkg/logging"
 	gwapiv1a2 "sigs.k8s.io/gateway-api/apis/v1alpha2"
@@ -155,6 +156,7 @@ func InitOperator() {
 		loggers.LoggerAPKOperator.ErrorC(logging.GetErrorByCode(2603, err))
 	}
 
+	internalLogging.InitializeContext()
 	go synchronizer.HandleAPILifeCycleEvents(&ch, &successChannel)
 	go synchronizer.HandleGatewayLifeCycleEvents(&gatewaych)
 	if config.ReadConfigs().ManagementServer.Enabled {
@@ -169,4 +171,5 @@ func InitOperator() {
 	if err := mgr.Start(ctrl.SetupSignalHandler()); err != nil {
 		loggers.LoggerAPKOperator.ErrorC(logging.GetErrorByCode(2604, err))
 	}
+	internalLogging.RemoveValueFromLogContext("API_UUID")
 }

adapter/internal/operator/synchronizer/synchronizer.go

@@ -30,6 +30,7 @@ import (
 
 	"github.com/wso2/apk/adapter/config"
 	"github.com/wso2/apk/adapter/internal/loggers"
+	internalLogging "github.com/wso2/apk/adapter/internal/logging"
 	model "github.com/wso2/apk/adapter/internal/oasparser/model"
 	"github.com/wso2/apk/adapter/internal/operator/constants"
 	"github.com/wso2/apk/adapter/internal/operator/utils"
@@ -139,6 +140,7 @@ func GenerateAdapterInternalAPI(apiState APIState, httpRoute *HTTPRouteState, en
 	var adapterInternalAPI model.AdapterInternalAPI
 	adapterInternalAPI.SetInfoAPICR(*apiState.APIDefinition)
 	adapterInternalAPI.SetAPIDefinitionFile(apiState.APIDefinitionFile)
+	internalLogging.SetValueToLogContext("API_UUID", adapterInternalAPI.UUID)
 	adapterInternalAPI.EnvType = envType
 	httpRouteParams := model.HTTPRouteParams{
 		AuthSchemes:               httpRoute.Authentications,
@@ -203,8 +205,8 @@ func getLabelsForAPI(httpRoute *gwapiv1b1.HTTPRoute) []string {
 func getListenersForAPI(httpRoute *gwapiv1b1.HTTPRoute) []string {
 	var listeners []string
 	for _, parentRef := range httpRoute.Spec.ParentRefs {
-		loggers.LoggerAPKOperator.Debugf("Recieved Parent Refs:%v", parentRef)
-		loggers.LoggerAPKOperator.Debugf("Recieved Parent Refs Section Name:%v", string(*parentRef.SectionName))
+		loggers.LoggerAPKOperator.Debugf("Recieved Parent Refs:%v, API_UUID: %v", parentRef, internalLogging.GetValueFromLogContext("API_UUID"))
+		loggers.LoggerAPKOperator.Debugf("Recieved Parent Refs Section Name:%v, API_UUID: %v", string(*parentRef.SectionName), internalLogging.GetValueFromLogContext("API_UUID"))
 		listeners = append(listeners, string(*parentRef.SectionName))
 	}
 	return listeners
@@ -231,7 +233,7 @@ func SendEventToPartitionServer() {
 	conf := config.ReadConfigs()
 	for apiEvent := range paritionCh {
 		if !apiEvent.Event.APIDefinition.Spec.SystemAPI {
-			loggers.LoggerAPKOperator.Infof("Sending API to APK management server: %v", apiEvent.Event.APIDefinition.Spec.APIDisplayName)
+			loggers.LoggerAPKOperator.Infof("Sending API to APK management server: %v, API_UUID: %v", apiEvent.Event.APIDefinition.Spec.APIDisplayName, internalLogging.GetValueFromLogContext("API_UUID"))
 			api := apiEvent.Event
 			eventType := apiEvent.EventType
 			context := api.APIDefinition.Spec.Context
@@ -259,16 +261,16 @@ func SendEventToPartitionServer() {
 			}
 			payload, err := json.Marshal(data)
 			if err != nil {
-				loggers.LoggerAPKOperator.Errorf("Error creating Event: %v", err)
+				loggers.LoggerAPKOperator.Errorf("Error creating Event: %v, API_UUID: %v", err, internalLogging.GetValueFromLogContext("API_UUID"))
 			}
 			req, err := http.NewRequest(http.MethodPost, fmt.Sprintf("%s%s%s", conf.PartitionServer.Host, conf.PartitionServer.ServiceBasePath, "/api-deployment"), bytes.NewBuffer(payload))
 			if err != nil {
-				loggers.LoggerAPKOperator.Errorf("Error creating api definition request: %v", err)
+				loggers.LoggerAPKOperator.Errorf("Error creating api definition request: %v, API_UUID: %v", err, internalLogging.GetValueFromLogContext("API_UUID"))
 			}
 			req.Header.Set("Content-Type", "application/json; charset=UTF-8")
 			resp, err := partitionClient.Do(req)
 			if err != nil {
-				loggers.LoggerAPKOperator.Errorf("Error sending API Event: %v", err)
+				loggers.LoggerAPKOperator.Errorf("Error sending API Event: %v, API_UUID: %v", err, internalLogging.GetValueFromLogContext("API_UUID"))
 			}
 			if resp.StatusCode == http.StatusAccepted {
 				loggers.LoggerAPKOperator.Info("API Event Accepted", resp.Status)

gateway/enforcer/org.wso2.apk.enforcer/src/main/java/org/wso2/apk/enforcer/constants/APIConstants.java

@@ -89,6 +89,7 @@ public class APIConstants {
     // SOAP protocol versions
     public static final String SOAP11_PROTOCOL = "SOAP 1.1 Protocol";
     public static final String SOAP12_PROTOCOL = "SOAP 1.2 Protocol";
+    public static final String API_UUID = "API_UUID";
 
     /**
      * Holds the constants related to denied response types.

gateway/enforcer/org.wso2.apk.enforcer/src/main/java/org/wso2/apk/enforcer/grpc/ExtAuthService.java

@@ -85,8 +85,9 @@ public void check(CheckRequest request, StreamObserver<CheckResponse> responseOb
             responseObserver.onNext(response);
             // When you are done, you must call onCompleted.
             responseObserver.onCompleted();
-            ThreadContext.remove(APIConstants.LOG_TRACE_ID);
         } finally {
+            ThreadContext.remove(APIConstants.LOG_TRACE_ID);
+            ThreadContext.remove(APIConstants.API_UUID);
             if (Utils.tracingEnabled()) {
                 extAuthServiceSpanScope.close();
                 Utils.finishSpan(extAuthServiceSpan);

gateway/enforcer/org.wso2.apk.enforcer/src/main/java/org/wso2/apk/enforcer/server/HttpRequestHandler.java

@@ -59,6 +59,7 @@ public ResponseObject process(CheckRequest request) {
             return responseObject;
         }
         APIConfig api = matchedAPI.getAPIConfig();
+        ThreadContext.put(APIConstants.API_UUID, api.getUuid());
         logger.debug("API {}/{} found in the cache", api.getBasePath(), api.getVersion());
 
         // putting API details into ThreadContext for logging purposes

gateway/enforcer/resources/conf/log4j2.properties

@@ -5,7 +5,8 @@ appenders = ENFORCER_CONSOLE, ENFORCER_LOGFILE, ENFORCER_ACCESS_LOG
 appender.ENFORCER_CONSOLE.type = Console
 appender.ENFORCER_CONSOLE.name = ENFORCER_CONSOLE
 appender.ENFORCER_CONSOLE.layout.type = PatternLayout
-appender.ENFORCER_CONSOLE.layout.pattern = [%d{DEFAULT}][%X{traceId}]%x %5p - {%c} - %m [%errorDetails]%n
+appender.ENFORCER_CONSOLE.layout.pattern = [%d{DEFAULT}][TRACE_ID: %X{traceId}][API_UUID: %X{API_UUID}]%x %5p - {%c} - \
+  %m [%errorDetails]%n
 appender.ENFORCER_CONSOLE.filter.threshold.type = ThresholdFilter
 appender.ENFORCER_CONSOLE.filter.threshold.level = DEBUG
 

helm-charts/templates/data-plane/gateway-components/log-conf.yaml

@@ -795,7 +795,7 @@ data:
     appender.ENFORCER_CONSOLE.type = Console
     appender.ENFORCER_CONSOLE.name = ENFORCER_CONSOLE
     appender.ENFORCER_CONSOLE.layout.type = PatternLayout
-    appender.ENFORCER_CONSOLE.layout.pattern = [%d{DEFAULT}][%X{traceId}]%x %5p - {%c} - %m [%errorDetails]%n
+    appender.ENFORCER_CONSOLE.layout.pattern = [%d{DEFAULT}][TRACE_ID: %X{traceId}][API_UUID: %X{API_UUID}]%x %5p - {%c} - \%m [%errorDetails]%n
     appender.ENFORCER_CONSOLE.filter.threshold.type = ThresholdFilter
     appender.ENFORCER_CONSOLE.filter.threshold.level = DEBUG