From e858902995ae35619e69a8402d1932b182f58d78 Mon Sep 17 00:00:00 2001 From: Yoshi Yamaguchi Date: Wed, 3 Oct 2018 12:58:14 +0900 Subject: [PATCH] log: use python-json-logger and create CustomJsonFormatter python-json-logger is one of the most popular JSON formatter for Python logging and it requires a custom class to fit the log spec of Stackdriver Logging. As Python projects in this project do not share the logger module, the custom logger module needs to be duplicated in each micro services. --- src/emailservice/email_client.py | 16 +++----- src/emailservice/email_server.py | 18 ++++---- src/emailservice/logger.py | 41 +++++++++---------- src/emailservice/requirements.txt | 3 +- src/recommendationservice/client.py | 12 ++---- src/recommendationservice/logger.py | 41 +++++++++---------- .../recommendation_server.py | 22 ++++------ src/recommendationservice/requirements.txt | 1 + 8 files changed, 69 insertions(+), 85 deletions(-) diff --git a/src/emailservice/email_client.py b/src/emailservice/email_client.py index f20815f..32593fe 100644 --- a/src/emailservice/email_client.py +++ b/src/emailservice/email_client.py @@ -15,16 +15,12 @@ # limitations under the License. import grpc -import logging import demo_pb2 import demo_pb2_grpc -from logger import JSONStreamHandler - -log = logging.getLogger('emailservice') -log.setLevel(logging.INFO) -log.addHandler(JSONStreamHandler()) +from logger import getJSONLogger +logger = getJSONLogger('emailservice-client') # from opencensus.trace.tracer import Tracer # from opencensus.trace.exporters import stackdriver_exporter @@ -46,10 +42,10 @@ def send_confirmation_email(email, order): email = email, order = order )) - log.info('Request sent.') + logger.info('Request sent.') except grpc.RpcError as err: - log.error(err.details()) - log.error('{}, {}'.format(err.code().name, err.code().value)) + logger.error(err.details()) + logger.error('{}, {}'.format(err.code().name, err.code().value)) if __name__ == '__main__': - log.info('Client for email service.') + logger.info('Client for email service.') diff --git a/src/emailservice/email_server.py b/src/emailservice/email_server.py index f637408..676b70e 100644 --- a/src/emailservice/email_server.py +++ b/src/emailservice/email_server.py @@ -16,7 +16,6 @@ from concurrent import futures import argparse -import logging import os import sys import time @@ -29,8 +28,6 @@ import demo_pb2_grpc from grpc_health.v1 import health_pb2 from grpc_health.v1 import health_pb2_grpc -from logger import JSONStreamHandler - # from opencensus.trace.ext.grpc import server_interceptor # from opencensus.trace.samplers import always_on # from opencensus.trace.exporters import stackdriver_exporter @@ -53,9 +50,8 @@ from logger import JSONStreamHandler # except: # pass -log = logging.getLogger('emailservice') -log.setLevel(logging.INFO) -log.addHandler(JSONStreamHandler()) +from logger import getJSONLogger +logger = getJSONLogger('emailservice-server') # Loads confirmation email template from file env = Environment( @@ -92,7 +88,7 @@ class EmailService(BaseEmailService): "html_body": content } ) - log.info("Message sent: {}".format(response.rfc822_message_id)) + logger.info("Message sent: {}".format(response.rfc822_message_id)) def SendOrderConfirmation(self, request, context): email = request.email @@ -102,7 +98,7 @@ class EmailService(BaseEmailService): confirmation = template.render(order = order) except TemplateError as err: context.set_details("An error occurred when preparing the confirmation mail.") - log.error(err.message) + logger.error(err.message) context.set_code(grpc.StatusCode.INTERNAL) return demo_pb2.Empty() @@ -118,7 +114,7 @@ class EmailService(BaseEmailService): class DummyEmailService(BaseEmailService): def SendOrderConfirmation(self, request, context): - log.info('A request to send order confirmation email to {} has been received.'.format(request.email)) + logger.info('A request to send order confirmation email to {} has been received.'.format(request.email)) return demo_pb2.Empty() class HealthCheck(): @@ -138,7 +134,7 @@ def start(dummy_mode): health_pb2_grpc.add_HealthServicer_to_server(service, server) port = os.environ.get('PORT', "8080") - log.info("listening on port: "+port) + logger.info("listening on port: "+port) server.add_insecure_port('[::]:'+port) server.start() try: @@ -149,5 +145,5 @@ def start(dummy_mode): if __name__ == '__main__': - log.info('starting the email service in dummy mode.') + logger.info('starting the email service in dummy mode.') start(dummy_mode = True) diff --git a/src/emailservice/logger.py b/src/emailservice/logger.py index 11d9d0e..a7fb527 100644 --- a/src/emailservice/logger.py +++ b/src/emailservice/logger.py @@ -16,26 +16,25 @@ import logging import sys -import json +from pythonjsonlogger import jsonlogger -class JSONStreamHandler(logging.StreamHandler): - """JSONStreamHandler emits log data in JSON format to stdout""" +# 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 __init__(self): - super().__init__(sys.stdout) - - def emit(self, record): - try: - msg = super().format(record) - data = { - 'message': msg, - 'severity': record.levelname, - 'name': 'emailservice' - } - stream = self.stream - stream.write(json.dumps(data)+'\n') - self.flush() - except (KeyboardInterrupt, SystemExit): - raise - except: - self.handleError(record) +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 diff --git a/src/emailservice/requirements.txt b/src/emailservice/requirements.txt index ca3f1c3..37f6f10 100644 --- a/src/emailservice/requirements.txt +++ b/src/emailservice/requirements.txt @@ -32,10 +32,11 @@ pycairo==1.17.1 pycparser==2.19 pycrypto==2.6.1 PyGObject==3.30.1 +python-json-logger==0.1.9 pytz==2018.5 pyxdg==0.26 requests==2.19.1 rsa==4.0 SecretStorage==3.1.0 six==1.11.0 -urllib3==1.23 \ No newline at end of file +urllib3==1.23 diff --git a/src/recommendationservice/client.py b/src/recommendationservice/client.py index 0e21c2c..7894886 100644 --- a/src/recommendationservice/client.py +++ b/src/recommendationservice/client.py @@ -14,21 +14,17 @@ # 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 -import logging from opencensus.trace.tracer import Tracer from opencensus.trace.exporters import stackdriver_exporter from opencensus.trace.ext.grpc import client_interceptor -from logger import JSONStreamHandler - -log = logging.getLogger('recommendationservice') -log.setLevel(logging.INFO) -log.addHandler(JSONStreamHandler()) +from logger import getJSONLogger +logger = getJSONLogger('recommendationservice-server') if __name__ == "__main__": # get port @@ -52,4 +48,4 @@ if __name__ == "__main__": request = demo_pb2.ListRecommendationsRequest(user_id="test", product_ids=["test"]) # make call to server response = stub.ListRecommendations(request) - log.info(response) + logger.info(response) diff --git a/src/recommendationservice/logger.py b/src/recommendationservice/logger.py index 3726f58..a7fb527 100644 --- a/src/recommendationservice/logger.py +++ b/src/recommendationservice/logger.py @@ -16,26 +16,25 @@ import logging import sys -import json +from pythonjsonlogger import jsonlogger -class JSONStreamHandler(logging.StreamHandler): - """JSONStreamHandler emits log data in JSON format to stdout""" +# 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 __init__(self): - super(JSONStreamHandler, self).__init__(sys.stdout) - - def emit(self, record): - try: - msg = super(JSONStreamHandler, self).format(record) - data = { - 'message': msg, - 'severity': record.levelname, - 'name': 'emailservice' - } - stream = self.stream - stream.write(json.dumps(data)+'\n') - self.flush() - except (KeyboardInterrupt, SystemExit): - raise - except: - self.handleError(record) +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 diff --git a/src/recommendationservice/recommendation_server.py b/src/recommendationservice/recommendation_server.py index 5ef3f0c..09e6e0d 100644 --- a/src/recommendationservice/recommendation_server.py +++ b/src/recommendationservice/recommendation_server.py @@ -18,9 +18,8 @@ import grpc from concurrent import futures import time import traceback -import random import os -import logging +import random import googleclouddebugger import demo_pb2 @@ -28,11 +27,8 @@ import demo_pb2_grpc from grpc_health.v1 import health_pb2 from grpc_health.v1 import health_pb2_grpc -from logger import JSONStreamHandler - -log = logging.getLogger('recommendationservice') -log.setLevel(logging.INFO) -log.addHandler(JSONStreamHandler()) +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 @@ -53,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] - log.info("[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) @@ -65,7 +61,7 @@ class RecommendationService(demo_pb2_grpc.RecommendationServiceServicer): if __name__ == "__main__": - log.info("initializing recommendationservice") + logger.info("initializing recommendationservice") # TODO(morganmclean,ahmetb) enabling the tracing interceptor/sampler below # causes an unbounded memory leak eventually OOMing the container. @@ -83,15 +79,15 @@ if __name__ == "__main__": version='1.0.0' ) except Exception, err: - log.error("could not enable debugger") - log.error(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') - log.info("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) @@ -104,7 +100,7 @@ if __name__ == "__main__": health_pb2_grpc.add_HealthServicer_to_server(service, server) # start server - log.info("listening on port: " + port) + logger.info("listening on port: " + port) server.add_insecure_port('[::]:'+port) server.start() diff --git a/src/recommendationservice/requirements.txt b/src/recommendationservice/requirements.txt index 470d93c..7e77517 100644 --- a/src/recommendationservice/requirements.txt +++ b/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