From 84ab47d6e5e02ac81958ec0dd5a662cf202ed9e1 Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Tue, 18 Jul 2017 22:42:06 +1000 Subject: [PATCH 1/5] feat(pm2): got pm2 working, needs tests --- lib/configuration.js | 5 ++++- lib/log4js.js | 41 +++++++++++++++++++++++------------- test/tap/pm2-support-test.js | 10 +++++++++ 3 files changed, 40 insertions(+), 16 deletions(-) create mode 100644 test/tap/pm2-support-test.js diff --git a/lib/configuration.js b/lib/configuration.js index 71cb484..2339117 100644 --- a/lib/configuration.js +++ b/lib/configuration.js @@ -76,7 +76,7 @@ class Configuration { debug(`DEPRECATION: Appender ${config.type} exports a shutdown function.`); } - if (cluster.isMaster) { + if (cluster.isMaster || (this.pm2 && process.env[this.pm2InstanceVar] === '0')) { return appenderModule.configure( config, layouts, @@ -195,6 +195,9 @@ class Configuration { this.throwExceptionIf(not(anObject(candidate.appenders)), 'must have a property "appenders" of type object.'); this.throwExceptionIf(not(anObject(candidate.categories)), 'must have a property "categories" of type object.'); + this.pm2 = this.candidate.pm2; + this.pm2InstanceVar = this.candidate.pm2InstanceVar || 'NODE_APP_INSTANCE'; + this.levels = candidate.levels; this.appenders = candidate.appenders; this.categories = candidate.categories; diff --git a/lib/log4js.js b/lib/log4js.js index 91b147e..2184863 100644 --- a/lib/log4js.js +++ b/lib/log4js.js @@ -139,7 +139,7 @@ function sendLogEventToAppender(logEvent) { function workerDispatch(logEvent) { debug(`sending message to master from worker ${process.pid}`); - process.send({ type: '::log4js-message', event: serialise(logEvent) }); + process.send({ topic: 'log4js:message', data: serialise(logEvent) }); } /** @@ -162,6 +162,21 @@ function loadConfigurationFile(filename) { return filename; } +// in a multi-process node environment, worker loggers will use +// process.send +const receiver = (worker, message) => { + // prior to node v6, the worker parameter was not passed (args were message, handle) + debug('cluster message received from worker ', worker, ': ', message); + if (worker.topic && worker.data) { + message = worker; + worker = undefined; + } + if (message && message.topic && message.topic === 'log4js:message') { + debug('received message: ', message.data); + sendLogEventToAppender(deserialise(message.data)); + } +}; + function configure(configurationFileOrObject) { let configObject = configurationFileOrObject; @@ -175,6 +190,15 @@ function configure(configurationFileOrObject) { Logger = loggerModule.Logger; LoggingEvent = loggerModule.LoggingEvent; module.exports.connectLogger = connectModule(config.levels).connectLogger; + + // PM2 cluster support + // PM2 runs everything as workers - install pm2-intercom for this to work. + // we only want one of the app instances to write logs + if (config.pm2 && process.env[config.pm2InstanceVar] === '0') { + debug('listening for PM2 broadcast messages'); + process.on('message', receiver); + } + enabled = true; } @@ -236,20 +260,7 @@ const log4js = { module.exports = log4js; -// in a multi-process node environment, worker loggers will use -// process.send -cluster.on('message', (worker, message) => { - // prior to node v6, the worker parameter was not passed (args were message, handle) - debug('cluster message received from worker ', worker, ': ', message); - if (worker.type && worker.event) { - message = worker; - worker = undefined; - } - if (message && message.type && message.type === '::log4js-message') { - debug('received message: ', message.event); - sendLogEventToAppender(deserialise(message.event)); - } -}); +cluster.on('message', receiver); // set ourselves up configure(process.env.LOG4JS_CONFIG || defaultConfig); diff --git a/test/tap/pm2-support-test.js b/test/tap/pm2-support-test.js new file mode 100644 index 0000000..863fd74 --- /dev/null +++ b/test/tap/pm2-support-test.js @@ -0,0 +1,10 @@ +'use strict'; + +const test = require('tap').test; + +test('PM2 Cluster support', (batch) => { + batch.test('should listen for messages if pm2 support enabled'); + batch.test('should write messages on NODE_APP_INSTANCE - 0'); + batch.test('should send messages with the correct format'); + batch.end(); +}); From 81ddd053e27f2b9c6f1bbca7bf7465ba347e995b Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Fri, 21 Jul 2017 08:35:36 +1000 Subject: [PATCH 2/5] feat(pm2): got tests for pm2 working --- lib/appenders/recording.js | 6 +-- lib/log4js.js | 7 +-- test/tap/cluster-test.js | 11 ++--- test/tap/pm2-support-test.js | 89 +++++++++++++++++++++++++++++++++--- 4 files changed, 94 insertions(+), 19 deletions(-) diff --git a/lib/appenders/recording.js b/lib/appenders/recording.js index 78992a4..f0fa2f2 100644 --- a/lib/appenders/recording.js +++ b/lib/appenders/recording.js @@ -2,7 +2,7 @@ const debug = require('debug')('log4js:recording'); -let recordedEvents = []; +const recordedEvents = []; function configure() { return function (logEvent) { @@ -12,11 +12,11 @@ function configure() { } function replay() { - return recordedEvents; + return recordedEvents.slice(); } function reset() { - recordedEvents = []; + recordedEvents.length = 0; } module.exports = { diff --git a/lib/log4js.js b/lib/log4js.js index 2184863..8677c7d 100644 --- a/lib/log4js.js +++ b/lib/log4js.js @@ -196,7 +196,11 @@ function configure(configurationFileOrObject) { // we only want one of the app instances to write logs if (config.pm2 && process.env[config.pm2InstanceVar] === '0') { debug('listening for PM2 broadcast messages'); + process.removeListener('message', receiver); process.on('message', receiver); + } else if (cluster.isMaster) { + cluster.removeListener('message', receiver); + cluster.on('message', receiver); } enabled = true; @@ -259,8 +263,5 @@ const log4js = { }; module.exports = log4js; - -cluster.on('message', receiver); - // set ourselves up configure(process.env.LOG4JS_CONFIG || defaultConfig); diff --git a/test/tap/cluster-test.js b/test/tap/cluster-test.js index 001ff17..f3e1dc6 100644 --- a/test/tap/cluster-test.js +++ b/test/tap/cluster-test.js @@ -20,14 +20,12 @@ if (cluster.isMaster) { masterLogger.info('this is master'); let workerLevel; - let workerId; cluster.on('message', (worker, message) => { - if (worker.type) { + if (worker.type || worker.topic) { message = worker; } - if (message.type === '::testing') { + if (message.type && message.type === '::testing') { workerLevel = message.level; - workerId = message.id; } }); @@ -67,10 +65,9 @@ if (cluster.isMaster) { // can't run the test in the worker, things get weird process.send({ type: '::testing', - level: workerLogger.level.toString(), - id: cluster.worker.id + level: workerLogger.level.toString() }); // test sending a badly-formed log message - process.send({ type: '::log4js-message', event: { cheese: 'gouda' } }); + process.send({ topic: 'log4js:message', data: { cheese: 'gouda' } }); cluster.worker.disconnect(); } diff --git a/test/tap/pm2-support-test.js b/test/tap/pm2-support-test.js index 863fd74..350726a 100644 --- a/test/tap/pm2-support-test.js +++ b/test/tap/pm2-support-test.js @@ -1,10 +1,87 @@ 'use strict'; const test = require('tap').test; +const cluster = require('cluster'); -test('PM2 Cluster support', (batch) => { - batch.test('should listen for messages if pm2 support enabled'); - batch.test('should write messages on NODE_APP_INSTANCE - 0'); - batch.test('should send messages with the correct format'); - batch.end(); -}); +// PM2 runs everything as workers +// - no master in the cluster (PM2 acts as master itself) +// - we will simulate that here (avoid having to include PM2 as a dev dep) +if (cluster.isMaster) { + // create two worker forks + // PASS IN NODE_APP_INSTANCE HERE + const appEvents = {}; + ['0', '1'].forEach((i) => { + cluster.fork({ NODE_APP_INSTANCE: i }); + }); + + cluster.on('message', (worker, msg) => { + if (worker.type || worker.topic) { + msg = worker; + } + if (msg.type === 'testing') { + appEvents[msg.instance] = msg.events; + } + + // we have to do the re-broadcasting that the pm2-intercom module would do. + if (msg.topic === 'log4js:message') { + for (const id in cluster.workers) { + cluster.workers[id].send(msg); + } + } + }); + + let count = 0; + cluster.on('exit', () => { + count += 1; + if (count === 2) { + test('PM2 Support', (batch) => { + batch.test('should not get any events when turned off', (t) => { + t.notOk(appEvents['0'].filter(e => e && e.data[0].indexOf('will not be logged') > -1).length); + t.notOk(appEvents['1'].filter(e => e && e.data[0].indexOf('will not be logged') > -1).length); + t.end(); + }); + + batch.test('should get events on app instance 0', (t) => { + t.equal(appEvents['0'].length, 2); + t.equal(appEvents['0'][0].data[0], 'this should now get logged'); + t.equal(appEvents['0'][1].data[0], 'this should now get logged'); + t.end(); + }); + + batch.test('should not get events on app instance 1', (t) => { + t.equal(appEvents['1'].length, 0); + t.end(); + }); + batch.end(); + }); + } + }); +} else { + const recorder = require('../../lib/appenders/recording'); + const log4js = require('../../lib/log4js'); + log4js.configure({ + appenders: { out: { type: 'recording' } }, + categories: { default: { appenders: ['out'], level: 'info' } } + }); + + const logger = log4js.getLogger('test'); + logger.info('this is a test, but without enabling PM2 support it will not be logged'); + + // we have to wait a bit, so that the process.send messages get a chance to propagate + setTimeout(() => { + log4js.configure({ + appenders: { out: { type: 'recording' } }, + categories: { default: { appenders: ['out'], level: 'info' } }, + pm2: true + }); + const anotherLogger = log4js.getLogger('test'); + anotherLogger.info('this should now get logged'); + }, 500); + + // we have to wait a bit, so that the process.send messages get a chance to propagate + setTimeout(() => { + const events = recorder.replay(); + process.send({ type: 'testing', instance: process.env.NODE_APP_INSTANCE, events: events }); + cluster.worker.disconnect(); + }, 1000); +} From 4de0dd6834ec3f3c9efa7e5bcd1e6a9d8421e813 Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Fri, 21 Jul 2017 08:49:26 +1000 Subject: [PATCH 3/5] docs(pm2): added docs for pm2 support --- docs/api.md | 2 ++ docs/faq.md | 15 +++++++++++++++ examples/pm2.js | 18 ++++++++++++++++++ 3 files changed, 35 insertions(+) create mode 100644 examples/pm2.js diff --git a/docs/api.md b/docs/api.md index d5e5be2..80320b3 100644 --- a/docs/api.md +++ b/docs/api.md @@ -17,6 +17,8 @@ Properties: * `categories` (object) - a map of named categories (string) to category definitions (object). You must define the `default` category which is used for all log events that do not match a specific category. Category definitions have two properties: * `appenders` (array of strings) - the list of appender names to be used for this category. A category must have at least one appender. * `level` (string, case insensitive) - the minimum log level that this category will send to the appenders. For example, if set to 'error' then the appenders will only receive log events of level 'error', 'fatal', 'mark' - log events of 'info', 'warn', 'debug', or 'trace' will be ignored. +* `pm2` (boolean) (optional) - set this to true if you're running your app using [pm2](http://pm2.keymetrics.io), otherwise logs will not work (you'll also need to install pm2-intercom) +* `pm2InstanceVar` (string) (optional, defaults to 'NODE_APP_INSTANCE') - set this if you're using pm2 and have changed the default name of the NODE_APP_INSTANCE variable. ## Loggers - `log4js.getLogger([category])` diff --git a/docs/faq.md b/docs/faq.md index 651ade1..2c63507 100644 --- a/docs/faq.md +++ b/docs/faq.md @@ -34,3 +34,18 @@ log4js.configure(...); // set up your categories and appenders const logger = log4js.getLogger('console'); console.log = logger.info.bind(logger); // do the same for others - console.debug, etc. ``` + +## I'm using PM2, but I'm not getting any logs! +To get log4js working with PM2, you'll need to install the [pm2-intercom](https://www.npmjs.com/package/pm2-intercom) module. +```bash +pm2 install pm2-intercom +``` +Then add the value `pm2: true` to your log4js configuration. If you're also using `node-config`, then you'll probably have renamed your `NODE_APP_INSTANCE` environment variable. If so, you'll also need to add `pm2InstanceVar: ''` where `` should be replaced with the new name you gave the instance environment variable. +```javascript +log4js.configure({ + appenders: { out: { type: 'stdout'}}, + categories: { default: { appenders: ['out'], level: 'info'}}, + pm2: true, + pm2InstanceVar: 'INSTANCE_ID' +}); +``` diff --git a/examples/pm2.js b/examples/pm2.js new file mode 100644 index 0000000..e3df67e --- /dev/null +++ b/examples/pm2.js @@ -0,0 +1,18 @@ +const log4js = require('../lib/log4js'); + +// NOTE: for PM2 support to work you'll need to install the pm2-intercom module +// `pm2 install pm2-intercom` +log4js.configure({ + appenders: { + out: { type: 'file', filename: 'pm2logs.log' } + }, + categories: { + default: { appenders: ['out'], level: 'info' } + }, + pm2: true +}); + +const logger = log4js.getLogger('app'); +setInterval(() => { + logger.info("I'm forever blowing bubbles"); +}, 1000); From 9771814a99393e4c9342d92aeef487086cb05e91 Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Sun, 23 Jul 2017 15:33:34 +1000 Subject: [PATCH 4/5] test(pm2): increasing timeout to see if it makes build less flaky --- test/tap/pm2-support-test.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/tap/pm2-support-test.js b/test/tap/pm2-support-test.js index 350726a..510c666 100644 --- a/test/tap/pm2-support-test.js +++ b/test/tap/pm2-support-test.js @@ -76,12 +76,12 @@ if (cluster.isMaster) { }); const anotherLogger = log4js.getLogger('test'); anotherLogger.info('this should now get logged'); - }, 500); + }, 1000); // we have to wait a bit, so that the process.send messages get a chance to propagate setTimeout(() => { const events = recorder.replay(); process.send({ type: 'testing', instance: process.env.NODE_APP_INSTANCE, events: events }); cluster.worker.disconnect(); - }, 1000); + }, 2000); } From e45bb6891998ffea1f7591f81696d04ced07dd78 Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Sun, 23 Jul 2017 17:09:03 +1000 Subject: [PATCH 5/5] fix(test): tweaked a couple of tests that fail during coverage --- test/tap/configuration-validation-test.js | 4 ++++ test/tap/multiprocess-shutdown-test.js | 16 +++++++++------- 2 files changed, 13 insertions(+), 7 deletions(-) diff --git a/test/tap/configuration-validation-test.js b/test/tap/configuration-validation-test.js index 5a652ad..b0fba77 100644 --- a/test/tap/configuration-validation-test.js +++ b/test/tap/configuration-validation-test.js @@ -274,6 +274,10 @@ test('log4js configuration validation', (batch) => { const mainPath = path.dirname(require.main.filename); const sandboxConfig = { singleOnly: true, requires: {} }; sandboxConfig.requires[`${mainPath}/cheese`] = testAppender('correct'); + // add this one, because when we're running coverage the main path is a bit different + sandboxConfig.requires[ + `${path.join(mainPath, '../../node_modules/tap/node_modules/nyc/bin/cheese')}` + ] = testAppender('correct'); const SandboxedConfiguration = sandbox.require( '../../lib/configuration', sandboxConfig ); diff --git a/test/tap/multiprocess-shutdown-test.js b/test/tap/multiprocess-shutdown-test.js index 5e9b84c..6d3c4f2 100644 --- a/test/tap/multiprocess-shutdown-test.js +++ b/test/tap/multiprocess-shutdown-test.js @@ -21,13 +21,15 @@ test('multiprocess appender shutdown (master)', { timeout: 2000 }, (t) => { setTimeout(() => { log4js.shutdown(() => { - net.connect({ port: 12345 }, () => { - t.fail('connection should not still work'); - t.end(); - }).on('error', (err) => { - t.ok(err, 'we got a connection error'); - t.end(); - }); + setTimeout(() => { + net.connect({ port: 12345 }, () => { + t.fail('connection should not still work'); + t.end(); + }).on('error', (err) => { + t.ok(err, 'we got a connection error'); + t.end(); + }); + }, 500); }); }, 500); });