From 22b8611a464ce731886c21699985b69abe77da70 Mon Sep 17 00:00:00 2001
From: Bastian Krol <bastian.krol@web.de>
Date: Fri, 2 Feb 2024 16:22:03 +0100
Subject: [PATCH] [adservice,recommendationservice] add debug logs

---
 src/adservice/src/main/java/oteldemo/AdService.java | 5 ++++-
 src/adservice/src/main/resources/log4j2.xml         | 5 +++--
 src/recommendationservice/logger.py                 | 2 +-
 src/recommendationservice/recommendation_server.py  | 5 +++++
 4 files changed, 13 insertions(+), 4 deletions(-)

diff --git a/src/adservice/src/main/java/oteldemo/AdService.java b/src/adservice/src/main/java/oteldemo/AdService.java
index 5daa9f9da7..b96b114b8b 100644
--- a/src/adservice/src/main/java/oteldemo/AdService.java
+++ b/src/adservice/src/main/java/oteldemo/AdService.java
@@ -138,6 +138,7 @@ private AdServiceImpl(FeatureFlagServiceBlockingStub featureFlagServiceStub) {
      */
     @Override
     public void getAds(AdRequest req, StreamObserver<AdResponse> responseObserver) {
+      logger.debug("received getAds request");
       AdService service = AdService.getInstance();
 
       // get the current span in context
@@ -177,14 +178,16 @@ public void getAds(AdRequest req, StreamObserver<AdResponse> responseObserver) {
             Attributes.of(
                 adRequestTypeKey, adRequestType.name(), adResponseTypeKey, adResponseType.name()));
 
+        logger.debug("checking adServiceFailure feature flag");
         if (checkAdFailure()) {
-          logger.warn(ADSERVICE_FAIL_FEATURE_FLAG + " fail feature flag enabled");
+          logger.warn(ADSERVICE_FAIL_FEATURE_FLAG + " fail feature flag enabled, failing request.");
           throw new StatusRuntimeException(Status.RESOURCE_EXHAUSTED);
         }
 
         AdResponse reply = AdResponse.newBuilder().addAllAds(allAds).build();
         responseObserver.onNext(reply);
         responseObserver.onCompleted();
+        logger.debug("getAds request completed");
       } catch (StatusRuntimeException e) {
         span.addEvent(
             "Error", Attributes.of(AttributeKey.stringKey("exception.message"), e.getMessage()));
diff --git a/src/adservice/src/main/resources/log4j2.xml b/src/adservice/src/main/resources/log4j2.xml
index 470129edec..b4a067bbb7 100644
--- a/src/adservice/src/main/resources/log4j2.xml
+++ b/src/adservice/src/main/resources/log4j2.xml
@@ -18,14 +18,15 @@ limitations under the License.
 <Configuration status="WARN">
   <Appenders>
     <Console name="STDOUT" target="SYSTEM_OUT">
-      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} - %logger{36} - %msg trace_id=%X{trace_id} span_id=%X{span_id} trace_flags=%X{trace_flags} %n"/>
+      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss} - %level{WARN=WARNING, DEBUG=DEBUG, ERROR=ERROR, TRACE=TRACE, INFO=INFO} - %logger{36} - %msg trace_id=%X{trace_id} span_id=%X{span_id} trace_flags=%X{trace_flags} %n"/>
     </Console>
   </Appenders>
   <Loggers>
     <Logger name="io.grpc.netty" level="INFO"/>
     <Logger name="io.netty" level="INFO"/>
     <Logger name="sun.net" level="INFO"/>
-    <Root level="INFO">
+    <Logger name="oteldemo" level="DEBUG"/>
+    <Root level="DEBUG">
       <AppenderRef ref="STDOUT"/>
     </Root>
   </Loggers>
diff --git a/src/recommendationservice/logger.py b/src/recommendationservice/logger.py
index 0569665539..e6b39ef740 100644
--- a/src/recommendationservice/logger.py
+++ b/src/recommendationservice/logger.py
@@ -23,6 +23,6 @@ def getJSONLogger(name):
     formatter = CustomJsonFormatter('%(asctime)s %(levelname)s [%(name)s] [%(filename)s:%(lineno)d] [trace_id=%(otelTraceID)s span_id=%(otelSpanID)s] - %(message)s')
     handler.setFormatter(formatter)
     logger.addHandler(handler)
-    logger.setLevel(logging.INFO)
+    logger.setLevel(logging.DEBUG)
     logger.propagate = False
     return logger
diff --git a/src/recommendationservice/recommendation_server.py b/src/recommendationservice/recommendation_server.py
index 993d032698..970d921ac4 100644
--- a/src/recommendationservice/recommendation_server.py
+++ b/src/recommendationservice/recommendation_server.py
@@ -61,6 +61,7 @@ def Watch(self, request, context):
 
 
 def get_product_list(request_product_ids):
+    logger.debug("get_product_list: start")
     global first_run
     global cached_ids
     with tracer.start_as_current_span("get_product_list") as span:
@@ -71,7 +72,9 @@ def get_product_list(request_product_ids):
         request_product_ids = request_product_ids_str.split(',')
 
         # Feature flag scenario - Cache Leak
+        logger.debug("get_product_list: checking recommendationCache feature flag")
         if check_feature_flag("recommendationCache"):
+            logger.debug("get_product_list: recommendationCache feature flag is enabled")
             span.set_attribute("app.recommendation.cache_enabled", True)
             if random.random() < 0.5 or first_run:
                 first_run = False
@@ -87,6 +90,7 @@ def get_product_list(request_product_ids):
                 logger.info("get_product_list: cache hit")
                 product_ids = cached_ids
         else:
+            logger.debug("get_product_list: recommendationCache feature flag is not enabled")
             span.set_attribute("app.recommendation.cache_enabled", False)
             cat_response = product_catalog_stub.ListProducts(demo_pb2.Empty())
             product_ids = [x.id for x in cat_response.products]
@@ -106,6 +110,7 @@ def get_product_list(request_product_ids):
 
         span.set_attribute("app.filtered_products.list", prod_list)
 
+        logger.debug("get_product_list: done")
         return prod_list