archive-gh-me/log4js-node
1
0
Fork 0
mirror of https://github.com/log4js-node/log4js-node.git synced 2025-12-08 19:26:01 +00:00
Code Issues Projects Releases Wiki Activity

fix(test): got multiprocess tests working

Browse Source
This commit is contained in:
Gareth Jones 2017-02-27 08:25:11 +11:00
parent d26b1a147b
commit 514fb9c771
3 changed files with 188 additions and 121 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

51
lib/appenders/multiprocess.js
View File

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

7
lib/appenders/recording.js
View File

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

251
test/tap/multiprocess-test.js
View File

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