From 7c22fb57523d55ac81006c42797580cb3080d0c9 Mon Sep 17 00:00:00 2001 From: Patrick Malouin Date: Wed, 10 Jun 2015 10:32:36 -0400 Subject: [PATCH 1/2] clustered appender - Unwrap the serialized errors When logging an `Error` object using the clustered appender, the logged event is a JSON representation of the error, ex: [2015-06-09 11:13:48.257] [ERROR] middleware.Security - { stack: 'Error: User is not authorized\n at Object.exec (D:\\Borealis\\demoux\\IMS\\server\\IMS\\middleware\\SecurityCheck\\Instance.js:41:14)\n [...] at applyArgs (D:\\Borealis\\demoux\\IMS\\server\\node_modules\\flow\\flow.js:9:15)\n at Function.flowState (D:\\Borealis\\demoux\\IMS\\server\\node_modules\\flow\\flow.js:39:6)\n at applyArgs (D:\\Borealis\\demoux\\IMS\\server\\node_modules\\flow\\flow.js:9:15)\n at Function.thisFlow.exec (D:\\Borealis\\demoux\\IMS\\server\\node_modules\\flow\\flow.js:94:4)\n at applyArgs (D:\\Borealis\\demoux\\IMS\\server\\node_modules\\flow\\flow.js:9:15)\n at thisFlow (D:\\Borealis\\demoux\\IMS\\server\\node_modules\\flow\\flow.js:15:4)\n at Object.exec (D:\\Borealis\\demoux\\IMS\\server\\node_modules\\flow\\flow.js:103:42)' } The error should be formatted identically as with other appenders (e.g. only printing the stack). This changes adds a check for a `stack` attribute on the serialized loggingEvent and unwraps the errors while deserializing it. Result is: [2015-06-09 11:13:48.257] [ERROR] middleware.Security - Error: User is not authorized at Object.exec (D:\Borealis\demoux\IMS\server\IMS\middleware\SecurityCheck\Instance.js:41:14) at applyArgs (D:\Borealis\demoux\IMS\server\node_modules\flow\flow.js:9:15) at Function.flowState (D:\Borealis\demoux\IMS\server\node_modules\flow\flow.js:39:6) at applyArgs (D:\Borealis\demoux\IMS\server\node_modules\flow\flow.js:9:15) at Function.thisFlow.exec (D:\Borealis\demoux\IMS\server\node_modules\flow\flow.js:94:4) at applyArgs (D:\Borealis\demoux\IMS\server\node_modules\flow\flow.js:9:15) at thisFlow (D:\Borealis\demoux\IMS\server\node_modules\flow\flow.js:15:4) at Object.exec (D:\Borealis\demoux\IMS\server\node_modules\flow\flow.js:103:42) --- lib/appenders/clustered.js | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/lib/appenders/clustered.js b/lib/appenders/clustered.js index 7c31248..fdbb283 100755 --- a/lib/appenders/clustered.js +++ b/lib/appenders/clustered.js @@ -37,7 +37,14 @@ function deserializeLoggingEvent(loggingEventString) { loggingEvent = JSON.parse(loggingEventString); loggingEvent.startTime = new Date(loggingEvent.startTime); loggingEvent.level = log4js.levels.toLevel(loggingEvent.level.levelStr); - + // Unwrap serialized errors + for (var i = 0; i < loggingEvent.data.length; i++) { + var item = loggingEvent.data[i]; + if (item && item.stack) { + loggingEvent.data[i] = item.stack; + } + } + } catch (e) { // JSON.parse failed, just log the contents probably a naughty. From 2cdbd60c7e76e78d09c44dbdc96fb8a1b9891982 Mon Sep 17 00:00:00 2001 From: Patrick Malouin Date: Thu, 11 Jun 2015 16:20:54 -0400 Subject: [PATCH 2/2] Add test for the logging event deserialization --- test/clusteredAppender-test.js | 35 +++++++++++++++++++++++++++++----- 1 file changed, 30 insertions(+), 5 deletions(-) diff --git a/test/clusteredAppender-test.js b/test/clusteredAppender-test.js index f36748c..ea3355d 100755 --- a/test/clusteredAppender-test.js +++ b/test/clusteredAppender-test.js @@ -12,18 +12,30 @@ vows.describe('log4js cluster appender').addBatch({ var registeredClusterEvents = []; var loggingEvents = []; + var onChildProcessForked; + var onMasterReceiveChildMessage; - // Fake cluster module, so no cluster listeners be really added + // Fake cluster module, so no real cluster listeners be really added var fakeCluster = { on: function(event, callback) { registeredClusterEvents.push(event); + onChildProcessForked = callback; }, isMaster: true, isWorker: false, }; + var fakeWorker = { + on: function(event, callback) { + onMasterReceiveChildMessage = callback; + }, + process: { + pid: 123 + }, + id: 'workerid' + }; var fakeActualAppender = function(loggingEvent) { loggingEvents.push(loggingEvent); @@ -38,12 +50,21 @@ vows.describe('log4js cluster appender').addBatch({ var masterAppender = appenderModule.appender({ actualAppenders: [fakeActualAppender, fakeActualAppender, fakeActualAppender], - appenders: [{}, {category: "test"}, {category: "wovs"}] + appenders: [{}, {category: "test"}, {category: "wovs"}] }); // Actual test - log message using masterAppender masterAppender(new LoggingEvent('wovs', 'Info', ['masterAppender test'])); - + + // Simulate a 'fork' event to register the master's message handler on our fake worker. + onChildProcessForked(fakeWorker); + // Simulate a cluster message received by the masterAppender. + var simulatedLoggingEvent = new LoggingEvent('wovs', 'Error', ['message deserialization test', {stack: 'my wrapped stack'}]); + onMasterReceiveChildMessage({ + type : '::log-message', + event : JSON.stringify(simulatedLoggingEvent) + }); + var returnValue = { registeredClusterEvents: registeredClusterEvents, loggingEvents: loggingEvents, @@ -57,9 +78,13 @@ vows.describe('log4js cluster appender').addBatch({ }, "should log using actual appender": function(topic) { - assert.equal(topic.loggingEvents.length, 2) + assert.equal(topic.loggingEvents.length, 4); assert.equal(topic.loggingEvents[0].data[0], 'masterAppender test'); - assert.equal(topic.loggingEvents[1].data[0], 'masterAppender test'); + assert.equal(topic.loggingEvents[1].data[0], 'masterAppender test'); + assert.equal(topic.loggingEvents[2].data[0], 'message deserialization test'); + assert.equal(topic.loggingEvents[2].data[1], 'my wrapped stack'); + assert.equal(topic.loggingEvents[3].data[0], 'message deserialization test'); + assert.equal(topic.loggingEvents[3].data[1], 'my wrapped stack'); }, },