Logs fail when multiple processes or timers log to same file #80

fquatro · 2011-12-29T17:04:53Z

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. WinstonSuite.js and LogSub.js must reside in the same directory. The three parent vows contexts are executed in parallel. This is intentional. 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:86
✗ Broken » 2 honored ∙ 1 broken (15.114s)

System Information

Mac OS X 10.6.8

$ node --version
v0.5.4

$ npm list
├── [email protected]
├─┬ [email protected]
│ └── [email protected]
├─┬ [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├─┬ [email protected]
│ │ ├── [email protected]
│ │ └── [email protected]
│ ├── [email protected]
│ └── [email protected]
└─┬ [email protected]
├── [email protected]
└── [email protected]

WinstonSuite.js

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 strPrefix4 = 'WinstonSuite 4th 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 );
        }
    },
    'should log all delayed 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(strPrefix4 + logArray[index]);
                argsArray.push('timeout');
                var oControllerProcess = oChildProcess.fork(__dirname + "/LogSub.js", argsArray);
            }

            oLogger.log('error', strPrefix4 + strLogLast, fnCallback.bind(this));
        },
        'to file': function(err, level, msg, meta) {
            assert.equal(msg, strPrefix4 + 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(strPrefix4 + logArray[index]) > -1;
                if (!bVowFulfilled) {
                    console.log('4th Vow - log does not contain "' + strPrefix4 + logArray[index] + '"');
                }
                assert.isTrue(bVowFulfilled);
            }
            assert.isTrue(logText.indexOf(msg) > -1 );
        }
    }
}).export(module);

LogSub.js

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 fnLog = function (p_strMsg) {
    try {
        oLogger.log("debug", p_strMsg);
    } catch (ex) {
        oLogger.log("error", __filename + ' - exception: ' + ex);
    }
};

var strArg2 = process.argv[2];
var strArg3 = process.argv[3];
if (strArg2 != null && strArg2 != undefined) {
    if (strArg3 != null && strArg3 != undefined && strArg3 === 'timeout') {
        var nRandomInteger = Math.floor(Math.random() * 150);
        setTimeout(fnLog, nRandomInteger, strArg2);
    } else {
        oLogger.log("debug", strArg2);
    }
} else {
    oLogger.log("debug", "Arg not provided");
}

indexzero · 2012-01-11T22:57:11Z

Give me a couple days to dig into this. Thanks

fquatro · 2012-04-17T19:32:23Z

Any update on this?

coderarity · 2012-04-28T21:25:25Z

That's... a lot. This was probably gist-worthy.

Marak · 2012-05-04T03:29:50Z

Your node version is from an unstable ( and very old ) branch.

You should be running at least node 0.6.12, and not the 0.7.x branch, which is unstable.

Marak · 2012-05-04T03:30:10Z

( please update your node and try to reconfirm issue )

fquatro · 2012-05-04T17:08:46Z

Same Unit test failure. I used node 0.6.15

fquatro · 2012-05-04T17:16:35Z

I just updated from winston 0.5.9 to 0.5.11 and re-ran the tests and the outcome was failure of the same test.

So all of the following fail on the same test:
node 0.5.4 winston 0.5.9
node 0.6.15 winston 0.5.9 or 0.5.11

indexzero · 2012-05-11T08:19:03Z

@fquatro I'll put this simply: can you make the repro smaller? It's a bit much to parse; kind of like looking for a bug on a needle in a haystack

srlowe · 2013-03-13T12:42:21Z

Not sure if this is related really, but what approach should we take when multiple processes are logging to the same transport type/destination? At the moment the problem I'm seeing is near simultaneous log events are writing on top of each other, and so become unreadable.

2fours · 2013-04-15T17:04:14Z

I'm using node 0.8.22 with winston 0.6.2. I'm using cluster and each of my node processes is writing to the same file transport. I set the file transport up with a maxsize of 1024576. Currently the server is writing to 2 log files at the same time (8 and 9), and all of the log files are above the size I specified:

-rw-r--r-- 1 adam users 1382735 Apr 8 15:35 server1.log
-rw-r--r-- 1 adam users 6073892 Apr 12 06:32 server2.log
-rw-r--r-- 1 adam users 1024662 Apr 9 11:47 server3.log
-rw-r--r-- 1 adam users 1390927 Apr 10 11:08 server4.log
-rw-r--r-- 1 adam users 1612898 Apr 10 18:42 server5.log
-rw-r--r-- 1 adam users 1903466 Apr 11 08:41 server6.log
-rw-r--r-- 1 adam users 1082249 Apr 11 19:48 server7.log
-rw-r--r-- 1 adam users 3467911 Apr 15 10:57 server8.log
-rw-r--r-- 1 adam users 1200339 Apr 15 10:57 server9.log
-rw-r--r-- 1 adam users 1851996 Apr 7 15:56 server.log

chjj · 2013-04-15T19:32:54Z

@2fours, it looks like winston never behaved the way you're expecting. maxsize is only checked when the log file is first opened. I'll look into changing this now.

2fours · 2013-05-09T02:14:24Z

Any progress on this? This is how my logs folder looks today:

[adam@server logs]$ ls -ltr
total 22072
-rw-r--r-- 1 adam users 1588214 Apr 16 17:26 server.log
-rw-r--r-- 1 adam users 1445676 Apr 20 12:51 server1.log
-rw-r--r-- 1 adam users 1216359 Apr 20 12:51 server2.log
-rw-r--r-- 1 adam users 1681744 Apr 24 13:27 server3.log
-rw-r--r-- 1 adam users 1155010 Apr 28 10:10 server4.log
-rw-r--r-- 1 adam users 1033874 May 2 10:48 server5.log
-rw-r--r-- 1 adam users 1069303 May 4 18:17 server6.log
-rw-r--r-- 1 adam users 2309658 May 6 10:20 server7.log
-rw-r--r-- 1 adam users 3326666 May 7 07:57 server8.log
-rw-r--r-- 1 adam users 1217806 May 7 09:38 server9.log
-rw-r--r-- 1 adam users 2262395 May 8 06:42 server10.log
-rw-r--r-- 1 adam users 1031696 May 8 08:15 server11.log
-rw-r--r-- 1 adam users 521363 May 8 20:11 server13.log
-rw-r--r-- 1 adam users 2646325 May 8 20:11 server12.log

currently it's writing to server12 and server13 simultaneously.

gfzabarino · 2015-04-27T03:25:49Z

+1 on a fix for this.

HansHammel · 2016-02-21T13:34:00Z

@2fours to support file logging correctly, winston would have to use the cluster module and pass all data to the master where it can safely be written to a single file. Unfortunately Winston doesn't care about Cluster/ concurrency. so, there are multiple Options to do it right. One way is to switch to a "real" log-server architecture. Maybe winstond, which I never tried, can help you here. The other Option is to use IPC or Transport that solves the issues by nature e.g. logging to a database or using a message broker. Here is a proof of concept (without winston): https://gist.github.com/HansHammel/19c2457fa8bb4c1cff2f

indexzero · 2016-02-21T13:35:34Z

@HansHammel you have nailed it. winston-godot is also an option. That's what we did at Nodejitsu for log aggregation.

2fours mentioned this issue Jun 9, 2013

Log files being deleted from filesystem on rotate #267

Closed

indexzero removed the medium-priority label Sep 30, 2014

indexzero mentioned this issue Oct 7, 2014

file transport's maxsize/maxFiles is broken when running as a cluster #275

Closed

indexzero removed the Needs Investigation label Feb 21, 2016

indexzero closed this as completed Feb 21, 2016

winstonjs locked and limited conversation to collaborators Feb 21, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Logs fail when multiple processes or timers log to same file #80

Logs fail when multiple processes or timers log to same file #80

fquatro commented Dec 29, 2011

indexzero commented Jan 11, 2012

fquatro commented Apr 17, 2012

coderarity commented Apr 28, 2012

Marak commented May 4, 2012

Marak commented May 4, 2012

fquatro commented May 4, 2012

fquatro commented May 4, 2012

indexzero commented May 11, 2012

srlowe commented Mar 13, 2013

2fours commented Apr 15, 2013

chjj commented Apr 15, 2013

2fours commented May 9, 2013

gfzabarino commented Apr 27, 2015

HansHammel commented Feb 21, 2016

indexzero commented Feb 21, 2016

Logs fail when multiple processes or timers log to same file #80

Logs fail when multiple processes or timers log to same file #80

Comments

fquatro commented Dec 29, 2011

System Information

WinstonSuite.js

LogSub.js

indexzero commented Jan 11, 2012

fquatro commented Apr 17, 2012

coderarity commented Apr 28, 2012

Marak commented May 4, 2012

Marak commented May 4, 2012

fquatro commented May 4, 2012

fquatro commented May 4, 2012

indexzero commented May 11, 2012

srlowe commented Mar 13, 2013

2fours commented Apr 15, 2013

chjj commented Apr 15, 2013

2fours commented May 9, 2013

gfzabarino commented Apr 27, 2015

HansHammel commented Feb 21, 2016

indexzero commented Feb 21, 2016