Added Lazy option to file transport (#2317)

* Test for file Transport option rotationFormat

* Test for file Transport option rotationFormat

* Added Lazy option in file transport

* Lint and test

* removed only statement

* Update test/unit/winston/transports/01-file-maxsize.test.js

Co-authored-by: David Hyde <[email protected]>

* Update test/unit/winston/transports/01-file-maxsize.test.js

Co-authored-by: David Hyde <[email protected]>

---------

Co-authored-by: myAlapi <[email protected]>
Co-authored-by: David Hyde <[email protected]>

Author: 3 people

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.

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) {

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);
+  });
 });

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);
+      });
+    });
+  });
 });

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);
+  });
+});