log: change log format to JSON payload for better log in Stackdriver (#66)

change the log format in Python and Node.js services.

Effected services are currencyservice, emailservice, paymentservice,
and recommendationservice. Loadgenerator is left as is because of
the diffculty to change the log format and log target in locust.

ref. #47

src/recommendationservice/client.py

@@ -14,15 +14,18 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
+import sys
 import grpc
 import demo_pb2
 import demo_pb2_grpc
-import sys
 
 from opencensus.trace.tracer import Tracer
 from opencensus.trace.exporters import stackdriver_exporter
 from opencensus.trace.ext.grpc import client_interceptor
 
+from logger import getJSONLogger
+logger = getJSONLogger('recommendationservice-server')
+
 if __name__ == "__main__":
     # get port
     if len(sys.argv) > 1:
@@ -45,4 +48,4 @@ if __name__ == "__main__":
     request = demo_pb2.ListRecommendationsRequest(user_id="test", product_ids=["test"])
     # make call to server
     response = stub.ListRecommendations(request)
-    print(response)
+    logger.info(response)

src/recommendationservice/logger.py

@@ -0,0 +1,40 @@
+#!/usr/bin/python
+#
+# Copyright 2018 Google LLC
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#      http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+import logging
+import sys
+from pythonjsonlogger import jsonlogger
+
+# TODO(yoshifumi) this class is duplicated since other Python services are
+# not sharing the modules for logging.
+class CustomJsonFormatter(jsonlogger.JsonFormatter):
+  def add_fields(self, log_record, record, message_dict):
+    super(CustomJsonFormatter, self).add_fields(log_record, record, message_dict)
+    if not log_record.get('timestamp'):
+      log_record['timestamp'] = record.created
+    if log_record.get('severity'):
+      log_record['severity'] = log_record['severity'].upper()
+    else:
+      log_record['severity'] = record.levelname
+
+def getJSONLogger(name):
+  logger = logging.getLogger(name)
+  handler = logging.StreamHandler(sys.stdout)
+  formatter = CustomJsonFormatter('(timestamp) (severity) (name) (message)')
+  handler.setFormatter(formatter)
+  logger.addHandler(handler)
+  logger.setLevel(logging.INFO)
+  return logger

src/recommendationservice/recommendation_server.py

@@ -18,8 +18,8 @@ import grpc
 from concurrent import futures
 import time
 import traceback
-import random
 import os
+import random
 import googleclouddebugger
 
 import demo_pb2
@@ -27,6 +27,8 @@ import demo_pb2_grpc
 from grpc_health.v1 import health_pb2
 from grpc_health.v1 import health_pb2_grpc
 
+from logger import getJSONLogger
+logger = getJSONLogger('recommendationservice-server')
 
 # TODO(morganmclean,ahmetb) tracing currently disabled due to memory leak (see TODO below)
 # from opencensus.trace.ext.grpc import server_interceptor
@@ -47,7 +49,7 @@ class RecommendationService(demo_pb2_grpc.RecommendationServiceServicer):
         indices = random.sample(range(num_products), num_return)
         # fetch product ids from indices
         prod_list = [filtered_products[i] for i in indices]
-        print("[Recv ListRecommendations] product_ids={}".format(prod_list))
+        logger.info("[Recv ListRecommendations] product_ids={}".format(prod_list))
         # build and return response
         response = demo_pb2.ListRecommendationsResponse()
         response.product_ids.extend(prod_list)
@@ -59,7 +61,7 @@ class RecommendationService(demo_pb2_grpc.RecommendationServiceServicer):
 
 
 if __name__ == "__main__":
-    print("initializing recommendationservice")
+    logger.info("initializing recommendationservice")
 
     # TODO(morganmclean,ahmetb) enabling the tracing interceptor/sampler below
     # causes an unbounded memory leak eventually OOMing the container.
@@ -77,15 +79,15 @@ if __name__ == "__main__":
             version='1.0.0'
         )
     except Exception, err:
-        print("could not enable debugger")
-        traceback.print_exc()
+        logger.error("could not enable debugger")
+        logger.error(traceback.print_exc())
         pass
 
     port = os.environ.get('PORT', "8080")
     catalog_addr = os.environ.get('PRODUCT_CATALOG_SERVICE_ADDR', '')
     if catalog_addr == "":
         raise Exception('PRODUCT_CATALOG_SERVICE_ADDR environment variable not set')
-    print("product catalog address: " + catalog_addr)
+    logger.info("product catalog address: " + catalog_addr)
     channel = grpc.insecure_channel(catalog_addr)
     product_catalog_stub = demo_pb2_grpc.ProductCatalogServiceStub(channel)
 
@@ -98,7 +100,7 @@ if __name__ == "__main__":
     health_pb2_grpc.add_HealthServicer_to_server(service, server)
 
     # start server
-    print("listening on port: " + port)
+    logger.info("listening on port: " + port)
     server.add_insecure_port('[::]:'+port)
     server.start()
 

src/recommendationservice/requirements.txt

@@ -20,6 +20,7 @@ opencensus==0.1.5
 protobuf==3.5.2.post1
 pyasn1==0.4.3
 pyasn1-modules==0.2.2
+python-json-logger==0.1.9
 pytz==2018.5
 PyYAML==3.13
 requests==2.19.1