From 8e6e7b1113b17c3167c53629857605d34e0d0da5 Mon Sep 17 00:00:00 2001 From: Yoshi Yamaguchi Date: Mon, 24 Sep 2018 21:04:36 +0900 Subject: [PATCH] log: change log format to JSON payload for better log in Stackdriver (#47) 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. --- src/currencyservice/client.js | 16 +++-- src/currencyservice/package-lock.json | 62 +++++++++++++++++++ src/currencyservice/package.json | 1 + src/currencyservice/server.js | 21 ++++--- src/emailservice/email_client.py | 15 +++-- src/emailservice/email_server.py | 21 ++++--- src/emailservice/logger.py | 41 ++++++++++++ src/paymentservice/charge.js | 11 +++- src/paymentservice/package-lock.json | 62 +++++++++++++++++++ src/paymentservice/package.json | 1 + src/paymentservice/server.js | 12 +++- src/recommendationservice/client.py | 9 ++- src/recommendationservice/logger.py | 41 ++++++++++++ .../recommendation_server.py | 18 ++++-- 14 files changed, 299 insertions(+), 32 deletions(-) create mode 100644 src/emailservice/logger.py create mode 100644 src/recommendationservice/logger.py diff --git a/src/currencyservice/client.js b/src/currencyservice/client.js index 2d367e0..f381dc8 100644 --- a/src/currencyservice/client.js +++ b/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)}`); } }); diff --git a/src/currencyservice/package-lock.json b/src/currencyservice/package-lock.json index fb39603..3279481 100644 --- a/src/currencyservice/package-lock.json +++ b/src/currencyservice/package-lock.json @@ -663,16 +663,36 @@ "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-1.1.0.tgz", "integrity": "sha1-wFNHeBfIa1HaqFPIHgWbcz0CNhQ=" }, + "fast-json-parse": { + "version": "1.0.3", + "resolved": "https://registry.npmjs.org/fast-json-parse/-/fast-json-parse-1.0.3.tgz", + "integrity": "sha512-FRWsaZRWEJ1ESVNbDWmsAlqDk96gPQezzLghafp5J4GUKjbCz3OkAHuZs5TuPEtkbVQERysLp9xv6c24fBm8Aw==" + }, "fast-json-stable-stringify": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/fast-json-stable-stringify/-/fast-json-stable-stringify-2.0.0.tgz", "integrity": "sha1-1RQsDK7msRifh9OnYREGT4bIu/I=" }, + "fast-redact": { + "version": "1.2.0", + "resolved": "https://registry.npmjs.org/fast-redact/-/fast-redact-1.2.0.tgz", + "integrity": "sha512-k/uSk9PtFmvYx0m7bRk5B2gZChQk4euWhrn7Mf3vYSmwZBLh7cGNuMuc/vhH1MKMPyVJMMtl9oMwPnwlKqs7CQ==" + }, + "fast-safe-stringify": { + "version": "2.0.6", + "resolved": "https://registry.npmjs.org/fast-safe-stringify/-/fast-safe-stringify-2.0.6.tgz", + "integrity": "sha512-q8BZ89jjc+mz08rSxROs8VsrBBcn1SIw1kq9NjolL509tkABRk9io01RAjSaEv1Xb2uFLt8VtRiZbGp5H8iDtg==" + }, "findit2": { "version": "2.2.3", "resolved": "https://registry.npmjs.org/findit2/-/findit2-2.2.3.tgz", "integrity": "sha1-WKRmaX34piBc39vzlVNri9d3pfY=" }, + "flatstr": { + "version": "1.0.8", + "resolved": "https://registry.npmjs.org/flatstr/-/flatstr-1.0.8.tgz", + "integrity": "sha512-YXblbv/vc1zuVVUtnKl1hPqqk7TalZCppnKE7Pr8FI/Rp48vzckS/4SJ4Y9O9RNiI82Vcw/FydmtqdQOg1Dpqw==" + }, "follow-redirects": { "version": "1.5.1", "resolved": "https://registry.npmjs.org/follow-redirects/-/follow-redirects-1.5.1.tgz", @@ -1570,6 +1590,26 @@ "resolved": "https://registry.npmjs.org/pify/-/pify-3.0.0.tgz", "integrity": "sha1-5aSs0sEB/fPZpNB/DbxNtJ3SgXY=" }, + "pino": { + "version": "5.6.2", + "resolved": "https://registry.npmjs.org/pino/-/pino-5.6.2.tgz", + "integrity": "sha512-JVMYqJkE58b2u5+t85zJLbUDOhoWDjEQqrRY1eQzuR4Ub9RIyUSQJms4deT8Joy+C/QIdrrie7NffgCm+ao9xw==", + "requires": { + "fast-json-parse": "^1.0.3", + "fast-redact": "^1.2.0", + "fast-safe-stringify": "^2.0.6", + "flatstr": "^1.0.5", + "pino-std-serializers": "^2.2.1", + "pump": "^3.0.0", + "quick-format-unescaped": "^3.0.0", + "sonic-boom": "^0.6.1" + } + }, + "pino-std-serializers": { + "version": "2.2.1", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-2.2.1.tgz", + "integrity": "sha512-QqL7kkF7eMCpFG4hpZD8UPQga/kxkkh3E62HzMzTIL4OQyijyisAnBL8msBEAml8xcb/ioGhH7UUzGxuHqczhQ==" + }, "pretty-ms": { "version": "3.2.0", "resolved": "https://registry.npmjs.org/pretty-ms/-/pretty-ms-3.2.0.tgz", @@ -1599,6 +1639,15 @@ "resolved": "https://registry.npmjs.org/pseudomap/-/pseudomap-1.0.2.tgz", "integrity": "sha1-8FKijacOYYkX7wqKw0wa5aaChrM=" }, + "pump": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.0.tgz", + "integrity": "sha512-LwZy+p3SFs1Pytd/jYct4wpv49HiYCqd9Rlc5ZVdk0V+8Yzv6jR5Blk3TRmPL1ft69TxP0IMZGJ+WPFU2BFhww==", + "requires": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "punycode": { "version": "1.4.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-1.4.1.tgz", @@ -1609,6 +1658,11 @@ "resolved": "https://registry.npmjs.org/qs/-/qs-6.5.2.tgz", "integrity": "sha512-N5ZAX4/LxJmF+7wN74pUD6qAh9/wnvdQcjq9TZjevvXzSUo7bfmw91saqMjzGS2xq91/odN2dW/WOl7qQHNDGA==" }, + "quick-format-unescaped": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-3.0.0.tgz", + "integrity": "sha512-XmIOc07VM2kPm6m3j/U6jgxyUgDm2Rgh2c1PPy0JUHoQRdoh86hOym0bHyF6G1T6sn+N5lildhvl/T59H5KVyA==" + }, "readable-stream": { "version": "2.3.6", "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-2.3.6.tgz", @@ -1706,6 +1760,14 @@ "resolved": "https://registry.npmjs.org/shimmer/-/shimmer-1.2.0.tgz", "integrity": "sha512-xTCx2vohXC2EWWDqY/zb4+5Mu28D+HYNSOuFzsyRDRvI/e1ICb69afwaUwfjr+25ZXldbOLyp+iDUZHq8UnTag==" }, + "sonic-boom": { + "version": "0.6.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-0.6.1.tgz", + "integrity": "sha512-3qx6XXDeG+hPNa+jla1H6BMBLcjLl8L8NRERLVeIf/EuPqoqmq4K8owG29Xu7OypT/7/YT/0uKW6YitsKA+nLQ==", + "requires": { + "flatstr": "^1.0.5" + } + }, "source-map": { "version": "0.6.1", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", diff --git a/src/currencyservice/package.json b/src/currencyservice/package.json index 1d89148..7a21752 100644 --- a/src/currencyservice/package.json +++ b/src/currencyservice/package.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" }, diff --git a/src/currencyservice/server.js b/src/currencyservice/server.js index 69f7c3c..633078c 100644 --- a/src/currencyservice/server.js +++ b/src/currencyservice/server.js @@ -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}); diff --git a/src/emailservice/email_client.py b/src/emailservice/email_client.py index e4e591f..f20815f 100644 --- a/src/emailservice/email_client.py +++ b/src/emailservice/email_client.py @@ -15,10 +15,17 @@ # 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 opencensus.trace.tracer import Tracer # from opencensus.trace.exporters import stackdriver_exporter # from opencensus.trace.ext.grpc import client_interceptor @@ -39,10 +46,10 @@ def send_confirmation_email(email, order): email = email, order = order )) - print('Request sent.') + log.info('Request sent.') except grpc.RpcError as err: - print(err.details()) - print('{}, {}'.format(err.code().name, err.code().value)) + log.error(err.details()) + log.error('{}, {}'.format(err.code().name, err.code().value)) if __name__ == '__main__': - print('Client for email service.') \ No newline at end of file + log.info('Client for email service.') diff --git a/src/emailservice/email_server.py b/src/emailservice/email_server.py index a2cb073..f637408 100644 --- a/src/emailservice/email_server.py +++ b/src/emailservice/email_server.py @@ -16,6 +16,7 @@ from concurrent import futures import argparse +import logging import os import sys import time @@ -28,6 +29,8 @@ 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 @@ -50,6 +53,10 @@ from grpc_health.v1 import health_pb2_grpc # except: # pass +log = logging.getLogger('emailservice') +log.setLevel(logging.INFO) +log.addHandler(JSONStreamHandler()) + # Loads confirmation email template from file env = Environment( loader=FileSystemLoader('templates'), @@ -78,14 +85,14 @@ class EmailService(BaseEmailService): "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)) + log.info("Message sent: {}".format(response.rfc822_message_id)) def SendOrderConfirmation(self, request, context): email = request.email @@ -95,7 +102,7 @@ class EmailService(BaseEmailService): confirmation = template.render(order = order) except TemplateError as err: context.set_details("An error occurred when preparing the confirmation mail.") - print(err.message) + log.error(err.message) context.set_code(grpc.StatusCode.INTERNAL) return demo_pb2.Empty() @@ -111,7 +118,7 @@ class EmailService(BaseEmailService): class DummyEmailService(BaseEmailService): def SendOrderConfirmation(self, request, context): - print('A request to send order confirmation email to {} has been received.'.format(request.email)) + log.info('A request to send order confirmation email to {} has been received.'.format(request.email)) return demo_pb2.Empty() class HealthCheck(): @@ -131,7 +138,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) + log.info("listening on port: "+port) server.add_insecure_port('[::]:'+port) server.start() try: @@ -142,5 +149,5 @@ def start(dummy_mode): if __name__ == '__main__': - print('starting the email service in dummy mode.') + log.info('starting the email service in dummy mode.') start(dummy_mode = True) diff --git a/src/emailservice/logger.py b/src/emailservice/logger.py new file mode 100644 index 0000000..11d9d0e --- /dev/null +++ b/src/emailservice/logger.py @@ -0,0 +1,41 @@ +#!/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 +import json + +class JSONStreamHandler(logging.StreamHandler): + """JSONStreamHandler emits log data in JSON format to stdout""" + + 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) diff --git a/src/paymentservice/charge.js b/src/paymentservice/charge.js index a0151ed..ce9674a 100644 --- a/src/paymentservice/charge.js +++ b/src/paymentservice/charge.js @@ -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() }; diff --git a/src/paymentservice/package-lock.json b/src/paymentservice/package-lock.json index f7d35a4..7d0e682 100644 --- a/src/paymentservice/package-lock.json +++ b/src/paymentservice/package-lock.json @@ -700,16 +700,36 @@ "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-1.1.0.tgz", "integrity": "sha1-wFNHeBfIa1HaqFPIHgWbcz0CNhQ=" }, + "fast-json-parse": { + "version": "1.0.3", + "resolved": "https://registry.npmjs.org/fast-json-parse/-/fast-json-parse-1.0.3.tgz", + "integrity": "sha512-FRWsaZRWEJ1ESVNbDWmsAlqDk96gPQezzLghafp5J4GUKjbCz3OkAHuZs5TuPEtkbVQERysLp9xv6c24fBm8Aw==" + }, "fast-json-stable-stringify": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/fast-json-stable-stringify/-/fast-json-stable-stringify-2.0.0.tgz", "integrity": "sha1-1RQsDK7msRifh9OnYREGT4bIu/I=" }, + "fast-redact": { + "version": "1.2.0", + "resolved": "https://registry.npmjs.org/fast-redact/-/fast-redact-1.2.0.tgz", + "integrity": "sha512-k/uSk9PtFmvYx0m7bRk5B2gZChQk4euWhrn7Mf3vYSmwZBLh7cGNuMuc/vhH1MKMPyVJMMtl9oMwPnwlKqs7CQ==" + }, + "fast-safe-stringify": { + "version": "2.0.6", + "resolved": "https://registry.npmjs.org/fast-safe-stringify/-/fast-safe-stringify-2.0.6.tgz", + "integrity": "sha512-q8BZ89jjc+mz08rSxROs8VsrBBcn1SIw1kq9NjolL509tkABRk9io01RAjSaEv1Xb2uFLt8VtRiZbGp5H8iDtg==" + }, "findit2": { "version": "2.2.3", "resolved": "https://registry.npmjs.org/findit2/-/findit2-2.2.3.tgz", "integrity": "sha1-WKRmaX34piBc39vzlVNri9d3pfY=" }, + "flatstr": { + "version": "1.0.8", + "resolved": "https://registry.npmjs.org/flatstr/-/flatstr-1.0.8.tgz", + "integrity": "sha512-YXblbv/vc1zuVVUtnKl1hPqqk7TalZCppnKE7Pr8FI/Rp48vzckS/4SJ4Y9O9RNiI82Vcw/FydmtqdQOg1Dpqw==" + }, "follow-redirects": { "version": "1.5.1", "resolved": "https://registry.npmjs.org/follow-redirects/-/follow-redirects-1.5.1.tgz", @@ -1592,6 +1612,26 @@ "resolved": "https://registry.npmjs.org/pify/-/pify-3.0.0.tgz", "integrity": "sha1-5aSs0sEB/fPZpNB/DbxNtJ3SgXY=" }, + "pino": { + "version": "5.6.2", + "resolved": "https://registry.npmjs.org/pino/-/pino-5.6.2.tgz", + "integrity": "sha512-JVMYqJkE58b2u5+t85zJLbUDOhoWDjEQqrRY1eQzuR4Ub9RIyUSQJms4deT8Joy+C/QIdrrie7NffgCm+ao9xw==", + "requires": { + "fast-json-parse": "^1.0.3", + "fast-redact": "^1.2.0", + "fast-safe-stringify": "^2.0.6", + "flatstr": "^1.0.5", + "pino-std-serializers": "^2.2.1", + "pump": "^3.0.0", + "quick-format-unescaped": "^3.0.0", + "sonic-boom": "^0.6.1" + } + }, + "pino-std-serializers": { + "version": "2.2.1", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-2.2.1.tgz", + "integrity": "sha512-QqL7kkF7eMCpFG4hpZD8UPQga/kxkkh3E62HzMzTIL4OQyijyisAnBL8msBEAml8xcb/ioGhH7UUzGxuHqczhQ==" + }, "pretty-ms": { "version": "3.2.0", "resolved": "https://registry.npmjs.org/pretty-ms/-/pretty-ms-3.2.0.tgz", @@ -1621,6 +1661,15 @@ "resolved": "https://registry.npmjs.org/pseudomap/-/pseudomap-1.0.2.tgz", "integrity": "sha1-8FKijacOYYkX7wqKw0wa5aaChrM=" }, + "pump": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pump/-/pump-3.0.0.tgz", + "integrity": "sha512-LwZy+p3SFs1Pytd/jYct4wpv49HiYCqd9Rlc5ZVdk0V+8Yzv6jR5Blk3TRmPL1ft69TxP0IMZGJ+WPFU2BFhww==", + "requires": { + "end-of-stream": "^1.1.0", + "once": "^1.3.1" + } + }, "punycode": { "version": "1.4.1", "resolved": "https://registry.npmjs.org/punycode/-/punycode-1.4.1.tgz", @@ -1631,6 +1680,11 @@ "resolved": "https://registry.npmjs.org/qs/-/qs-6.5.2.tgz", "integrity": "sha512-N5ZAX4/LxJmF+7wN74pUD6qAh9/wnvdQcjq9TZjevvXzSUo7bfmw91saqMjzGS2xq91/odN2dW/WOl7qQHNDGA==" }, + "quick-format-unescaped": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-3.0.0.tgz", + "integrity": "sha512-XmIOc07VM2kPm6m3j/U6jgxyUgDm2Rgh2c1PPy0JUHoQRdoh86hOym0bHyF6G1T6sn+N5lildhvl/T59H5KVyA==" + }, "readable-stream": { "version": "2.3.6", "resolved": "https://registry.npmjs.org/readable-stream/-/readable-stream-2.3.6.tgz", @@ -1728,6 +1782,14 @@ "resolved": "https://registry.npmjs.org/simple-card-validator/-/simple-card-validator-1.1.0.tgz", "integrity": "sha1-675uRp/q7Cy7SBX4Qyu+BMccNvk=" }, + "sonic-boom": { + "version": "0.6.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-0.6.1.tgz", + "integrity": "sha512-3qx6XXDeG+hPNa+jla1H6BMBLcjLl8L8NRERLVeIf/EuPqoqmq4K8owG29Xu7OypT/7/YT/0uKW6YitsKA+nLQ==", + "requires": { + "flatstr": "^1.0.5" + } + }, "source-map": { "version": "0.6.1", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", diff --git a/src/paymentservice/package.json b/src/paymentservice/package.json index c62033b..b977be4 100644 --- a/src/paymentservice/package.json +++ b/src/paymentservice/package.json @@ -16,6 +16,7 @@ "@google-cloud/trace-agent": "^2.11.0", "@grpc/proto-loader": "^0.1.0", "grpc": "^1.12.3", + "pino": "^5.6.2", "simple-card-validator": "^1.1.0", "uuid": "^3.2.1" }, diff --git a/src/paymentservice/server.js b/src/paymentservice/server.js index ebce323..11598b7 100644 --- a/src/paymentservice/server.js +++ b/src/paymentservice/server.js @@ -14,10 +14,18 @@ const path = require('path'); const grpc = require('grpc'); +const pino = require('pino'); const protoLoader = require('@grpc/proto-loader'); const charge = require('./charge'); +const logger = pino({ + name: 'paymentservice-server', + messageKey: 'message', + changeLevelName: 'severity', + useLevelLabels: true +}); + class HipsterShopServer { constructor (protoRoot, port = HipsterShopServer.DEFAULT_PORT) { this.port = port; @@ -38,7 +46,7 @@ class HipsterShopServer { */ static ChargeServiceHandler (call, callback) { try { - console.log(`PaymentService#Charge invoked with request ${JSON.stringify(call.request)}`); + logger.info(`PaymentService#Charge invoked with request ${JSON.stringify(call.request)}`); const response = charge(call.request); callback(null, response); } catch (err) { @@ -53,7 +61,7 @@ class HipsterShopServer { listen () { this.server.bind(`0.0.0.0:${this.port}`, grpc.ServerCredentials.createInsecure()); - console.log(`PaymentService grpc server listening on ${this.port}`); + logger.info(`PaymentService grpc server listening on ${this.port}`); this.server.start(); } diff --git a/src/recommendationservice/client.py b/src/recommendationservice/client.py index d24afee..0e21c2c 100644 --- a/src/recommendationservice/client.py +++ b/src/recommendationservice/client.py @@ -18,11 +18,18 @@ 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()) + if __name__ == "__main__": # get port if len(sys.argv) > 1: @@ -45,4 +52,4 @@ if __name__ == "__main__": request = demo_pb2.ListRecommendationsRequest(user_id="test", product_ids=["test"]) # make call to server response = stub.ListRecommendations(request) - print(response) \ No newline at end of file + log.info(response) diff --git a/src/recommendationservice/logger.py b/src/recommendationservice/logger.py new file mode 100644 index 0000000..3726f58 --- /dev/null +++ b/src/recommendationservice/logger.py @@ -0,0 +1,41 @@ +#!/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 +import json + +class JSONStreamHandler(logging.StreamHandler): + """JSONStreamHandler emits log data in JSON format to stdout""" + + 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) diff --git a/src/recommendationservice/recommendation_server.py b/src/recommendationservice/recommendation_server.py index b897f73..5ef3f0c 100644 --- a/src/recommendationservice/recommendation_server.py +++ b/src/recommendationservice/recommendation_server.py @@ -20,6 +20,7 @@ import time import traceback import random import os +import logging import googleclouddebugger import demo_pb2 @@ -27,6 +28,11 @@ 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()) # TODO(morganmclean,ahmetb) tracing currently disabled due to memory leak (see TODO below) # from opencensus.trace.ext.grpc import server_interceptor @@ -47,7 +53,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)) + log.info("[Recv ListRecommendations] product_ids={}".format(prod_list)) # build and return response response = demo_pb2.ListRecommendationsResponse() response.product_ids.extend(prod_list) @@ -59,7 +65,7 @@ class RecommendationService(demo_pb2_grpc.RecommendationServiceServicer): if __name__ == "__main__": - print("initializing recommendationservice") + log.info("initializing recommendationservice") # TODO(morganmclean,ahmetb) enabling the tracing interceptor/sampler below # causes an unbounded memory leak eventually OOMing the container. @@ -77,15 +83,15 @@ if __name__ == "__main__": version='1.0.0' ) except Exception, err: - print("could not enable debugger") - traceback.print_exc() + log.error("could not enable debugger") + log.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) + log.info("product catalog address: " + catalog_addr) channel = grpc.insecure_channel(catalog_addr) product_catalog_stub = demo_pb2_grpc.ProductCatalogServiceStub(channel) @@ -98,7 +104,7 @@ if __name__ == "__main__": health_pb2_grpc.add_HealthServicer_to_server(service, server) # start server - print("listening on port: " + port) + log.info("listening on port: " + port) server.add_insecure_port('[::]:'+port) server.start()