log: change log format to JSON payload for better log in Stackdriver (GoogleCloudPlatform#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. GoogleCloudPlatform#47

Author: ymotongpoo

src/currencyservice/client.js

@@ -20,6 +20,7 @@ require('@google-cloud/trace-agent').start();
 const path = require('path');
 const grpc = require('grpc');
 const leftPad = require('left-pad');
+const pino = require('pino');
 
 const PROTO_PATH = path.join(__dirname, './proto/demo.proto');
 const PORT = 7000;
@@ -28,6 +29,13 @@ const shopProto = grpc.load(PROTO_PATH).hipstershop;
 const client = new shopProto.CurrencyService(`localhost:${PORT}`,
   grpc.credentials.createInsecure());
 
+const logger = pino({
+  name: 'currencyservice-client',
+  messageKey: 'message',
+  changeLevelName: 'severity',
+  useLevelLabels: true
+});
+
 const request = {
   from: {
     currency_code: 'CHF',
@@ -43,16 +51,16 @@ function _moneyToString (m) {
 
 client.getSupportedCurrencies({}, (err, response) => {
   if (err) {
-    console.error(`Error in getSupportedCurrencies: ${err}`);
+    logger.error(`Error in getSupportedCurrencies: ${err}`);
   } else {
-    console.log(`Currency codes: ${response.currency_codes}`);
+    logger.info(`Currency codes: ${response.currency_codes}`);
   }
 });
 
 client.convert(request, (err, response) => {
   if (err) {
-    console.error(`Error in convert: ${err}`);
+    logger.error(`Error in convert: ${err}`);
   } else {
-    console.log(`Convert: ${_moneyToString(request.from)} to ${_moneyToString(response)}`);
+    logger.log(`Convert: ${_moneyToString(request.from)} to ${_moneyToString(response)}`);
   }
 });

src/currencyservice/package-lock.json

@@ -17,6 +17,7 @@
     "google-protobuf": "^3.0.0",
     "grpc": "^1.0.0",
     "left-pad": "^1.3.0",
+    "pino": "^5.6.2",
     "request": "^2.87.0",
     "xml2js": "^0.4.19"
   },

src/currencyservice/package.json

@@ -32,6 +32,7 @@ const path = require('path');
 const grpc = require('grpc');
 const request = require('request');
 const xml2js = require('xml2js');
+const pino = require('pino');
 const protoLoader = require('@grpc/proto-loader');
 
 const MAIN_PROTO_PATH = path.join(__dirname, './proto/demo.proto');
@@ -43,6 +44,13 @@ const DATA_URL = 'http://www.ecb.europa.eu/stats/eurofxref/eurofxref-daily.xml';
 const shopProto = _loadProto(MAIN_PROTO_PATH).hipstershop;
 const healthProto = _loadProto(HEALTH_PROTO_PATH).grpc.health.v1;
 
+const logger = pino({
+  name: 'currencyservice-server',
+  messageKey: 'message',
+  changeLevelName: 'severity',
+  useLevelLabels: true
+});
+
 /**
  * Helper function that loads a protobuf file.
  */
@@ -67,7 +75,7 @@ function _loadProto (path) {
 let _data;
 function _getCurrencyData (callback) {
   if (!_data) {
-    console.log('Fetching currency data...');
+    logger.info('Fetching currency data...');
     request(DATA_URL, (err, res) => {
       if (err) {
         throw new Error(`Error getting data: ${err}`);
@@ -108,7 +116,7 @@ function _carry (amount) {
  * Lists the supported currencies
  */
 function getSupportedCurrencies (call, callback) {
-  console.log('Getting supported currencies...');
+  logger.info('Getting supported currencies...');
   _getCurrencyData((data) => {
     callback(null, {currency_codes: Object.keys(data)});
   });
@@ -118,7 +126,7 @@ function getSupportedCurrencies (call, callback) {
  * Converts between currencies
  */
 function convert (call, callback) {
-  console.log('received conversion request');
+  logger.info('received conversion request');
   try {
     _getCurrencyData((data) => {
       const request = call.request;
@@ -142,12 +150,11 @@ function convert (call, callback) {
       result.nanos = Math.floor(result.nanos);
       result.currency_code = request.to_code;
 
-      console.log(`conversion request successful`);
+      logger.info(`conversion request successful`);
       callback(null, result);
     });
   } catch (err) {
-    console.error('conversion request failed.');
-    console.error(err);
+    logger.error(`conversion request failed: ${err}`);
     callback(err.message);
   }
 }
@@ -164,7 +171,7 @@ function check (call, callback) {
  * CurrencyConverter service at the sample server port
  */
 function main () {
-  console.log(`Starting gRPC server on port ${PORT}...`);
+  logger.info(`Starting gRPC server on port ${PORT}...`);
   const server = new grpc.Server();
   server.addService(shopProto.CurrencyService.service, {getSupportedCurrencies, convert});
   server.addService(healthProto.Health.service, {check});

src/currencyservice/server.js

@@ -19,6 +19,9 @@
 import demo_pb2
 import demo_pb2_grpc
 
+from logger import getJSONLogger
+logger = getJSONLogger('emailservice-client')
+
 # from opencensus.trace.tracer import Tracer
 # from opencensus.trace.exporters import stackdriver_exporter
 # from opencensus.trace.ext.grpc import client_interceptor
@@ -39,10 +42,10 @@ def send_confirmation_email(email, order):
       email = email,
       order = order
     ))
-    print('Request sent.')
+    logger.info('Request sent.')
   except grpc.RpcError as err:
-    print(err.details())
-    print('{}, {}'.format(err.code().name, err.code().value))
+    logger.error(err.details())
+    logger.error('{}, {}'.format(err.code().name, err.code().value))
 
 if __name__ == '__main__':
-  print('Client for email service.')
+  logger.info('Client for email service.')

src/emailservice/email_client.py

@@ -50,6 +50,9 @@
 # except:
 #     pass
 
+from logger import getJSONLogger
+logger = getJSONLogger('emailservice-server')
+
 # Loads confirmation email template from file
 env = Environment(
     loader=FileSystemLoader('templates'),
@@ -78,14 +81,14 @@ def send_email(client, email_address, content):
         "from": {
           "address_spec": from_address,
         },
-        "to": [{ 
-          "address_spec": email_address 
+        "to": [{
+          "address_spec": email_address
         }],
         "subject": "Your Confirmation Email",
         "html_body": content
       }
     )
-    print("Message sent: {}".format(response.rfc822_message_id))
+    logger.info("Message sent: {}".format(response.rfc822_message_id))
 
   def SendOrderConfirmation(self, request, context):
     email = request.email
@@ -95,7 +98,7 @@ def SendOrderConfirmation(self, request, context):
       confirmation = template.render(order = order)
     except TemplateError as err:
       context.set_details("An error occurred when preparing the confirmation mail.")
-      print(err.message)
+      logger.error(err.message)
       context.set_code(grpc.StatusCode.INTERNAL)
       return demo_pb2.Empty()
 
@@ -111,7 +114,7 @@ def SendOrderConfirmation(self, request, context):
 
 class DummyEmailService(BaseEmailService):
   def SendOrderConfirmation(self, request, context):
-    print('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():
@@ -131,7 +134,7 @@ def start(dummy_mode):
   health_pb2_grpc.add_HealthServicer_to_server(service, server)
 
   port = os.environ.get('PORT', "8080")
-  print("listening on port: "+port)
+  logger.info("listening on port: "+port)
   server.add_insecure_port('[::]:'+port)
   server.start()
   try:
@@ -142,5 +145,5 @@ def start(dummy_mode):
 
 
 if __name__ == '__main__':
-  print('starting the email service in dummy mode.')
+  logger.info('starting the email service in dummy mode.')
   start(dummy_mode = True)

src/emailservice/email_server.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/emailservice/logger.py

@@ -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
+urllib3==1.23

src/emailservice/requirements.txt

@@ -14,6 +14,15 @@
 
 const cardValidator = require('simple-card-validator');
 const uuid = require('uuid/v4');
+const pino = require('pino');
+
+const logger = pino({
+  name: 'paymentservice-charge',
+  messageKey: 'message',
+  changeLevelName: 'severity',
+  useLevelLabels: true
+});
+
 
 class CreditCardError extends Error {
   constructor (message) {
@@ -67,7 +76,7 @@ module.exports = function charge (request) {
   const { credit_card_expiration_year: year, credit_card_expiration_month: month } = creditCard;
   if ((currentYear * 12 + currentMonth) > (year * 12 + month)) { throw new ExpiredCreditCard(cardNumber.replace('-', ''), month, year); }
 
-  console.log(`Transaction processed: ${cardType} ending ${cardNumber.substr(-4)} \
+  logger.info(`Transaction processed: ${cardType} ending ${cardNumber.substr(-4)} \
     Amount: ${amount.currency_code}${amount.units}.${amount.nanos}`);
 
   return { transaction_id: uuid() };