flatiron/winston — Issue #80: Logs fail when multiple processes or timers log to same file
Author: fquatro
Created: 2011-12-29 17:04:53+00:00
State: open

I created this test suite after experiencing missing log entries in my file transport. The console transport on the same Logger instance would contain all log entries. I attempted to mimic my original application's logging which created a Winston Logger in the node global namespace and added a file transport to the Logger. The application forked child processes and in the child processes created a Winston Logger in the node global namespace and added a file transport to the Logger. All file transports were configured with the same options and logged to the same file.

The vows suite (and dependent file) below will fail assertions. The three parent vows contexts are executed in parallel. The order in which they finish is undefined and the results may vary from each execution. The suite consistently fails with "expected true, got false // WinstonSuite.js:85" for example:

··1st Vow - log does not contain "WinstonSuite 1st Topic: Log Test 0 random 5UasDeNJpH"
✗

should log all delayed messages
✗ to file
» expected true, got false // WinstonSuite.js:85
✗ Broken » 2 honored ∙ 1 broken (15.114s)

##System Information
Mac OS X 10.6.8

$ node --version
v0.5.4

$ npm list
├── libxmljs@0.4.3
├─┬ vows@0.6.1
│ └── eyes@0.1.7
├─┬ winston@0.5.9
│ ├── async@0.1.15
│ ├── colors@0.6.0-1
│ ├── eyes@0.1.7
│ ├─┬ loggly@0.3.10
│ │ ├── request@2.1.1
│ │ └── timespan@2.2.0
│ ├── pkginfo@0.2.3
│ └── stack-trace@0.0.6
└─┬ xmlrpc@0.9.2
├── sax@0.3.4
└── xmlbuilder@0.3.1

## WinstonSuite.js
```javascript
var vows = require('vows');
var assert = require('assert');
var winston = require('winston');
var fs = require("fs");
var path = require('path');
var oChildProcess = require("child_process");

var oLogger = new winston.Logger();
var oTestTransportOptions = {
filename : 'winston-test.log',
dirname : __dirname,
/*maxsize : 100000,*/
handleExceptions : true,
level : 'silly',
timestamp : true,
json : false
};
var oTransport = new winston.transports.File(oTestTransportOptions);
oTransport.name = "test-file-transport";
oLogger.add(oTransport, oTestTransportOptions, true);

var strPrefix1 = 'WinstonSuite 1st Topic: ';
var strPrefix2 = 'WinstonSuite 2nd Topic: ';
var strPrefix3 = 'WinstonSuite 3rd Topic: ';
var nForkMax = 100;
var nLogMsgNumber = 10000;

function getRandomString(p_nLength)
{
if (p_nLength === null || p_nLength === undefined || p_nLength === NaN) {
p_nLength = 6;
}

var str = "";
var strChars = "0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ";

for(var i=0; i < p_nLength; i++) {
str += strChars.charAt(Math.floor(Math.random() * strChars.length));
}

return str;
}

var logArray = new Array();
for (var i = 0; i < nLogMsgNumber; i++) {
logArray.push('Log Test ' + i + ' random ' + getRandomString(10));
}

var strLogLast = 'Log TEST LAST';

vows.describe('WinstonSuite').addBatch({
// multiple runs of this context with all other contexts commented out
// will eventually cause vow assert failure in one of the runs
'should log all delayed messages' : {
topic : function() {
var fnCallback = function(err, level, msg, meta) {
setTimeout(this.callback, 15000, err, level, msg, meta);
};

for (var index in logArray) {
var strMsg = strPrefix1 + logArray[index];
var fnLog = function (p_strMsg) {
try {
oLogger.log('error', p_strMsg);
} catch (ex) {
console.log("error: " + __filename + ' - exception: ' + ex);
}
};
var nRandomInteger = Math.floor(Math.random() * 200);
setTimeout(fnLog, nRandomInteger, strMsg);
//oLogger.log('error', 'regular ' + strPrefix1 + logArray[index]);
}

oLogger.log('error', strPrefix1 + strLogLast, fnCallback.bind(this));
},
'to file': function(err, level, msg, meta) {
assert.equal(msg, strPrefix1 + strLogLast);
var logText = fs.readFileSync(path.normalize(__dirname + "/winston-test.log"), "utf-8");
for (var index in logArray) {
bVowFulfilled = logText.indexOf(strPrefix1 + logArray[index]) > -1;
if (!bVowFulfilled) {
console.log('1st Vow - log does not contain "' + strPrefix1 + logArray[index] + '"');
}
assert.isTrue(bVowFulfilled);
}
assert.isTrue(logText.indexOf(msg) > -1 );
}
},
'should log all messages' : {
topic : function() {
var fnCallback = function(err, level, msg, meta) {
setTimeout(this.callback, 10000, err, level, msg, meta);
};

for (var index in logArray) {
oLogger.log('error', strPrefix2 + logArray[index]);
}

oLogger.log('error', strPrefix2 + strLogLast, fnCallback.bind(this));
},
'to file': function(err, level, msg, meta) {
assert.equal(msg, strPrefix2 + strLogLast);
var logText = fs.readFileSync(path.normalize(__dirname + "/winston-test.log"), "utf-8");
for (var index in logArray) {
var bVowFulfilled = logText.indexOf(strPrefix2 + logArray[index]) > -1;
if (!bVowFulfilled) {
console.log('2nd Vow - log does not contain "' + strPrefix2 + logArray[index] + '"' );
}
assert.isTrue(bVowFulfilled);
}
assert.isTrue(logText.indexOf(msg) > -1 );
}
},
'should log all messages from sub processes' : {
topic : function() {
var fnCallback = function(err, level, msg, meta) {
setTimeout(this.callback, 10000, err, level, msg, meta);
};

for (var index in logArray) {
//do not fork over max
if (index > (nForkMax -1)) {
break;
}
//console.log('WinstonSuite - forking ' + index);
var argsArray = new Array();
argsArray.push(strPrefix3 + logArray[index]);
var oControllerProcess = oChildProcess.fork(__dirname + "/LogSub.js", argsArray);
}

oLogger.log('error', strPrefix3 + strLogLast, fnCallback.bind(this));
},
'to file': function(err, level, msg, meta) {
assert.equal(msg, strPrefix3 + strLogLast);
var logText = fs.readFileSync(path.normalize(__dirname + "/winston-test.log"), "utf-8");
for (var index in logArray) {
if (index > (nForkMax -1)) {
break;
}
var bVowFulfilled = logText.indexOf(strPrefix3 + logArray[index]) > -1;
if (!bVowFulfilled) {
console.log('3rd Vow - log does not contain "' + strPrefix3 + logArray[index] + '"');
}
assert.isTrue(bVowFulfilled);
}
assert.isTrue(logText.indexOf(msg) > -1 );
}
}
}).export(module);
```

## LogSub.js
```javascript
var winston = require('winston');

var oLogger = new winston.Logger();
var oTestTransportOptions = {
filename : 'winston-test.log',
dirname : __dirname,
/*maxsize : 100000,*/
handleExceptions : true,
level : 'silly',
timestamp : true,
json : false
};
var oTransport = new winston.transports.File(oTestTransportOptions);
oTransport.name = "test-file-transport";
oLogger.add(oTransport, oTestTransportOptions, true);

var strArg2 = process.argv[2];
if (strArg2 != null && strArg2 != undefined) {
oLogger.log("debug", strArg2);
} else {
oLogger.log("debug", "Arg not provided");
}
```