From a09eb6c6fd86842bb8bfe244a9ff111617b912c6 Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Tue, 13 Dec 2016 15:22:25 +0000 Subject: [PATCH 1/8] change logging level with flags --- bin/server.js | 3 +-- lib/config.js | 4 +++- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/bin/server.js b/bin/server.js index d065c5ce..21920b4b 100755 --- a/bin/server.js +++ b/bin/server.js @@ -256,9 +256,8 @@ if ( require.main === module ) { if ( options.get('version') ) { console.log(require('../package.json').version); process.exit(0); - } else if ( options.get('debug') ) { - LOGGER.level = 'debug'; } + LOGGER.level = options.get('debug') ? 'debug' : options.get('loglevel'); let numWorkers = options.get('numworkers'); let waitingConsec = options.get('clustertimeout'); let maxConsec = options.get('clustermaxdeaths'); diff --git a/lib/config.js b/lib/config.js index e4104d6d..977a5f97 100644 --- a/lib/config.js +++ b/lib/config.js @@ -56,12 +56,14 @@ const optionsList = [ ['s','skipauth' ,'skip authorisation steps'], ['' ,'anyorigin' ,'accept CORS requests from any origin'], ['e','emaildomain=DOMAIN' ,'email domain to validate the remote user value against'], - ['d','debug' ,'debugging mode for this server'], + ['d','debug' ,'sets logger level to debug for this server'], + ['L','loglevel=[error|warn|info|debug]','logging level for this server [default: error]'], ['V','version' ,'print version and exit'], ['h','help' ,'display this help'] ]; const defaultOptions = { + loglevel: 'error', [RO_OPTION_KEY]: false, /* cluster */ numworkers: 1, From 4d2996585ebdfd4d85011391ad0824ac7aca01aa Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Tue, 13 Dec 2016 16:01:27 +0000 Subject: [PATCH 2/8] Add flag for logging to console --- bin/server.js | 1 + lib/config.js | 3 ++- lib/logsetup.js | 51 ++++++++++++++++++++++++++------------------- test/config.spec.js | 2 ++ 4 files changed, 34 insertions(+), 23 deletions(-) diff --git a/bin/server.js b/bin/server.js index 21920b4b..a4796041 100755 --- a/bin/server.js +++ b/bin/server.js @@ -253,6 +253,7 @@ class BrokerFactory { */ if ( require.main === module ) { const options = config.provide(config.fromCommandLine); + LOGGER.setup(); if ( options.get('version') ) { console.log(require('../package.json').version); process.exit(0); diff --git a/lib/config.js b/lib/config.js index 977a5f97..cb689e9d 100644 --- a/lib/config.js +++ b/lib/config.js @@ -56,6 +56,7 @@ const optionsList = [ ['s','skipauth' ,'skip authorisation steps'], ['' ,'anyorigin' ,'accept CORS requests from any origin'], ['e','emaildomain=DOMAIN' ,'email domain to validate the remote user value against'], + ['', 'logconsole' ,'outputs logs to console'], ['d','debug' ,'sets logger level to debug for this server'], ['L','loglevel=[error|warn|info|debug]','logging level for this server [default: error]'], ['V','version' ,'print version and exit'], @@ -63,7 +64,7 @@ const optionsList = [ ]; const defaultOptions = { - loglevel: 'error', + loglevel: 'error', [RO_OPTION_KEY]: false, /* cluster */ numworkers: 1, diff --git a/lib/logsetup.js b/lib/logsetup.js index 65f2291f..a2e016dd 100644 --- a/lib/logsetup.js +++ b/lib/logsetup.js @@ -3,6 +3,8 @@ const LOGGER = require('winston'); const moment = require('moment'); +const config = require('../lib/config.js'); + /** * @external winston * @see {@link https://www.npmjs.com/package/winston|winston} @@ -27,27 +29,32 @@ var getTimeStamp = function() { return moment().format('YYYY-MM-DD HH:mm:ss Z'); }; -try { - LOGGER.remove(LOGGER.transports.Console); - LOGGER.add(LOGGER.transports.Console, { - level: 'warn', - colorize: true, - json: false, - timestamp: getTimeStamp, - stderrLevels: [ 'error' ] // Which levels to send to stderr - }); - LOGGER.add(LOGGER.transports.File, { - level: 'warn', - filename: 'npg_ranger.winston.log', - json: false, - timestamp: getTimeStamp, - maxsize: 10 * 1000 * 1000, - maxFiles: 20 - }); -} catch (e) { - console.error('Error when trying to init logging with Winston'); - console.error(e); - process.exit(1); -} +var setup = function() { + try { + LOGGER.remove(LOGGER.transports.Console); + if (config.provide().get('logconsole')) { + LOGGER.add(LOGGER.transports.Console, { + level: 'warn', + colorize: true, + json: false, + timestamp: getTimeStamp, + stderrLevels: [ 'error' ] // Which levels to send to stderr + }); + } + LOGGER.add(LOGGER.transports.File, { + level: 'warn', + filename: 'npg_ranger.winston.log', + json: false, + timestamp: getTimeStamp, + maxsize: 10 * 1000 * 1000, + maxFiles: 20 + }); + } catch (e) { + console.error('Error when trying to init logging with Winston'); + console.error(e); + process.exit(1); + } +}; module.exports = LOGGER; +module.exports.setup = setup; diff --git a/test/config.spec.js b/test/config.spec.js index 9ff5c1b2..e6cc29b9 100644 --- a/test/config.spec.js +++ b/test/config.spec.js @@ -131,6 +131,8 @@ describe('Listing config options', function() { 'debug=true', 'emaildomain="some.com"', 'hostname="myhost"', + 'logconsole=undefined', + 'loglevel="error"', 'mongourl="mymongourl"', 'multiref=undefined', 'numworkers=3', From 3a4f8d324eae10fc3091f58cbd23e6b9f15b1e97 Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Tue, 13 Dec 2016 16:31:59 +0000 Subject: [PATCH 3/8] Fix tests that rely on console logging --- test/client/highLevelClient.spec.js | 1 + test/server/secure_server.spec.js | 1 + 2 files changed, 2 insertions(+) diff --git a/test/client/highLevelClient.spec.js b/test/client/highLevelClient.spec.js index 86aef536..5b2a46c0 100644 --- a/test/client/highLevelClient.spec.js +++ b/test/client/highLevelClient.spec.js @@ -241,6 +241,7 @@ describe('Running with ranger server with a', () => { let serv = spawn(serverCommand, [ '-s', '-d', + '--logconsole', '-n0', `-p${SERV_PORT}`, `-m${mongourl}`]); diff --git a/test/server/secure_server.spec.js b/test/server/secure_server.spec.js index d6b46c64..f2bcff64 100644 --- a/test/server/secure_server.spec.js +++ b/test/server/secure_server.spec.js @@ -35,6 +35,7 @@ describe('test running https server', () => { let s = spawn(serverCommand, [ '-s', '-d', + '--logconsole', '--startssl', '--secure_key', private_pem, '--secure_cert', cert_pem, From 9dacbc5270218296a5a4e90bab52d4d2a51c218e Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Wed, 14 Dec 2016 09:50:01 +0000 Subject: [PATCH 4/8] fix client to work with new logging --- bin/client.js | 1 + bin/server.js | 7 +++++-- lib/logsetup.js | 6 ++---- 3 files changed, 8 insertions(+), 6 deletions(-) diff --git a/bin/client.js b/bin/client.js index be767afa..8c68a0be 100755 --- a/bin/client.js +++ b/bin/client.js @@ -91,6 +91,7 @@ cline.on('--help', () => { if ( !cline.args.length || ( cline.args.length != 1 && cline.args.length != 2 ) ) { cline.help(); } +LOGGER.setup(true); if ( !cline.debug ) { LOGGER.level = 'warn'; } else { diff --git a/bin/server.js b/bin/server.js index a4796041..bf78f887 100755 --- a/bin/server.js +++ b/bin/server.js @@ -253,12 +253,15 @@ class BrokerFactory { */ if ( require.main === module ) { const options = config.provide(config.fromCommandLine); - LOGGER.setup(); + if ( options.get('version') ) { console.log(require('../package.json').version); process.exit(0); + } else { + LOGGER.setup(options.get('logconsole')); + LOGGER.level = options.get('debug') ? 'debug' : options.get('loglevel'); } - LOGGER.level = options.get('debug') ? 'debug' : options.get('loglevel'); + let numWorkers = options.get('numworkers'); let waitingConsec = options.get('clustertimeout'); let maxConsec = options.get('clustermaxdeaths'); diff --git a/lib/logsetup.js b/lib/logsetup.js index a2e016dd..1f069aae 100644 --- a/lib/logsetup.js +++ b/lib/logsetup.js @@ -3,8 +3,6 @@ const LOGGER = require('winston'); const moment = require('moment'); -const config = require('../lib/config.js'); - /** * @external winston * @see {@link https://www.npmjs.com/package/winston|winston} @@ -29,10 +27,10 @@ var getTimeStamp = function() { return moment().format('YYYY-MM-DD HH:mm:ss Z'); }; -var setup = function() { +var setup = function(logconsole) { try { LOGGER.remove(LOGGER.transports.Console); - if (config.provide().get('logconsole')) { + if (logconsole) { LOGGER.add(LOGGER.transports.Console, { level: 'warn', colorize: true, From 2e262b856622495858aa35dec46c5053ab6582d7 Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Wed, 14 Dec 2016 09:52:40 +0000 Subject: [PATCH 5/8] update CHANGES for new logging flags --- CHANGES | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGES b/CHANGES index 2199d077..c65a5d6d 100644 --- a/CHANGES +++ b/CHANGES @@ -11,6 +11,7 @@ LIST OF CHANGES for npg_ranger project - upgrade tmp to 0.0.31 from 0.0.30 - do not allow query strings containing multiple attribute-value pairs for the same attribute + - added flags to server to change logging level and enable logging to console release 1.0.0 - show error in log when controller tests fail to cleanup From bd6ef9cdce691e5c246d15490a682c84e771ba71 Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Wed, 14 Dec 2016 17:05:09 +0000 Subject: [PATCH 6/8] send all console output to stderr --- lib/logsetup.js | 3 ++- test/client/highLevelClient.spec.js | 8 ++++---- test/server/secure_server.spec.js | 2 +- 3 files changed, 7 insertions(+), 6 deletions(-) diff --git a/lib/logsetup.js b/lib/logsetup.js index 1f069aae..ffaa20df 100644 --- a/lib/logsetup.js +++ b/lib/logsetup.js @@ -1,6 +1,7 @@ "use strict"; const LOGGER = require('winston'); + const moment = require('moment'); /** @@ -36,7 +37,7 @@ var setup = function(logconsole) { colorize: true, json: false, timestamp: getTimeStamp, - stderrLevels: [ 'error' ] // Which levels to send to stderr + stderrLevels: [ 'error', 'warn', 'info', 'verbose', 'debug', 'silly' ] // Which levels to send to stderr }); } LOGGER.add(LOGGER.transports.File, { diff --git a/test/client/highLevelClient.spec.js b/test/client/highLevelClient.spec.js index 5b2a46c0..ce4dc163 100644 --- a/test/client/highLevelClient.spec.js +++ b/test/client/highLevelClient.spec.js @@ -257,7 +257,7 @@ describe('Running with ranger server with a', () => { it('file url', (done) => { let serv = startServer( done, fail ); - serv.stdout.on('data', (data) => { + serv.stderr.on('data', (data) => { if (data.toString().match(/Server listening on /)) { // Server is listening and ready for connection let client = spawn('bin/client.js', [ @@ -279,7 +279,7 @@ describe('Running with ranger server with a', () => { it('sample url', (done) => { let serv = startServer( done, fail ); - serv.stdout.on('data', (data) => { + serv.stderr.on('data', (data) => { if (data.toString().match(/Server listening on /)) { // Server is listening and ready for connection let client = spawn('bin/client.js', [ @@ -305,7 +305,7 @@ describe('Running with ranger server with a', () => { it('sample url returning vcf', (done) => { let serv = startServer( done, fail ); - serv.stdout.on('data', (data) => { + serv.stderr.on('data', (data) => { if (data.toString().match(/Server listening on /)) { // Server is listening and ready for connection let body = ''; @@ -328,7 +328,7 @@ describe('Running with ranger server with a', () => { it('GA4GH url and the redirect is followed', (done) => { let serv = startServer( done, fail ); - serv.stdout.on('data', (data) => { + serv.stderr.on('data', (data) => { if (data.toString().match(/Server listening on /)) { // Server is listening and ready for connection let client = spawn('bin/client.js', [ diff --git a/test/server/secure_server.spec.js b/test/server/secure_server.spec.js index f2bcff64..b9ff33b3 100644 --- a/test/server/secure_server.spec.js +++ b/test/server/secure_server.spec.js @@ -107,7 +107,7 @@ describe('test running https server', () => { it('can reply with a reference from a https requests', ( done ) => { serv = startServer( done ); let acc = 'XYZ120923'; - serv.stdout.on('data', (data) => { + serv.stderr.on('data', (data) => { if (data.toString().match(/Server listening on /)) { // Server is listening and ready for connection let options = { From a807760cae02297aa3f02afcbc3bbbf4d79b4c8a Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Thu, 15 Dec 2016 12:13:42 +0000 Subject: [PATCH 7/8] edit CHANGES: all console logging outputs to stderr --- CHANGES | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGES b/CHANGES index c65a5d6d..6b4c8d52 100644 --- a/CHANGES +++ b/CHANGES @@ -12,6 +12,7 @@ LIST OF CHANGES for npg_ranger project - do not allow query strings containing multiple attribute-value pairs for the same attribute - added flags to server to change logging level and enable logging to console + - all logging to console is now sent to stderr release 1.0.0 - show error in log when controller tests fail to cleanup From 7d61fa2d3fe22db7491b66237cd4d4f24169d18e Mon Sep 17 00:00:00 2001 From: Andrew Nowak Date: Fri, 16 Dec 2016 17:03:21 +0000 Subject: [PATCH 8/8] Don't log to file There is a long-standing (multiple years) bug with winston that logging to file may not necessarily finish before a process.exit(). Avoid this by allowing logging to stderr, and expect users to redirect as necessary. --- bin/client.js | 9 +++------ bin/server.js | 17 ++++++++++++++++- lib/logsetup.js | 16 ++++------------ 3 files changed, 23 insertions(+), 19 deletions(-) diff --git a/bin/client.js b/bin/client.js index 8c68a0be..21cc06fd 100755 --- a/bin/client.js +++ b/bin/client.js @@ -65,7 +65,7 @@ cline .version(require('../package.json').version) .description('Command line client for GA4GH data streaming') .arguments(' [output]') - .option('--debug', 'Show debug output') + .option('--loglevel ', 'level of logging output', /^(error|warn|info|debug)$/i, 'warn') .option('--accept-trailers', 'Request trailers from server') .parse(process.argv); @@ -92,11 +92,8 @@ if ( !cline.args.length || ( cline.args.length != 1 && cline.args.length != 2 ) ) { cline.help(); } LOGGER.setup(true); -if ( !cline.debug ) { - LOGGER.level = 'warn'; -} else { - LOGGER.level = 'debug'; -} + +LOGGER.level = cline.loglevel; var url = cline.args[0]; var output = cline.args.length == 2 ? cline.args[1] : undefined; diff --git a/bin/server.js b/bin/server.js index bf78f887..d9bcfae8 100755 --- a/bin/server.js +++ b/bin/server.js @@ -247,6 +247,21 @@ class BrokerFactory { : new FlatBroker(serverFactory); } } +function setLogLevel(options) { + if (options.get('debug')) { + LOGGER.level = 'debug'; + return; + } + let logLevel = options.get('loglevel'); + let knownLevels = ['error', 'warn', 'info', 'debug', 'silly']; + if (knownLevels.indexOf(logLevel) !== -1) { + LOGGER.level = logLevel; + return; + } + // --loglevel was given an invalid parameter - leave at default and log error + LOGGER.error('configuration: loglevel expects one of ' + knownLevels.join(',') + '; but received ' + logLevel); + process.exit(1); +} /** * Application's main method. @@ -259,7 +274,7 @@ if ( require.main === module ) { process.exit(0); } else { LOGGER.setup(options.get('logconsole')); - LOGGER.level = options.get('debug') ? 'debug' : options.get('loglevel'); + setLogLevel(options); } let numWorkers = options.get('numworkers'); diff --git a/lib/logsetup.js b/lib/logsetup.js index ffaa20df..90a1c935 100644 --- a/lib/logsetup.js +++ b/lib/logsetup.js @@ -33,21 +33,13 @@ var setup = function(logconsole) { LOGGER.remove(LOGGER.transports.Console); if (logconsole) { LOGGER.add(LOGGER.transports.Console, { - level: 'warn', - colorize: true, - json: false, - timestamp: getTimeStamp, + level: 'warn', + colorize: true, + json: false, + timestamp: getTimeStamp, stderrLevels: [ 'error', 'warn', 'info', 'verbose', 'debug', 'silly' ] // Which levels to send to stderr }); } - LOGGER.add(LOGGER.transports.File, { - level: 'warn', - filename: 'npg_ranger.winston.log', - json: false, - timestamp: getTimeStamp, - maxsize: 10 * 1000 * 1000, - maxFiles: 20 - }); } catch (e) { console.error('Error when trying to init logging with Winston'); console.error(e);