diff --git a/lib/appenders/multiprocess.js b/lib/appenders/multiprocess.js index ab0d97b..f6db7f7 100644 --- a/lib/appenders/multiprocess.js +++ b/lib/appenders/multiprocess.js @@ -1,5 +1,6 @@ 'use strict'; +const debug = require('debug')('log4js:multiprocess'); const levels = require('../levels'); const net = require('net'); @@ -10,12 +11,13 @@ const END_MSG = '__LOG4JS__'; * Output goes to config.actualAppender (config.appender is used to * set up that appender). */ -function logServer(config) { +function logServer(config, actualAppender) { /** * Takes a utf-8 string, returns an object with * the correct log properties. */ function deserializeLoggingEvent(clientSocket, msg) { + debug('deserialising log event'); let loggingEvent; try { loggingEvent = JSON.parse(msg); @@ -37,8 +39,6 @@ function logServer(config) { return loggingEvent; } - const actualAppender = config.actualAppender; - /* eslint prefer-arrow-callback:0 */ const server = net.createServer(function serverCreated(clientSocket) { clientSocket.setEncoding('utf8'); @@ -46,11 +46,13 @@ function logServer(config) { function logTheMessage(msg) { if (logMessage.length > 0) { + debug('deserialising log event and sending to actual appender'); actualAppender(deserializeLoggingEvent(clientSocket, msg)); } } function chunkReceived(chunk) { + debug('chunk of data received'); let event; logMessage += chunk || ''; if (logMessage.indexOf(END_MSG) > -1) { @@ -67,15 +69,18 @@ function logServer(config) { }); server.listen(config.loggerPort || 5000, config.loggerHost || 'localhost', function () { + debug('master server listening'); // allow the process to exit, if this is the only socket active server.unref(); }); function app(event) { + debug('log event sent directly to actual appender (local event)'); return actualAppender(event); } app.shutdown = function (cb) { + debug('master shutdown called, closing server'); server.close(cb); }; @@ -88,19 +93,24 @@ function workerAppender(config) { let socket; function write(loggingEvent) { + debug('Writing log event to socket'); // JSON.stringify(new Error('test')) returns {}, which is not really useful for us. // The following allows us to serialize errors correctly. // Validate that we really are in this case - if (loggingEvent && loggingEvent.stack && JSON.stringify(loggingEvent) === '{}') { - loggingEvent = { stack: loggingEvent.stack }; - } + const logData = loggingEvent.data.map((e) => { + if (e && e.stack && JSON.stringify(e) === '{}') { + e = { stack: e.stack }; + } + return e; + }); + loggingEvent.data = logData; socket.write(JSON.stringify(loggingEvent), 'utf8'); socket.write(END_MSG, 'utf8'); } function emptyBuffer() { let evt; - + debug('emptying worker buffer'); /* eslint no-cond-assign:0 */ while ((evt = buffer.shift())) { write(evt); @@ -108,8 +118,10 @@ function workerAppender(config) { } function createSocket() { + debug(`worker appender creating socket to ${config.loggerHost || 'localhost'}:${config.loggerPort || 5000}`); socket = net.createConnection(config.loggerPort || 5000, config.loggerHost || 'localhost'); socket.on('connect', () => { + debug('worker socket connected'); emptyBuffer(); canWrite = true; }); @@ -124,29 +136,44 @@ function workerAppender(config) { if (canWrite) { write(loggingEvent); } else { + debug('worker buffering log event because it cannot write at the moment'); buffer.push(loggingEvent); } } log.shutdown = function (cb) { + debug('worker shutdown called'); socket.removeAllListeners('close'); socket.close(cb); }; return log; } -function createAppender(config) { +function createAppender(config, appender) { if (config.mode === 'master') { - return logServer(config); + debug('Creating master appender'); + return logServer(config, appender); } + debug('Creating worker appender'); return workerAppender(config); } function configure(config, layouts, findAppender) { - if (config.appender && config.mode === 'master') { - config.actualAppender = findAppender(config.appender); + let appender; + debug(`configure with mode = ${config.mode}`); + if (config.mode === 'master') { + if (!config.appender) { + debug(`no appender found in config ${config}`); + throw new Error('multiprocess master must have an "appender" defined'); + } + debug(`actual appender is ${config.appender}`); + appender = findAppender(config.appender); + if (!appender) { + debug(`actual appender "${config.appender}" not found`); + throw new Error(`multiprocess master appender "${config.appender}" not defined`); + } } - return createAppender(config); + return createAppender(config, appender); } module.exports.configure = configure; diff --git a/lib/appenders/recording.js b/lib/appenders/recording.js index da66607..78992a4 100644 --- a/lib/appenders/recording.js +++ b/lib/appenders/recording.js @@ -1,9 +1,12 @@ 'use strict'; +const debug = require('debug')('log4js:recording'); + let recordedEvents = []; function configure() { return function (logEvent) { + debug(`received logEvent, number of events now ${recordedEvents.length + 1}`); recordedEvents.push(logEvent); }; } @@ -19,5 +22,7 @@ function reset() { module.exports = { configure: configure, replay: replay, - reset: reset + playback: replay, + reset: reset, + erase: reset }; diff --git a/test/tap/multiprocess-test.js b/test/tap/multiprocess-test.js index 0b0c61c..0d6f1ed 100644 --- a/test/tap/multiprocess-test.js +++ b/test/tap/multiprocess-test.js @@ -2,16 +2,13 @@ const test = require('tap').test; const sandbox = require('sandboxed-module'); +const recording = require('../../lib/appenders/recording'); function makeFakeNet() { return { - logEvents: [], data: [], cbs: {}, createConnectionCalled: 0, - fakeAppender: function (logEvent) { - this.logEvents.push(logEvent); - }, createConnection: function (port, host) { const fakeNet = this; this.port = port; @@ -54,27 +51,36 @@ function makeFakeNet() { } test('Multiprocess Appender', (batch) => { + batch.beforeEach((done) => { + recording.erase(); + done(); + }); + batch.test('worker', (t) => { const fakeNet = makeFakeNet(); - const appender = sandbox.require( - '../../lib/appenders/multiprocess', + const log4js = sandbox.require( + '../../lib/log4js', { requires: { net: fakeNet } } - ).appender({ mode: 'worker', loggerPort: 1234, loggerHost: 'pants' }); + ); + log4js.configure({ + appenders: { worker: { type: 'multiprocess', mode: 'worker', loggerPort: 1234, loggerHost: 'pants' } }, + categories: { default: { appenders: ['worker'], level: 'trace' } } + }); - // don't need a proper log event for the worker tests - appender('before connect'); + const logger = log4js.getLogger(); + logger.info('before connect'); fakeNet.cbs.connect(); - appender('after connect'); + logger.info('after connect'); fakeNet.cbs.close(true); - appender('after error, before connect'); + logger.info('after error, before connect'); fakeNet.cbs.connect(); - appender('after error, after connect'); - appender(new Error('Error test')); + logger.info('after error, after connect'); + logger.error(new Error('Error test')); const net = fakeNet; t.test('should open a socket to the loggerPort and loggerHost', (assert) => { @@ -84,23 +90,23 @@ test('Multiprocess Appender', (batch) => { }); t.test('should buffer messages written before socket is connected', (assert) => { - assert.equal(net.data[0], JSON.stringify('before connect')); + assert.include(net.data[0], JSON.stringify('before connect')); assert.end(); }); t.test('should write log messages to socket as json strings with a terminator string', (assert) => { - assert.equal(net.data[0], JSON.stringify('before connect')); + assert.include(net.data[0], JSON.stringify('before connect')); assert.equal(net.data[1], '__LOG4JS__'); - assert.equal(net.data[2], JSON.stringify('after connect')); + assert.include(net.data[2], JSON.stringify('after connect')); assert.equal(net.data[3], '__LOG4JS__'); assert.equal(net.encoding, 'utf8'); assert.end(); }); t.test('should attempt to re-open the socket on error', (assert) => { - assert.equal(net.data[4], JSON.stringify('after error, before connect')); + assert.include(net.data[4], JSON.stringify('after error, before connect')); assert.equal(net.data[5], '__LOG4JS__'); - assert.equal(net.data[6], JSON.stringify('after error, after connect')); + assert.include(net.data[6], JSON.stringify('after error, after connect')); assert.equal(net.data[7], '__LOG4JS__'); assert.equal(net.createConnectionCalled, 2); assert.end(); @@ -108,48 +114,53 @@ test('Multiprocess Appender', (batch) => { t.test('should serialize an Error correctly', (assert) => { assert.ok( - JSON.parse(net.data[8]).stack, - `Expected:\n\n${net.data[8]}\n\n to have a 'stack' property` + JSON.parse(net.data[8]).data[0].stack, + `Expected:\n\n${net.data[8]}\n\n to have a 'data[0].stack' property` ); - const actual = JSON.parse(net.data[8]).stack; + const actual = JSON.parse(net.data[8]).data[0].stack; assert.match(actual, /^Error: Error test/); assert.end(); }); + t.end(); }); batch.test('worker with timeout', (t) => { const fakeNet = makeFakeNet(); - const appender = sandbox.require( - '../../lib/appenders/multiprocess', + const log4js = sandbox.require( + '../../lib/log4js', { requires: { net: fakeNet } } - ).appender({ mode: 'worker' }); + ); + log4js.configure({ + appenders: { worker: { type: 'multiprocess', mode: 'worker' } }, + categories: { default: { appenders: ['worker'], level: 'trace' } } + }); - // don't need a proper log event for the worker tests - appender('before connect'); + const logger = log4js.getLogger(); + logger.info('before connect'); fakeNet.cbs.connect(); - appender('after connect'); + logger.info('after connect'); fakeNet.cbs.timeout(); - appender('after timeout, before close'); + logger.info('after timeout, before close'); fakeNet.cbs.close(); - appender('after close, before connect'); + logger.info('after close, before connect'); fakeNet.cbs.connect(); - appender('after close, after connect'); + logger.info('after close, after connect'); const net = fakeNet; t.test('should attempt to re-open the socket', (assert) => { // skipping the __LOG4JS__ separators - assert.equal(net.data[0], JSON.stringify('before connect')); - assert.equal(net.data[2], JSON.stringify('after connect')); - assert.equal(net.data[4], JSON.stringify('after timeout, before close')); - assert.equal(net.data[6], JSON.stringify('after close, before connect')); - assert.equal(net.data[8], JSON.stringify('after close, after connect')); + assert.include(net.data[0], JSON.stringify('before connect')); + assert.include(net.data[2], JSON.stringify('after connect')); + assert.include(net.data[4], JSON.stringify('after timeout, before close')); + assert.include(net.data[6], JSON.stringify('after close, before connect')); + assert.include(net.data[8], JSON.stringify('after close, after connect')); assert.equal(net.createConnectionCalled, 2); assert.end(); }); @@ -159,14 +170,18 @@ test('Multiprocess Appender', (batch) => { batch.test('worker defaults', (t) => { const fakeNet = makeFakeNet(); - sandbox.require( - '../../lib/appenders/multiprocess', + const log4js = sandbox.require( + '../../lib/log4js', { requires: { net: fakeNet } } - ).appender({ mode: 'worker' }); + ); + log4js.configure({ + appenders: { worker: { type: 'multiprocess', mode: 'worker' } }, + categories: { default: { appenders: ['worker'], level: 'trace' } } + }); t.test('should open a socket to localhost:5000', (assert) => { assert.equal(fakeNet.port, 5000); @@ -179,22 +194,29 @@ test('Multiprocess Appender', (batch) => { batch.test('master', (t) => { const fakeNet = makeFakeNet(); - const appender = sandbox.require( - '../../lib/appenders/multiprocess', + const log4js = sandbox.require( + '../../lib/log4js', { requires: { - net: fakeNet + net: fakeNet, + './appenders/recording': recording } } - ).appender({ - mode: 'master', - loggerHost: 'server', - loggerPort: 1234, - actualAppender: fakeNet.fakeAppender.bind(fakeNet) + ); + log4js.configure({ + appenders: { + recorder: { type: 'recording' }, + master: { + type: 'multiprocess', + mode: 'master', + loggerPort: 1234, + loggerHost: 'server', + appender: 'recorder' + } + }, + categories: { default: { appenders: ['master'], level: 'trace' } } }); - appender('this should be sent to the actual appender directly'); - const net = fakeNet; t.test('should listen for log messages on loggerPort and loggerHost', (assert) => { @@ -204,7 +226,9 @@ test('Multiprocess Appender', (batch) => { }); t.test('should return the underlying appender', (assert) => { - assert.equal(net.logEvents[0], 'this should be sent to the actual appender directly'); + log4js.getLogger().info('this should be sent to the actual appender directly'); + + assert.equal(recording.replay()[0].data[0], 'this should be sent to the actual appender directly'); assert.end(); }); @@ -237,48 +261,98 @@ test('Multiprocess Appender', (batch) => { ); net.cbs.data('bad message__LOG4JS__'); + const logEvents = recording.replay(); // should parse log messages into log events and send to appender - assert.equal(net.logEvents[1].level.toString(), 'ERROR'); - assert.equal(net.logEvents[1].data[0], 'an error message'); - assert.equal(net.logEvents[1].remoteAddress, '1.2.3.4'); - assert.equal(net.logEvents[1].remotePort, '1234'); + assert.equal(logEvents[0].level.toString(), 'ERROR'); + assert.equal(logEvents[0].data[0], 'an error message'); + assert.equal(logEvents[0].remoteAddress, '1.2.3.4'); + assert.equal(logEvents[0].remotePort, '1234'); // should parse log messages split into multiple chunks' - assert.equal(net.logEvents[2].level.toString(), 'DEBUG'); - assert.equal(net.logEvents[2].data[0], 'some debug'); - assert.equal(net.logEvents[2].remoteAddress, '1.2.3.4'); - assert.equal(net.logEvents[2].remotePort, '1234'); + assert.equal(logEvents[1].level.toString(), 'DEBUG'); + assert.equal(logEvents[1].data[0], 'some debug'); + assert.equal(logEvents[1].remoteAddress, '1.2.3.4'); + assert.equal(logEvents[1].remotePort, '1234'); // should parse multiple log messages in a single chunk' - assert.equal(net.logEvents[3].data[0], 'some debug'); - assert.equal(net.logEvents[4].data[0], 'some debug'); - assert.equal(net.logEvents[5].data[0], 'some debug'); + assert.equal(logEvents[2].data[0], 'some debug'); + assert.equal(logEvents[3].data[0], 'some debug'); + assert.equal(logEvents[4].data[0], 'some debug'); // should handle log messages sent as part of end event' - assert.equal(net.logEvents[6].data[0], "that's all folks"); + assert.equal(logEvents[5].data[0], "that's all folks"); // should handle unparseable log messages - assert.equal(net.logEvents[7].level.toString(), 'ERROR'); - assert.equal(net.logEvents[7].categoryName, 'log4js'); - assert.equal(net.logEvents[7].data[0], 'Unable to parse log:'); - assert.equal(net.logEvents[7].data[1], 'bad message'); + assert.equal(logEvents[6].level.toString(), 'ERROR'); + assert.equal(logEvents[6].categoryName, 'log4js'); + assert.equal(logEvents[6].data[0], 'Unable to parse log:'); + assert.equal(logEvents[6].data[1], 'bad message'); assert.end(); }); t.end(); }); - batch.test('master defaults', (t) => { + batch.test('master without actual appender throws error', (t) => { const fakeNet = makeFakeNet(); - sandbox.require( - '../../lib/appenders/multiprocess', + const log4js = sandbox.require( + '../../lib/log4js', { requires: { net: fakeNet } } - ).appender({ mode: 'master' }); + ); + t.throws(() => + log4js.configure({ + appenders: { master: { type: 'multiprocess', mode: 'master' } }, + categories: { default: { appenders: ['master'], level: 'trace' } } + }), + new Error('multiprocess master must have an "appender" defined') + ); + t.end(); + }); + + batch.test('master with unknown appender throws error', (t) => { + const fakeNet = makeFakeNet(); + + const log4js = sandbox.require( + '../../lib/log4js', + { + requires: { + net: fakeNet + } + } + ); + t.throws(() => + log4js.configure({ + appenders: { master: { type: 'multiprocess', mode: 'master', appender: 'cheese' } }, + categories: { default: { appenders: ['master'], level: 'trace' } } + }), + new Error('multiprocess master appender "cheese" not defined') + ); + t.end(); + }); + + batch.test('master defaults', (t) => { + const fakeNet = makeFakeNet(); + + const log4js = sandbox.require( + '../../lib/log4js', + { + requires: { + net: fakeNet + } + } + ); + log4js.configure({ + appenders: { + stdout: { type: 'stdout' }, + master: { type: 'multiprocess', mode: 'master', appender: 'stdout' } + }, + categories: { default: { appenders: ['master'], level: 'trace' } } + }); t.test('should listen for log messages on localhost:5000', (assert) => { assert.equal(fakeNet.port, 5000); @@ -288,44 +362,5 @@ test('Multiprocess Appender', (batch) => { t.end(); }); - batch.test('configure', (t) => { - const results = {}; - const fakeNet = makeFakeNet(); - - sandbox.require( - '../../lib/appenders/multiprocess', - { - requires: { - net: fakeNet, - '../log4js': { - loadAppender: function (app) { - results.appenderLoaded = app; - }, - appenderMakers: { - madeupappender: function (config, options) { - results.config = config; - results.options = options; - } - } - } - } - } - ).configure( - { - mode: 'master', - appender: { - type: 'madeupappender', - cheese: 'gouda' - } - }, - { crackers: 'jacobs' } - ); - - t.equal(results.appenderLoaded, 'madeupappender', 'should load underlying appender for master'); - t.equal(results.config.cheese, 'gouda', 'should pass config to underlying appender'); - t.equal(results.options.crackers, 'jacobs', 'should pass options to underlying appender'); - t.end(); - }); - batch.end(); });