From fb09bf54104e1207195cf71c49185a6c16762ab0 Mon Sep 17 00:00:00 2001 From: Steve Waterworth Date: Wed, 23 Jan 2019 12:26:19 +0000 Subject: [PATCH] nodejs logging --- .env | 2 +- cart/package.json | 1 + cart/server.js | 45 ++++++++++++++---------- catalogue/package.json | 3 ++ catalogue/server.js | 58 ++++++++++++++++++++----------- user/package.json | 3 ++ user/server.js | 77 ++++++++++++++++++++++++++++-------------- 7 files changed, 125 insertions(+), 64 deletions(-) diff --git a/.env b/.env index 1e51c9a..c965bee 100644 --- a/.env +++ b/.env @@ -1,3 +1,3 @@ # environment file for docker-compose REPO=robotshop -TAG=0.3.3 +TAG=0.4.0 diff --git a/cart/package.json b/cart/package.json index 6799978..e4725a6 100644 --- a/cart/package.json +++ b/cart/package.json @@ -13,6 +13,7 @@ "express": "^4.15.4", "redis": "^2.8.0", "request": "^2.83.0", + "pino": "^5.10.8", "express-pino-logger": "^4.0.0", "pino-pretty": "^2.5.0", "instana-nodejs-sensor": "^1.28.0" diff --git a/cart/server.js b/cart/server.js index 0e5c7c8..343a70a 100644 --- a/cart/server.js +++ b/cart/server.js @@ -11,7 +11,8 @@ const redis = require('redis'); const request = require('request'); const bodyParser = require('body-parser'); const express = require('express'); -const pino = require('express-pino-logger'); +const pino = require('pino'); +const expPino = require('express-pino-logger'); var redisConnected = false; @@ -20,12 +21,16 @@ var catalogueHost = process.env.CATALOGUE_HOST || 'catalogue' const logger = pino({ level: 'info', - prettyPrint: true, + prettyPrint: false, useLevelLabels: true }); +const expLogger = expPino({ + logger: logger +}); + const app = express(); -app.use(logger); +app.use(expLogger); app.use((req, res, next) => { res.set('Timing-Allow-Origin', '*'); @@ -37,7 +42,6 @@ app.use(bodyParser.urlencoded({ extended: true })); app.use(bodyParser.json()); app.get('/health', (req, res) => { - req.log.info('Health check'); var stat = { app: 'OK', redis: redisConnected @@ -67,7 +71,7 @@ app.get('/cart/:id', (req, res) => { app.delete('/cart/:id', (req, res) => { redisClient.del(req.params.id, (err, data) => { if(err) { - console.log('ERROR', err); + req.log.error('ERROR', err); res.status(500).send(err); } else { if(data == 1) { @@ -83,7 +87,7 @@ app.delete('/cart/:id', (req, res) => { app.get('/rename/:from/:to', (req, res) => { redisClient.get(req.params.from, (err, data) => { if(err) { - console.log('ERROR', err); + req.log.error('ERROR', err); res.status(500).send(err); } else { if(data == null) { @@ -111,7 +115,7 @@ app.get('/add/:id/:sku/:qty', (req, res) => { // look up product details getProduct(req.params.sku).then((product) => { - console.log('got product', product); + req.log.info('got product', product); // is the product in stock? if(product.instock == 0) { res.status(404).send('out of stock'); @@ -120,7 +124,7 @@ app.get('/add/:id/:sku/:qty', (req, res) => { // does the cart already exist? redisClient.get(req.params.id, (err, data) => { if(err) { - console.log('ERROR', err); + req.log.error('ERROR', err); res.status(500).send(err); } else { var cart; @@ -134,7 +138,7 @@ app.get('/add/:id/:sku/:qty', (req, res) => { } else { cart = JSON.parse(data); } - console.log('got cart', cart); + req.log.info('got cart', cart); // add sku to cart var item = { qty: qty, @@ -155,6 +159,7 @@ app.get('/add/:id/:sku/:qty', (req, res) => { } }); }).catch((err) => { + req.log.error(err); res.status(500).send(err); }); }); @@ -166,12 +171,15 @@ app.get('/update/:id/:sku/:qty', (req, res) => { if(isNaN(qty)) { res.status(400).send('quantity must be a number'); return; + } else if(qty < 0) { + res.status(400).send('negative quantity not allowed'); + return; } // get the cart redisClient.get(req.params.id, (err, data) => { if(err) { - console.log('ERROR', err); + req.log.error('ERROR', err); res.status(500).send(err); } else { if(data == null) { @@ -210,17 +218,17 @@ app.get('/update/:id/:sku/:qty', (req, res) => { app.post('/shipping/:id', (req, res) => { var shipping = req.body; if(shipping.distance === undefined || shipping.cost === undefined || shipping.location == undefined) { - console.log('bad shipping data', shipping); + req.log.warn('bad shipping data', shipping); res.status(400).send('shipping data missing'); } else { // get the cart redisClient.get(req.params.id, (err, data) => { if(err) { - console.log('ERROR', err); + req.log.error('ERROR', err); res.status(500).send(err); } else { if(data == null) { - console.log('no cart for', req.params.id); + req.log.info('no cart for', req.params.id); res.status(404).send('cart not found'); } else { var cart = JSON.parse(data); @@ -310,10 +318,10 @@ function getProduct(sku) { } function saveCart(id, cart) { - console.log('saving cart', cart); + logger.info('saving cart', cart); redisClient.setex(id, 3600, JSON.stringify(cart), (err, data) => { if(err) { - console.log('saveCart ERROR', err); + logger.error('saveCart ERROR', err); } }); } @@ -324,15 +332,16 @@ var redisClient = redis.createClient({ }); redisClient.on('error', (e) => { - console.error('Redis ERROR', e); + logger.error('Redis ERROR', e); }); redisClient.on('ready', (r) => { - console.info('Redis READY', r); + logger.info('Redis READY', r); redisConnected = true; }); // fire it up! const port = process.env.CART_SERVER_PORT || '8080'; app.listen(port, () => { - console.info('Started on port', port); + logger.info('Started on port', port); }); + diff --git a/catalogue/package.json b/catalogue/package.json index ef637e8..dfbd9d0 100644 --- a/catalogue/package.json +++ b/catalogue/package.json @@ -12,6 +12,9 @@ "body-parser": "^1.18.1", "express": "^4.15.4", "mongodb": "^2.2.33", + "pino": "^5.10.8", + "express-pino-logger": "^4.0.0", + "pino-pretty": "^2.5.0", "instana-nodejs-sensor": "^1.28.0" } } diff --git a/catalogue/server.js b/catalogue/server.js index def849f..9f67bc7 100644 --- a/catalogue/server.js +++ b/catalogue/server.js @@ -11,6 +11,17 @@ const mongoClient = require('mongodb').MongoClient; const mongoObjectID = require('mongodb').ObjectID; const bodyParser = require('body-parser'); const express = require('express'); +const pino = require('pino'); +const expPino = require('express-pino-logger'); + +const logger = pino({ + level: 'info', + prettyPrint: false, + useLevelLabels: true +}); +const expLogger = expPino({ + logger: logger +}); // MongoDB var db; @@ -19,6 +30,8 @@ var mongoConnected = false; const app = express(); +app.use(expLogger); + app.use((req, res, next) => { res.set('Timing-Allow-Origin', '*'); res.set('Access-Control-Allow-Origin', '*'); @@ -42,10 +55,11 @@ app.get('/products', (req, res) => { collection.find({}).toArray().then((products) => { res.json(products); }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not avaiable'); } }); @@ -54,17 +68,18 @@ app.get('/products', (req, res) => { app.get('/product/:sku', (req, res) => { if(mongoConnected) { collection.findOne({sku: req.params.sku}).then((product) => { - console.log('product', product); + req.log.info('product', product); if(product) { res.json(product); } else { res.status(404).send('SKU not found'); } }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); @@ -75,10 +90,11 @@ app.get('/products/:cat', (req, res) => { collection.find({ categories: req.params.cat }).sort({ name: 1 }).toArray().then((products) => { res.json(products); }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not avaiable'); } }); @@ -89,10 +105,11 @@ app.get('/categories', (req, res) => { collection.distinct('categories').then((categories) => { res.json(categories); }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); @@ -103,10 +120,11 @@ app.get('/search/:text', (req, res) => { collection.find({ '$text': { '$search': req.params.text }}).toArray().then((hits) => { res.json(hits); }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); @@ -114,25 +132,26 @@ app.get('/search/:text', (req, res) => { // set up Mongo function mongoConnect() { return new Promise((resolve, reject) => { - var mongoURL = process.env.MONGO_URL || 'mongodb://mongodb:27017/catalogue'; - mongoClient.connect(mongoURL, (error, _db) => { - if(error) { - reject(error); - } else { - db = _db; - collection = db.collection('products'); - resolve('connected'); - } + var mongoURL = process.env.MONGO_URL || 'mongodb://mongodb:27017/catalogue'; + mongoClient.connect(mongoURL, (error, _db) => { + if(error) { + reject(error); + } else { + db = _db; + collection = db.collection('products'); + resolve('connected'); + } + }); }); -}); } +// mongodb connection retry loop function mongoLoop() { mongoConnect().then((r) => { mongoConnected = true; - console.log('MongoDB connected'); + logger.info('MongoDB connected'); }).catch((e) => { - console.error('ERROR', e); + logger.error('ERROR', e); setTimeout(mongoLoop, 2000); }); } @@ -142,5 +161,6 @@ mongoLoop(); // fire it up! const port = process.env.CATALOGUE_SERVER_PORT || '8080'; app.listen(port, () => { - console.log('Started on port', port); + logger.info('Started on port', port); }); + diff --git a/user/package.json b/user/package.json index 7d80c8b..577c8f2 100644 --- a/user/package.json +++ b/user/package.json @@ -13,6 +13,9 @@ "express": "^4.15.4", "mongodb": "^2.2.33", "redis": "^2.8.0", + "pino": "^5.10.8", + "express-pino-logger": "^4.0.0", + "pino-pretty": "^2.5.0", "instana-nodejs-sensor": "^1.28.0" } } diff --git a/user/server.js b/user/server.js index cc85922..17f5c76 100644 --- a/user/server.js +++ b/user/server.js @@ -12,6 +12,8 @@ const mongoObjectID = require('mongodb').ObjectID; const redis = require('redis'); const bodyParser = require('body-parser'); const express = require('express'); +const pino = require('pino'); +const expPino = require('express-pino-logger'); // MongoDB var db; @@ -19,8 +21,20 @@ var usersCollection; var ordersCollection; var mongoConnected = false; +const logger = pino({ + level: 'info', + prettyPrint: false, + useLevelLabels: true +}); +const expLogger = expPino({ + logger: logger + +}); + const app = express(); +app.use(expLogger); + app.use((req, res, next) => { res.set('Timing-Allow-Origin', '*'); res.set('Access-Control-Allow-Origin', '*'); @@ -47,7 +61,7 @@ app.get('/uniqueid', (req, res) => { uuid: 'anonymous-' + r }); } else { - console.log('ERROR', err); + req.log.error('ERROR', err); res.status(500).send(err); } }); @@ -59,23 +73,24 @@ app.get('/users', (req, res) => { usersCollection.find().toArray().then((users) => { res.json(users); }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); app.post('/login', (req, res) => { - console.log('login', req.body); + req.log.info('login', req.body); if(req.body.name === undefined || req.body.password === undefined) { res.status(400).send('name or passowrd not supplied'); } else if(mongoConnected) { usersCollection.findOne({ name: req.body.name, }).then((user) => { - console.log('user', user); + req.log.info('user', user); if(user) { if(user.password == req.body.password) { res.json(user); @@ -86,17 +101,18 @@ app.post('/login', (req, res) => { res.status(404).send('name not found'); } }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); // TODO - validate email address format app.post('/register', (req, res) => { - console.log('register', req.body); + req.log.info('register', req.body); if(req.body.name === undefined || req.body.password === undefined || req.body.email === undefined) { res.status(400).send('insufficient data'); } else if(mongoConnected) { @@ -111,24 +127,25 @@ app.post('/register', (req, res) => { password: req.body.password, email: req.body.email }).then((r) => { - console.log('inserted', r.result); + req.log.info('inserted', r.result); res.send('OK'); }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } }).catch((e) => { - console.log('ERROR', e); + req.log.error('ERROR', e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); app.post('/order/:id', (req, res) => { - console.log('order', req.body); + req.log.info('order', req.body); // only for registered users if(mongoConnected) { usersCollection.findOne({ @@ -149,6 +166,7 @@ app.post('/order/:id', (req, res) => { ).then((r) => { res.send('OK'); }).catch((e) => { + req.log.error(e); res.status(500).send(e); }); } else { @@ -159,19 +177,23 @@ app.post('/order/:id', (req, res) => { }).then((r) => { res.send('OK'); }).catch((e) => { + req.log.error(e); res.status(500).send(e); }); } }).catch((e) => { + req.log.error(e); res.status(500).send(e); }); } else { res.status(404).send('name not found'); } }).catch((e) => { + req.log.error(e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); @@ -187,9 +209,11 @@ app.get('/history/:id', (req, res) => { res.status(404).send('history not found'); } }).catch((e) => { + req.log.error(e); res.status(500).send(e); }); } else { + req.log.error('database not available'); res.status(500).send('database not available'); } }); @@ -200,35 +224,35 @@ var redisClient = redis.createClient({ }); redisClient.on('error', (e) => { - console.log('Redis ERROR', e); + logger.error('Redis ERROR', e); }); redisClient.on('ready', (r) => { - console.log('Redis READY', r); + logger.info('Redis READY', r); }); // set up Mongo function mongoConnect() { return new Promise((resolve, reject) => { - var mongoURL = process.env.MONGO_URL || 'mongodb://mongodb:27017/users'; - mongoClient.connect(mongoURL, (error, _db) => { - if(error) { - reject(error); - } else { - db = _db; - usersCollection = db.collection('users'); - ordersCollection = db.collection('orders'); - resolve('connected'); - } + var mongoURL = process.env.MONGO_URL || 'mongodb://mongodb:27017/users'; + mongoClient.connect(mongoURL, (error, _db) => { + if(error) { + reject(error); + } else { + db = _db; + usersCollection = db.collection('users'); + ordersCollection = db.collection('orders'); + resolve('connected'); + } + }); }); -}); } function mongoLoop() { mongoConnect().then((r) => { mongoConnected = true; - console.log('MongoDB connected'); + logger.info('MongoDB connected'); }).catch((e) => { - console.error('ERROR', e); + logger.error('ERROR', e); setTimeout(mongoLoop, 2000); }); } @@ -238,5 +262,6 @@ mongoLoop(); // fire it up! const port = process.env.USER_SERVER_PORT || '8080'; app.listen(port, () => { - console.log('Started on port', port); + logger.info('Started on port', port); }); +