From 2d1a2190d70c1d58b74b11807b696d0d3cb7272f Mon Sep 17 00:00:00 2001 From: Alex Layton Date: Thu, 11 Mar 2021 17:26:43 -0500 Subject: [PATCH] Use pino-http in http-handler --- oada/services/http-handler/package.json | 2 + .../http-handler/src/authorizations.js | 18 +++---- oada/services/http-handler/src/resources.js | 41 +++++++--------- oada/services/http-handler/src/server.js | 45 +++++++---------- oada/services/http-handler/src/users.js | 28 +++++------ oada/yarn.lock | 49 ++++++++++++++++++- 6 files changed, 104 insertions(+), 79 deletions(-) diff --git a/oada/services/http-handler/package.json b/oada/services/http-handler/package.json index c7d09300..dd02bfc5 100755 --- a/oada/services/http-handler/package.json +++ b/oada/services/http-handler/package.json @@ -45,6 +45,7 @@ "jsonpointer": "^4.1.0", "ksuid": "^2.0.0", "oada-error": "^1.1.1", + "pino-http": "^5.5.0", "type-is": "^1.6.18", "uuid": "^8.3.2", "well-known-json": "^0.2.0", @@ -54,6 +55,7 @@ "@types/debug": "^4.1.5", "@types/helmet": "^4", "@types/node": "^14.14.31", + "@types/pino-http": "^5", "@types/ws": "^7.4.0" } } diff --git a/oada/services/http-handler/src/authorizations.js b/oada/services/http-handler/src/authorizations.js index a3a0ed5b..88877d8d 100644 --- a/oada/services/http-handler/src/authorizations.js +++ b/oada/services/http-handler/src/authorizations.js @@ -5,18 +5,14 @@ const express = require('express'); const { v4: uuid } = require('uuid'); const cloneDeep = require('clone-deep'); -const debug = require('debug'); -const trace = debug('http-handler#authorizations:trace'); -const info = debug('http-handler#authorizations:info'); - const { authorizations, clients } = require('@oada/lib-arangodb'); const { OADAError } = require('oada-error'); const router = express.Router(); // eslint-disable-line new-cap -function addClientToAuth(auth) { +function addClientToAuth(req, auth) { if (auth && auth.clientId) { - trace('GET /%s: authorization has a client, retrieving', auth._id); + req.log.trace('GET /%s: authorization has a client, retrieving', auth._id); return clients .findById(auth.clientId) .then((client) => { @@ -24,11 +20,11 @@ function addClientToAuth(auth) { return auth; }) .catch((err) => { - debug.error('ERROR: authorization clientId not found in DB'); + req.log.error('ERROR: authorization clientId not found in DB'); throw err; }); } else { - trace('GET /%s: authorization DOES NOT have a clientId', auth._id); + req.log.trace('GET /%s: authorization DOES NOT have a clientId', auth._id); return auth; } } @@ -41,7 +37,7 @@ router.get('/', function (req, res, next) { .reduce(async (o, i) => { const k = i['_id'].replace(/^authorizations\//, ''); // returns either a promise or the same auth object - i = await addClientToAuth(i); + i = await addClientToAuth(req, i); o[k] = i; return o; }, {}) @@ -65,7 +61,7 @@ router.get('/:authId', function (req, res, next) { // Get the full client out of the DB to send out with this auth document // That way anybody listing authorizations can print the name, etc. of the client }) - .then(addClientToAuth) + .then((auth) => addClientToAuth(req, auth)) .then(res.json) .catch(next); }); @@ -108,7 +104,7 @@ router.post('/', function (req, res, next) { } // otherwise, token has admin scope so allow it (check user too?) - info( + req.log.info( 'Posted authorization for a different user, but token has admin.user scope so we are allowing it' ); } diff --git a/oada/services/http-handler/src/resources.js b/oada/services/http-handler/src/resources.js index e7f22883..194891a3 100644 --- a/oada/services/http-handler/src/resources.js +++ b/oada/services/http-handler/src/resources.js @@ -11,11 +11,6 @@ const { pipeline } = require('stream'); const pipelineAsync = Bluebird.promisify(pipeline); const cacache = require('cacache'); -const info = require('debug')('http-handler:resources:info'); -const warn = require('debug')('http-handler:resources:warn'); -const error = require('debug')('http-handler:resources:error'); -const trace = require('debug')('http-handler:resources:trace'); - const { resources } = require('@oada/lib-arangodb'); const { changes } = require('@oada/lib-arangodb'); const { putBodies } = require('@oada/lib-arangodb'); @@ -44,12 +39,12 @@ router.use(function graphHandler(req, res, next) { resources.lookupFromUrl('/resources' + req.url, req.user.user_id) ) .then(function handleGraphRes(resp) { - trace('GRAPH LOOKUP RESULT %O', resp); + req.log.trace('GRAPH LOOKUP RESULT %O', resp); if (resp['resource_id']) { // Rewire URL to resource found by graph - let url = `${resp['resource_id']}${resp['path_leftover']}`; + const url = `${resp['resource_id']}${resp['path_leftover']}`; // log - info(`Graph lookup: ${req.url} => ${url}`); + req.log.info(`Graph lookup: ${req.url} => ${url}`); // Remove "/resources" from id req.url = url.replace(/^\/?resources\//, '/'); } @@ -80,7 +75,7 @@ router.delete('/*', function checkScope(req, res, next) { // PUTing non-existant resource return; } else if (!response.permissions.owner && !response.permissions.write) { - warn( + req.log.warn( req.user['user_id'] + ' tried to GET resource without proper permissions' ); @@ -120,7 +115,7 @@ router.put('/*', function checkScope(req, res, next) { // PUTing non-existant resource return; } else if (!response.permissions.owner && !response.permissions.write) { - warn( + req.log.warn( req.user['user_id'] + ' tried to GET resource without proper permissions' ); @@ -155,7 +150,7 @@ router.get('/*', function checkScope(req, res, next) { config.get('kafka:topics:permissionsRequest') ) .then(function handlePermissionsRequest(response) { - trace('permissions response: %o', response); + req.log.trace('permissions response: %o', response); if (!response.permissions.owner && !response.permissions.read) { warn( req.user['user_id'] + @@ -201,7 +196,7 @@ router.get('/*', async function getChanges(req, res, next) { } else if (/^\/_meta\/_changes\/.*?/.test(req.oadaGraph.path_leftover)) { let rev = req.oadaGraph.path_leftover.split('/')[3]; let ch = await changes.getChangeArray(req.oadaGraph.resource_id, rev); - trace('CHANGE %O', ch); + req.log.trace('CHANGE %O', ch); return res.json(ch); } else { return next(); @@ -229,13 +224,13 @@ router.get('/*', async function getResource(req, res, next) { ); return Bluebird.join(doc, function returnDoc(doc) { - trace('DOC IS %O', doc); + req.log.trace('DOC IS %O', doc); // TODO: Allow null values in OADA? if (doc === undefined || doc === null) { - error('Resource not found'); + req.log.error('Resource not found'); throw new OADAError('Not Found', 404); } else { - info( + req.log.info( `Resource: ${req.oadaGraph.resource_id}, Rev: ${req.oadaGraph.rev}` ); } @@ -245,7 +240,7 @@ router.get('/*', async function getResource(req, res, next) { } else { // get binary if (req.oadaGraph['path_leftover']) { - trace(req.oadaGraph['path_leftover']); + req.log.trace(req.oadaGraph['path_leftover']); throw new OADAError('Path Leftover on Binary GEt'); } @@ -323,7 +318,7 @@ router.put( ); router.put('/*', async function putResource(req, res, next) { - trace(`Saving PUT body for request ${req.id}`); + req.log.trace(`Saving PUT body for request ${req.id}`); if ( req.header('content-type') && @@ -338,12 +333,12 @@ router.put('/*', async function putResource(req, res, next) { return putBodies .savePutBody(req.body) - .tap(() => trace(`PUT body saved for request ${req.id}`)) + .tap(() => req.log.trace(`PUT body saved for request ${req.id}`)) .get('_id') .then((bodyid) => { - trace('RESOURCE EXISTS %O', req.oadaGraph); - trace('RESOURCE EXISTS %O', req.resourceExists); + req.log.trace('RESOURCE EXISTS %O', req.oadaGraph); + req.log.trace('RESOURCE EXISTS %O', req.resourceExists); let ignoreLinks = (req.get('x-oada-ignore-links') || '').toLowerCase() == 'true'; return requester.send( @@ -367,7 +362,7 @@ router.put('/*', async function putResource(req, res, next) { ); }) .tap(function checkWrite(resp) { - trace(`Recieved write response for request ${req.id}`); + req.log.trace(`Recieved write response for request ${req.id}`); switch (resp.code) { case 'success': return; @@ -428,7 +423,7 @@ router.delete('/*', function deleteLink(req, res, next) { }); router.delete('/*', function deleteResource(req, res, next) { - trace(`Sending DELETE request for request ${req.id}`); + req.log.trace(`Sending DELETE request for request ${req.id}`); return requester .send( { @@ -449,7 +444,7 @@ router.delete('/*', function deleteResource(req, res, next) { config.get('kafka:topics:writeRequest') ) .tap(function checkDelete(resp) { - trace(`Recieved delete response for request ${req.id}`); + req.log.trace(`Recieved delete response for request ${req.id}`); switch (resp.code) { case 'success': return; diff --git a/oada/services/http-handler/src/server.js b/oada/services/http-handler/src/server.js index ece8093a..327fa9cf 100644 --- a/oada/services/http-handler/src/server.js +++ b/oada/services/http-handler/src/server.js @@ -7,28 +7,30 @@ const ksuid = require('ksuid'); const cors = require('cors'); const wellKnownJson = require('well-known-json'); const helmet = require('helmet'); +const pinoHttp = require('pino-http'); const oadaError = require('oada-error'); const { OADAError } = oadaError; -const info = require('debug')('http-handler:server:info'); -const warn = require('debug')('http-handler:server:warn'); -const error = require('debug')('http-handler:server:error'); -const trace = require('debug')('http-handler:server:trace'); +const { pino } = require('@oada/pino-debug'); -var config = require('./config'); +const config = require('./config'); ///////////////////////////////////////////////////////////////// // Setup express: const http = require('http'); -var app = express(); -var server = http.createServer(app); +const app = express(); +const server = http.createServer(app); const tokenLookup = require('./tokenLookup'); -var resources = require('./resources'); -var authorizations = require('./authorizations'); -var users = require('./users'); +const resources = require('./resources'); +const authorizations = require('./authorizations'); +const users = require('./users'); require('./websockets')(server); -var requester = require('./requester'); +const requester = require('./requester'); + +// Use pino/pino-http for logging +const logger = pino(); +app.use(pinoHttp({ logger })); app.use(helmet()); @@ -39,22 +41,15 @@ app.get('/favicon.ico', (req, res) => res.end()); function start() { return Bluebird.fromCallback(function (done) { - info('Starting server...'); + logger.info('Starting server...'); server.listen(config.get('server:port'), done); }).tap(() => { - info('OADA Server started on port %d', config.get('server:port')); + logger.info('OADA Server started on port %d', config.get('server:port')); }); } // Allow route handlers to return promises: app.use(expressPromise()); -// Log all requests before anything else gets them for debugging: -app.use(function (req, res, next) { - trace('Received request: ' + req.method + ' ' + req.url); - trace('req.headers = %O' + req.headers); - trace('req.body = %O', req.body); - next(); -}); // Turn on CORS for all domains, allow the necessary headers app.use( cors({ @@ -84,7 +79,7 @@ app.use(function requestId(req, res, next) { } res.set('X-Request-ID', req.id); - res.on('finish', () => trace(`finished request ${req.id}`)); + res.on('finish', () => req.log.trace(`finished request ${req.id}`)); next(); }); @@ -103,11 +98,11 @@ app.use(function tokenHandler(req, res, next) { }) .tap(function checkTok(tok) { if (!tok['token_exists']) { - info('Token does not exist'); + req.log.info('Token does not exist'); throw new OADAError('Unauthorized', 401); } if (tok.doc.expired) { - info('Token expired'); + req.log.info('Token expired'); throw new OADAError('Unauthorized', 401); } }) @@ -158,10 +153,6 @@ app.use(function (req) { ); }); -/////////////////////////////////////////////////// -// Use OADA middleware to catch errors and respond -app.use(oadaError.middleware(error)); - if (require.main === module) { start(); } diff --git a/oada/services/http-handler/src/users.js b/oada/services/http-handler/src/users.js index 2414eb2f..0ccc6f96 100644 --- a/oada/services/http-handler/src/users.js +++ b/oada/services/http-handler/src/users.js @@ -2,14 +2,9 @@ const express = require('express'); const bodyParser = require('body-parser'); -const debug = require('debug'); -const trace = debug('http-handler:trace'); -const info = debug('http-handler:info'); -const warn = debug('http-handler:warn'); -const error = debug('http-handler:error'); const ksuid = require('ksuid'); const cloneDeep = require('clone-deep'); -const { OADAError, middleware } = require('oada-error'); +const { OADAError } = require('oada-error'); const config = require('./config'); @@ -66,7 +61,7 @@ function requestUserWrite(req, id) { } router.post('/', function (req, res) { - info('Users POST, body = %O', req.body); + req.log.info('Users POST, body = %O', req.body); // Note: if the username already exists, the ksuid() below will end up // silently discarded and replaced in the response with the real one. const newid = ksuid.randomSync().string; // generate a random string for ID @@ -84,7 +79,7 @@ router.post('/', function (req, res) { // Update (merge) a user: router.put('/:id', function (req, res) { - info('Users PUT(id: ' + req.params.id + '), body = %O', req.body); + req.log.info('Users PUT(id: ' + req.params.id + '), body = %O', req.body); // generate an ID for this particular request if (!req.id) req.id = ksuid.randomSync().string; return requestUserWrite(req, req.params.id).then((resp) => { @@ -100,7 +95,7 @@ router.put('/:id', function (req, res) { // Lookup a username, limited to tokens and users with oada.admin.user scope router.get('/username-index/:uname', function (req, res) { // Check token scope - trace( + req.log.trace( 'username-index: Checking token scope, req.authorization.scope = %s', req.authorization ? req.authorization.scope : null ); @@ -108,7 +103,7 @@ router.get('/username-index/:uname', function (req, res) { (s) => s === 'oada.admin.user:read' || s === 'oada.admin.user:all' ); if (!havetokenscope) { - warn( + req.log.warn( 'WARNING: attempt to lookup user by username (username-index), but token does not have oada.admin.user:read or oada.admin.user:all scope!' ); throw new OADAError( @@ -118,14 +113,14 @@ router.get('/username-index/:uname', function (req, res) { } // Check user's scope - trace('username-index: Checking user scope, req.user = %O', req.user); + req.log.trace('username-index: Checking user scope, req.user = %O', req.user); const haveuserscope = Array.isArray(req.user.scope) && req.user.scope.find( (s) => s === 'oada.admin.user:read' || s === 'oada.admin.user:all' ); if (!haveuserscope) { - warn( + req.log.warn( 'WARNING: attempt to lookup user by username (username-index), but USER does not have oada.admin.user:read or oada.admin.user:all scope!' ); throw new OADAError( @@ -139,7 +134,7 @@ router.get('/username-index/:uname', function (req, res) { .then((u) => { u = sanitizeDbResult(u); if (!u) { - info( + req.log.info( `#username-index: 404: username ${req.params.uname} does not exist` ); res @@ -147,7 +142,9 @@ router.get('/username-index/:uname', function (req, res) { .send('Username ' + req.params.uname + ' does not exist.'); return res.end(); } - info(`#username-index: found user, returning info for userid ${u._id}`); + req.log.info( + `#username-index: found user, returning info for userid ${u._id}` + ); res .set('content-location', `/${u._id}`) .set('content-type', 'application/vnd.oada.user.1+json') @@ -156,7 +153,7 @@ router.get('/username-index/:uname', function (req, res) { return res.end(); }) .catch((e) => { - error( + req.log.error( 'FAILED to find user in DB for username-index, username = ' + req.params.uname + '. Error was: %O', @@ -190,6 +187,5 @@ router.get('/:id', function (req, res) { return res.json(user); }); }); -//router.use(middleware(error)) module.exports = router; diff --git a/oada/yarn.lock b/oada/yarn.lock index 19a68944..8f81d6d6 100644 --- a/oada/yarn.lock +++ b/oada/yarn.lock @@ -1018,6 +1018,7 @@ __metadata: "@types/debug": ^4.1.5 "@types/helmet": ^4 "@types/node": ^14.14.31 + "@types/pino-http": ^5 "@types/ws": ^7.4.0 axios: ^0.21.1 bluebird: ^3.7.2 @@ -1033,6 +1034,7 @@ __metadata: jsonpointer: ^4.1.0 ksuid: ^2.0.0 oada-error: ^1.1.1 + pino-http: ^5.5.0 type-is: ^1.6.18 uuid: ^8.3.2 well-known-json: ^0.2.0 @@ -1549,6 +1551,15 @@ __metadata: languageName: node linkType: hard +"@types/pino-http@npm:^5": + version: 5.4.0 + resolution: "@types/pino-http@npm:5.4.0" + dependencies: + "@types/pino": "*" + checksum: 6429806da4bc7f1896d9ce5d29806f1a21c4096838fac84a979cf2d780c7b9d4fb2bdcb836d62dee67b1ecf9a495529da621b157b776df385c938d6e8911a744 + languageName: node + linkType: hard + "@types/pino-std-serializers@npm:*": version: 2.4.1 resolution: "@types/pino-std-serializers@npm:2.4.1" @@ -1558,7 +1569,7 @@ __metadata: languageName: node linkType: hard -"@types/pino@npm:^6.3.6": +"@types/pino@npm:*, @types/pino@npm:^6.3.6": version: 6.3.6 resolution: "@types/pino@npm:6.3.6" dependencies: @@ -3989,6 +4000,15 @@ __metadata: languageName: node linkType: hard +"fast-url-parser@npm:^1.1.3": + version: 1.1.3 + resolution: "fast-url-parser@npm:1.1.3" + dependencies: + punycode: ^1.3.2 + checksum: 8dbc306b736e32963fe4391a581401c422d826497ce5cacf6e7c60525febfbcea477fbc5b012fe3316f6634a20fa00882168c5ed792ff3ef904c5bc6a11a598d + languageName: node + linkType: hard + "fastq@npm:^1.6.0": version: 1.11.0 resolution: "fastq@npm:1.11.0" @@ -7872,6 +7892,17 @@ fsevents@~2.3.1: languageName: node linkType: hard +"pino-http@npm:^5.5.0": + version: 5.5.0 + resolution: "pino-http@npm:5.5.0" + dependencies: + fast-url-parser: ^1.1.3 + pino: ^6.0.0 + pino-std-serializers: ^2.4.0 + checksum: 6ee96d9e9036bf11a1a03646b28f58fc30ece6524d4035a498e3c8ff4988192fdc6f297ab739753cc889f70aca7fd578343fc18d514ef823f54dd25a89a6cb45 + languageName: node + linkType: hard + "pino-pretty@npm:^4.6.0": version: 4.6.0 resolution: "pino-pretty@npm:4.6.0" @@ -7893,6 +7924,13 @@ fsevents@~2.3.1: languageName: node linkType: hard +"pino-std-serializers@npm:^2.4.0": + version: 2.5.0 + resolution: "pino-std-serializers@npm:2.5.0" + checksum: c7605e6b9dd3b2e6898059da0bca93277ed9139f0b884d9f7c922f22f011ba4a930389a71728e7c682ee5c3bf786aa67a90f10b1eb8eadc0467c5b78883a43bc + languageName: node + linkType: hard + "pino-std-serializers@npm:^3.1.0": version: 3.2.0 resolution: "pino-std-serializers@npm:3.2.0" @@ -7900,7 +7938,7 @@ fsevents@~2.3.1: languageName: node linkType: hard -"pino@npm:^6.0.2, pino@npm:^6.11.1": +"pino@npm:^6.0.0, pino@npm:^6.0.2, pino@npm:^6.11.1": version: 6.11.1 resolution: "pino@npm:6.11.1" dependencies: @@ -8079,6 +8117,13 @@ fsevents@~2.3.1: languageName: node linkType: hard +"punycode@npm:^1.3.2": + version: 1.4.1 + resolution: "punycode@npm:1.4.1" + checksum: 5ce1e044cee2b12f1c65ccd523d7e71d6578f2c77f5c21c2e7a9d588535559c9508571d42638c131dab93cbe9a7b37bce1a7475d43fc8236c99dfe1efc36cfa5 + languageName: node + linkType: hard + "q@npm:^1.5.1": version: 1.5.1 resolution: "q@npm:1.5.1"