diff --git a/docs/transports.md b/docs/transports.md index c5dc8eafd..3ad2466d1 100644 --- a/docs/transports.md +++ b/docs/transports.md @@ -102,6 +102,7 @@ looking for daily log rotation see [DailyRotateFile](#dailyrotatefile-transport) * __level:__ Level of messages that this transport should log (default: level set on parent logger). * __silent:__ Boolean flag indicating whether to suppress output (default false). * __eol:__ Line-ending character to use. (default: `os.EOL`). +* __lazy:__ If true, log files will be created on demand, not at the initialization time. * __filename:__ The filename of the logfile to write output to. * __maxsize:__ Max size in bytes of the logfile, if the size is exceeded then a new file is created, a counter will become a suffix of the log file. * __maxFiles:__ Limit the number of files created when the size of the logfile is exceeded. diff --git a/lib/winston/transports/file.js b/lib/winston/transports/file.js index 49edd8b13..b5801038b 100644 --- a/lib/winston/transports/file.js +++ b/lib/winston/transports/file.js @@ -79,6 +79,7 @@ module.exports = class File extends TransportStream { this.maxFiles = options.maxFiles || null; this.eol = (typeof options.eol === 'string') ? options.eol : os.EOL; this.tailable = options.tailable || false; + this.lazy = options.lazy || false; // Internal state variables representing the number of files this instance // has created and the current size (in bytes) of the current logfile. @@ -88,9 +89,10 @@ module.exports = class File extends TransportStream { this._drain = false; this._opening = false; this._ending = false; + this._fileExist = false; if (this.dirname) this._createLogDirIfNotExist(this.dirname); - this.open(); + if (!this.lazy) this.open(); } finishIfEnding() { @@ -107,14 +109,13 @@ module.exports = class File extends TransportStream { } } - /** * Core logging method exposed to Winston. Metadata is optional. * @param {Object} info - TODO: add param description. * @param {Function} callback - TODO: add param description. * @returns {undefined} */ - log(info, callback = () => {}) { + log(info, callback = () => { }) { // Remark: (jcrugzz) What is necessary about this callback(null, true) now // when thinking about 3.x? Should silent be handled in the base // TransportStream _write method? @@ -123,6 +124,7 @@ module.exports = class File extends TransportStream { return true; } + // Output stream buffer is full and has asked us to wait for the drain event if (this._drain) { this._stream.once('drain', () => { @@ -138,6 +140,32 @@ module.exports = class File extends TransportStream { }); return; } + if (this.lazy) { + if (!this._fileExist) { + if (!this._opening) { + this.open(); + } + this.once('open', () => { + this._fileExist = true; + this.log(info, callback); + return; + }); + return; + } + if (this._needsNewFile(this._pendingSize)) { + this._dest.once('close', () => { + if (!this._opening) { + this.open(); + } + this.once('open', () => { + this.log(info, callback); + return; + }); + return; + }); + return; + } + } // Grab the raw string and append the expected EOL. const output = `${info[MESSAGE]}${this.eol}`; @@ -169,6 +197,10 @@ module.exports = class File extends TransportStream { if (!this._needsNewFile()) { return; } + if (this.lazy) { + this._endStream(() => {this.emit('fileclosed')}); + return; + } // End the current stream, ensure it flushes and create a new one. // This could potentially be optimized to not run a stat call but its @@ -508,7 +540,6 @@ module.exports = class File extends TransportStream { _cleanupStream(stream) { stream.removeListener('error', this._onError); stream.destroy(); - return stream; } @@ -526,7 +557,7 @@ module.exports = class File extends TransportStream { * @param {function} callback - Callback for when the current file has closed. * @private */ - _endStream(callback = () => {}) { + _endStream(callback = () => { }) { if (this._dest) { this._stream.unpipe(this._dest); this._dest.end(() => { @@ -542,7 +573,7 @@ module.exports = class File extends TransportStream { * Returns the WritableStream for the active file on this instance. If we * should gzip the file then a zlib stream is returned. * - * @param {ReadableStream} source – PassThrough to pipe to the file when open. + * @param {ReadableStream} source –PassThrough to pipe to the file when open. * @returns {WritableStream} Stream that writes to disk for the active file. */ _createStream(source) { diff --git a/test/unit/winston/transports/00-file-stress.test.js b/test/unit/winston/transports/00-file-stress.test.js index 55cae623d..46fe59768 100644 --- a/test/unit/winston/transports/00-file-stress.test.js +++ b/test/unit/winston/transports/00-file-stress.test.js @@ -150,4 +150,47 @@ describe('File (stress)', function () { }); }, 10000); }); + + it('should handle a high volume of writes with lazy option enabled', function (done) { + const logger = winston.createLogger({ + transports: [ + new winston.transports.File({ + filename: fileStressLogFile, + lazy: true + }) + ] + }); + + const counters = { + write: 0, + read: 0 + }; + + const interval = setInterval(function () { + logger.info(++counters.write); + }, 0); + + setTimeout(function () { + clearInterval(interval); + + helpers + .tryRead(fileStressLogFile) + .on('error', function (err) { + assume(err).false(); + logger.close(); + done(); + }) + .pipe(split()) + .on('data', function (d) { + const json = JSON.parse(d); + assume(json.level).equal('info'); + assume(json.message).equal(++counters.read); + }) + .on('end', function () { + assume(counters.write).equal(counters.read); + logger.close(); + done(); + }); + }, 10000); + }); }); diff --git a/test/unit/winston/transports/01-file-maxsize.test.js b/test/unit/winston/transports/01-file-maxsize.test.js index 01ca88076..8f2db41ec 100644 --- a/test/unit/winston/transports/01-file-maxsize.test.js +++ b/test/unit/winston/transports/01-file-maxsize.test.js @@ -25,8 +25,8 @@ describe('File (maxsize)', function () { this.timeout(10000); let testDone = false; - before(removeFixtures); - after(done => { + this.beforeEach(removeFixtures); + this.afterEach(done => { testDone = true; removeFixtures(done); }); @@ -119,4 +119,94 @@ describe('File (maxsize)', function () { setImmediate(() => logKbytes(4)); }); }); + + describe('With lazy option enabled', () => { + it('should not create extra file', function (done) { + const fillWith = ['a', 'b', 'c', 'd', 'e']; + const lazyTransport = new winston.transports.File({ + format: winston.format.printf(info => info.message), + filename: path.join(testLogFixturesPath, 'testmaxsize.log'), + maxsize: 3072, + lazy: true + }); + const logger = winston.createLogger({ + transports: [lazyTransport] + }); + // + // Setup a list of files which we will later stat. + // + const files = []; + + // + // Assets the no of files and all the files have been created with the + // correct filesize + // + function assumeFilesCreated() { + assume(files.length).equals(fillWith.length); + files.map(function (file, i) { + let stats; + try { + stats = fs.statSync(file); + } catch (ex) { + assume(stats).is.an( + 'object', + `${file} failed to open: ${ex.message}` + ); + } + + const text = fs.readFileSync(file, 'utf8'); + assume(text[0]).equals(fillWith[i]); + // Either 4096 on Unix or 4100 on Windows + // because of the eol. + if (process.platform === 'win32') { + assume(stats.size).equals(3075); + } else { + assume(stats.size).equals(3072); + } + }); + done(); + } + + // + // Log the specified kbytes to the transport + // + function logKbytes(kbytes) { + // + // Shift the next fill char off the array then push it back + // to rotate the chars. + // + const filler = fillWith.shift(); + fillWith.push(filler); + + // + // + // To not make each file not fail the assertion of the filesize we can + // make the array 1023 characters long. + // + const kbStr = Array(1023).fill(filler).join(''); + for (var i = 0; i < kbytes; i++) { + logger.log({ level: 'info', message: kbStr }); + } + } + + // Initial Log + let count =1; + logKbytes(3); + + // Listen to file close event called when the file is closed + lazyTransport.on('fileclosed', ()=>{ + if (count === fillWith.length) { + assumeFilesCreated(); + return; + } + count += 1; + setImmediate(()=>{logKbytes(3);}); + }) + + //Listent to file open event called when the file is opened + lazyTransport.on('open', file => { + files.push(file); + }); + }); + }); }); diff --git a/test/unit/winston/transports/file-lazy.test.js b/test/unit/winston/transports/file-lazy.test.js new file mode 100644 index 000000000..d5516b865 --- /dev/null +++ b/test/unit/winston/transports/file-lazy.test.js @@ -0,0 +1,61 @@ +'use strict'; + +const path = require('path'); +const winston = require('../../../../lib/winston'); +const helpers = require('../../../helpers'); +const fs = require('fs'); +const { MESSAGE } = require('triple-beam'); +const split = require('split2'); +const assume = require('assume'); + +function noop() {} + +describe('Lazy Option Test', function () { + this.timeout(10 * 1000); + var logPath = path.join( + __dirname, + '..', + '..', + '..', + 'fixtures', + 'file', + 'lazy.log' + ); + + beforeEach(function () { + try { + fs.unlinkSync(logPath); + } catch (ex) { + if (ex && ex.code !== 'ENOENT') { + return done(ex); + } + } + }); + + it('should not create a log file before receiving any logs', function (done) { + var transport = new winston.transports.File({ + filename: logPath, + lazy: true + }); + + setTimeout(function () { + assume(fs.existsSync(logPath)).false(); + done(); + }, 0); + }); + it('should create a log file after receiving log', function (done) { + var transport = new winston.transports.File({ + filename: logPath, + lazy: true + }); + + var info = { [MESSAGE]: 'this is my log message' }; + + transport.log(info, noop); + + setTimeout(function () { + assume(fs.existsSync(logPath)); + done(); + }, 0); + }); +}); diff --git a/test/unit/winston/transports/file-rotationFormat.test.js b/test/unit/winston/transports/file-rotationFormat.test.js new file mode 100644 index 000000000..0626cdc7b --- /dev/null +++ b/test/unit/winston/transports/file-rotationFormat.test.js @@ -0,0 +1,136 @@ +'use strict'; + +const path = require('path'); +const winston = require('../../../../lib/winston'); +const helpers = require('../../../helpers'); +const fs = require('fs'); +const { MESSAGE } = require('triple-beam'); +const split = require('split2'); +const assume = require('assume'); +const rimraf = require('rimraf'); +const testFileFixturesPath = path.join( + __dirname, + '..', + '..', + '..', + 'fixtures', + 'file' +); + +// +// Remove all log fixtures +// +function removeFixtures(done) { + rimraf(path.join(testFileFixturesPath, 'rotation*'), done); +} + +// Validate Filename according to rotation +function isCorrectFormat(filename) { + let time = filename.split('rotation')[1].split('.')[0]; + return new Date(time).getTime() > 0; +} + +describe('winston/transports/file/rotationFormat', function () { + this.timeout(10000); + + let testDone = false; + before(removeFixtures); + after(done => { + testDone = true; + removeFixtures(done); + }); + + it('should create multiple files correctly with rotation Function', function (done) { + const fillWith = ['a', 'b', 'c', 'd', 'e']; + const rotationTransport = new winston.transports.File({ + level: 'info', + format: winston.format.printf(info => info.message), + filename: path.join(testFileFixturesPath, 'rotation.log'), + maxsize: 4096, + rotationFormat: () => { + return new Date().getTime(); + } + }); + + // + // Have to wait for `fs.stats` to be done in `rotationTransport.open()`. + // Otherwise the rotationTransport._dest is undefined. See https://github.com/winstonjs/winston/issues/1174 + // + + // + // Setup a list of files which we will later stat. + // + const files = []; + + // + // Assets all the files have been created with the + // correct filesize + // + function assumeFilesCreated() { + files.map(function (file, i) { + let stats; + try { + stats = fs.statSync(file); + } catch (ex) { + assume(stats).is.an( + 'object', + `${file} failed to open: ${ex.message}` + ); + } + + const text = fs.readFileSync(file, 'utf8'); + assume(text[0]).equals(fillWith[i]); + assume(isCorrectFormat(file)); + // Either 4096 on Unix or 4100 on Windows + // because of the eol. + if (process.platform === 'win32') { + assume(stats.size).equals(4100); + } else { + assume(stats.size).equals(4096); + } + }); + + done(); + } + + // + // Log the specified kbytes to the transport + // + function logKbytes(kbytes) { + // + // Shift the next fill char off the array then push it back + // to rotate the chars. + // + const filler = fillWith.shift(); + fillWith.push(filler); + + // + // + // To not make each file not fail the assertion of the filesize we can + // make the array 1023 characters long. + // + const kbStr = Array(1023).fill(filler).join(''); + + // + // With printf format that displays the message only + // winston adds exactly 0 characters. + // + for (var i = 0; i < kbytes; i++) { + rotationTransport.log({ level: 'info', [MESSAGE]: kbStr }); + } + } + + rotationTransport.on('open', function (file) { + + if (testDone) return; // ignore future notifications + const match = file.match(/(\d+)\.log$/); + const count = match ? match[1] : 0; + if (files.length === 5) { + return assumeFilesCreated(); + } + + files.push(file); + setImmediate(() => logKbytes(4)); + }); + }); +});