From 863ac652270f0b3fd3ff44a208d14c387221d9bf Mon Sep 17 00:00:00 2001 From: Gareth Jones Date: Mon, 15 Jul 2019 12:00:51 +1000 Subject: [PATCH] chore: made one of the tests simpler trying to diagnose a weird problem --- lib/appenders/multiprocess.js | 33 ++++++++++-------- test/{tap => }/multiprocess-worker.js | 2 +- test/tap/multiprocess-shutdown-test.js | 47 ++++++++++---------------- 3 files changed, 37 insertions(+), 45 deletions(-) rename test/{tap => }/multiprocess-worker.js (90%) diff --git a/lib/appenders/multiprocess.js b/lib/appenders/multiprocess.js index 2226e81..227a5a2 100644 --- a/lib/appenders/multiprocess.js +++ b/lib/appenders/multiprocess.js @@ -17,7 +17,7 @@ function logServer(config, actualAppender, levels) { * the correct log properties. */ function deserializeLoggingEvent(clientSocket, msg) { - debug('deserialising log event'); + debug('(master) deserialising log event'); const loggingEvent = LoggingEvent.deserialise(msg); loggingEvent.remoteAddress = clientSocket.remoteAddress; loggingEvent.remotePort = clientSocket.remotePort; @@ -26,19 +26,20 @@ function logServer(config, actualAppender, levels) { } /* eslint prefer-arrow-callback:0 */ - const server = net.createServer(function serverCreated(clientSocket) { + const server = net.createServer(function connectionHandler(clientSocket) { + debug('(master) connection received'); clientSocket.setEncoding('utf8'); let logMessage = ''; function logTheMessage(msg) { if (logMessage.length > 0) { - debug('deserialising log event and sending to actual appender'); + debug('(master) deserialising log event and sending to actual appender'); actualAppender(deserializeLoggingEvent(clientSocket, msg)); } } function chunkReceived(chunk) { - debug('chunk of data received'); + debug('(master) chunk of data received'); let event; logMessage += chunk || ''; if (logMessage.indexOf(END_MSG) > -1) { @@ -67,19 +68,19 @@ function logServer(config, actualAppender, levels) { clientSocket.on('error', handleError); }); - server.listen(config.loggerPort || 5000, config.loggerHost || 'localhost', function () { - debug('master server listening'); + server.listen(config.loggerPort || 5000, config.loggerHost || 'localhost', function (e) { + debug('(master) master server listening, error was ', e); // 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)'); + debug('(master) log event sent directly to actual appender (local event)'); return actualAppender(event); } app.shutdown = function (cb) { - debug('master shutdown called, closing server'); + debug('(master) master shutdown called, closing server'); server.close(cb); }; @@ -93,14 +94,14 @@ function workerAppender(config) { let shutdownAttempts = 3; function write(loggingEvent) { - debug('Writing log event to socket'); + debug('(worker) Writing log event to socket'); socket.write(loggingEvent.serialise(), 'utf8'); socket.write(END_MSG, 'utf8'); } function emptyBuffer() { let evt; - debug('emptying worker buffer'); + debug('(worker) emptying worker buffer'); /* eslint no-cond-assign:0 */ while ((evt = buffer.shift())) { write(evt); @@ -108,10 +109,12 @@ function workerAppender(config) { } function createSocket() { - debug(`worker appender creating socket to ${config.loggerHost || 'localhost'}:${config.loggerPort || 5000}`); + debug( + `(worker) 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'); + debug('(worker) worker socket connected'); emptyBuffer(); canWrite = true; }); @@ -126,14 +129,14 @@ function workerAppender(config) { if (canWrite) { write(loggingEvent); } else { - debug('worker buffering log event because it cannot write at the moment'); + debug('(worker) worker buffering log event because it cannot write at the moment'); buffer.push(loggingEvent); } } log.shutdown = function (cb) { - debug('worker shutdown called'); + debug('(worker) worker shutdown called'); if (buffer.length && shutdownAttempts) { - debug('worker buffer has items, waiting 100ms to empty'); + debug('(worker) worker buffer has items, waiting 100ms to empty'); shutdownAttempts -= 1; setTimeout(() => { log.shutdown(cb); diff --git a/test/tap/multiprocess-worker.js b/test/multiprocess-worker.js similarity index 90% rename from test/tap/multiprocess-worker.js rename to test/multiprocess-worker.js index a688b0a..804c4c9 100644 --- a/test/tap/multiprocess-worker.js +++ b/test/multiprocess-worker.js @@ -1,5 +1,5 @@ if (process.argv.indexOf('start-multiprocess-worker') >= 0) { - const log4js = require('../../lib/log4js'); + const log4js = require('../lib/log4js'); const port = parseInt(process.argv[process.argv.length - 1], 10); log4js.configure({ appenders: { diff --git a/test/tap/multiprocess-shutdown-test.js b/test/tap/multiprocess-shutdown-test.js index 7c2d052..532ec81 100644 --- a/test/tap/multiprocess-shutdown-test.js +++ b/test/tap/multiprocess-shutdown-test.js @@ -23,13 +23,15 @@ test('multiprocess appender shutdown (master)', { timeout: 2000 }, (t) => { setTimeout(() => { log4js.shutdown(() => { 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(); - }); + 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(); + }); }, 250); }); }, 250); @@ -92,23 +94,10 @@ test('multiprocess appender shutdown (worker)', (t) => { test('multiprocess appender crash (worker)', (t) => { const loggerPort = 12346; - const messages = []; - const fakeConsole = { - log: function (msg) { - messages.push(msg); - } - }; - const log4jsWithFakeConsole = sandbox.require( - '../../lib/log4js', - { - globals: { - console: fakeConsole - } - } - ); - log4jsWithFakeConsole.configure({ + const vcr = require('../../lib/appenders/recording'); + log4js.configure({ appenders: { - console: { type: 'console', layout: { type: 'messagePassThrough' } }, + console: { type: 'recording' }, multi: { type: 'multiprocess', mode: 'master', @@ -119,17 +108,17 @@ test('multiprocess appender crash (worker)', (t) => { categories: { default: { appenders: ['multi'], level: 'debug' } } }); - const worker = childProcess.fork( - require.resolve('./multiprocess-worker'), - ['start-multiprocess-worker', loggerPort] - ); + const worker = childProcess.fork(require.resolve('../multiprocess-worker'), [ + 'start-multiprocess-worker', + loggerPort + ]); worker.on('message', (m) => { if (m === 'worker is done') { setTimeout(() => { worker.kill(); - t.equal(messages[0], 'Logging from worker'); - log4jsWithFakeConsole.shutdown(() => t.end()); + t.equal(vcr.replay()[0].data[0], 'Logging from worker'); + log4js.shutdown(() => t.end()); }, 100); } });