From b5346475909d52d13c86799498d6623607d542f6 Mon Sep 17 00:00:00 2001 From: compulim Date: Thu, 11 Sep 2014 12:07:31 +0800 Subject: [PATCH 1/4] "flush" event should always fire after "flush" call --- lib/winston/transports/file.js | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/lib/winston/transports/file.js b/lib/winston/transports/file.js index 96a38ca9f..47bbee56f 100644 --- a/lib/winston/transports/file.js +++ b/lib/winston/transports/file.js @@ -365,6 +365,13 @@ File.prototype.close = function () { File.prototype.flush = function () { var self = this; + // If nothing to flush, there will be no "flush" event from native stream + // Thus, the "open" event will never be fired (see _createStream.createAndFlush function) + // That means, self.opening will never set to false and no logs will be written to disk + if (!this._buffer.length) { + return self.emit('flush'); + } + // // Iterate over the `_buffer` of enqueued messaged // and then write them to the newly created stream. From 0c28041f6d62d515f5cda870c5ac450ff4a9fba1 Mon Sep 17 00:00:00 2001 From: compulim Date: Thu, 11 Sep 2014 12:15:04 +0800 Subject: [PATCH 2/4] Flush buffer again after first "flush" event --- lib/winston/transports/file.js | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/lib/winston/transports/file.js b/lib/winston/transports/file.js index 47bbee56f..6797580ad 100644 --- a/lib/winston/transports/file.js +++ b/lib/winston/transports/file.js @@ -441,6 +441,11 @@ File.prototype._createStream = function () { // and thus can emit the `open` event. // self.once('flush', function () { + // Because "flush" event is based on native stream "drain" event, + // logs could be written inbetween "self.flush()" and here + // Therefore, we need to flush again to make sure everything is flushed + self.flush(); + self.opening = false; self.emit('open', fullname); }); From 47d885797a2dd0d3cd879305ca813a0bd951c378 Mon Sep 17 00:00:00 2001 From: compulim Date: Fri, 12 Sep 2014 11:57:46 +0800 Subject: [PATCH 3/4] Tests for open/stress fix --- test/transports/file-open-test.js | 61 +++++++++++++++++++++++ test/transports/file-stress-test.js | 76 +++++++++++++++++++++++++++++ 2 files changed, 137 insertions(+) create mode 100644 test/transports/file-open-test.js create mode 100644 test/transports/file-stress-test.js diff --git a/test/transports/file-open-test.js b/test/transports/file-open-test.js new file mode 100644 index 000000000..503b953f4 --- /dev/null +++ b/test/transports/file-open-test.js @@ -0,0 +1,61 @@ +/* + * file-open-test.js: Tests for File transport "open" event + * + * (C) 2014 William Wong + * MIT LICENSE + * + */ + +!function (assert, fs, os, path, vows, winston) { + 'use strict'; + + vows.describe('winston/transports/file').addBatch({ + 'An instance of the File Transport': { + topic: function () { + var callback = this.callback.bind(this), + logPath = path.resolve(process.cwd(), '../fixtures/logs/file-open-test.log'); + + try { + fs.unlinkSync(logPath); + } catch (ex) { + if (ex && ex.code !== 'ENOENT') { return callback(ex); } + } + + var fileTransport = new (winston.transports.File)({ + filename: logPath + }), + logger = new (winston.Logger)({ + transports: [fileTransport] + }), + timeline = {}; + + fileTransport.open(function () { + timeline.open = Date.now(); + + setTimeout(function () { + logger.info('Hello, World!', function () { + timeline.logged = Date.now(); + }); + }, 100); + + setTimeout(function () { + callback(null, timeline); + }, 1000); + }); + }, + 'should fire "open" event': function (results) { + assert.isTrue(!!results.open); + }, + 'should fire "logged" event': function (results) { + assert.isTrue(!!results.logged); + } + } + }).export(module); +}( + require('assert'), + require('fs'), + require('os'), + require('path'), + require('vows'), + require('../../lib/winston') +); \ No newline at end of file diff --git a/test/transports/file-stress-test.js b/test/transports/file-stress-test.js new file mode 100644 index 000000000..bec307b6c --- /dev/null +++ b/test/transports/file-stress-test.js @@ -0,0 +1,76 @@ +/* + * file-stress-test.js: Tests for stressing File transport + * + * (C) 2014 William Wong + * MIT LICENSE + * + */ + +!function (assert, fs, os, path, vows, winston) { + 'use strict'; + + vows.describe('winston/transports/file').addBatch({ + 'A stressed instance of the File Transport': { + topic: function () { + var callback = this.callback.bind(this), + logPath = path.resolve(process.cwd(), '../fixtures/logs/file-stress-test.log'); + + try { + fs.unlinkSync(logPath); + } catch (ex) { + if (ex && ex.code !== 'ENOENT') { return callback(ex); } + } + + var fileTransport = new (winston.transports.File)({ + filename: logPath + }), + logger = new (winston.Logger)({ + transports: [fileTransport] + }); + + fileTransport.on('open', function () { + setTimeout(function () { + clearInterval(interval); + + logger.query({ order: 'asc' }, function (err, results) { + callback(null, results); + }); + }, 100); + }); + + var logIndex = 0, + interval = setInterval(function () { + logger.info(++logIndex); + stress(200); + }, 0); + + logger.info(++logIndex); + stress(200); + + function stress(duration) { + var startTime = Date.now(); + + while (Date.now() - startTime < duration) { + Math.sqrt(Math.PI); + } + } + }, + 'should not skip any log lines': function (results) { + var testIndex = 0; + + results.file.forEach(function (log) { + if (+log.message !== ++testIndex) { + throw new Error('Number skipped'); + } + }); + } + } + }).export(module); +}( + require('assert'), + require('fs'), + require('os'), + require('path'), + require('vows'), + require('../../lib/winston') +); \ No newline at end of file From 9e39150e0018f43d198ca4c160acef2af9860bf4 Mon Sep 17 00:00:00 2001 From: compulim Date: Fri, 12 Sep 2014 14:59:45 +0800 Subject: [PATCH 4/4] Fix test under vows --- test/transports/file-open-test.js | 2 +- test/transports/file-stress-test.js | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/test/transports/file-open-test.js b/test/transports/file-open-test.js index 503b953f4..7fd4ed638 100644 --- a/test/transports/file-open-test.js +++ b/test/transports/file-open-test.js @@ -13,7 +13,7 @@ 'An instance of the File Transport': { topic: function () { var callback = this.callback.bind(this), - logPath = path.resolve(process.cwd(), '../fixtures/logs/file-open-test.log'); + logPath = path.resolve(__dirname, '../fixtures/logs/file-open-test.log'); try { fs.unlinkSync(logPath); diff --git a/test/transports/file-stress-test.js b/test/transports/file-stress-test.js index bec307b6c..519b12c02 100644 --- a/test/transports/file-stress-test.js +++ b/test/transports/file-stress-test.js @@ -13,7 +13,7 @@ 'A stressed instance of the File Transport': { topic: function () { var callback = this.callback.bind(this), - logPath = path.resolve(process.cwd(), '../fixtures/logs/file-stress-test.log'); + logPath = path.resolve(__dirname, '../fixtures/logs/file-stress-test.log'); try { fs.unlinkSync(logPath);