Merge pull request #509 from nomiddlename/pm2-support

PM2 Support

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])`
 

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: '<NEW_APP_INSTANCE_ID>'` where `<NEW_APP_INSTANCE_ID>` 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'
+});
+```

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);

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 = {

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;

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,19 @@ 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.removeListener('message', receiver);
+    process.on('message', receiver);
+  } else if (cluster.isMaster) {
+    cluster.removeListener('message', receiver);
+    cluster.on('message', receiver);
+  }
+
   enabled = true;
 }
 
@@ -235,21 +263,5 @@ 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));
-  }
-});
-
 // set ourselves up
 configure(process.env.LOG4JS_CONFIG || defaultConfig);

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();
 }

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
     );

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);
 });

test/tap/pm2-support-test.js

@@ -0,0 +1,87 @@
+'use strict';
+
+const test = require('tap').test;
+const cluster = require('cluster');
+
+// 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');
+  }, 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();
+  }, 2000);
+}