Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Added Lazy Option in transport #2317

Merged
merged 7 commits into from
Jul 10, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions docs/transports.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
43 changes: 37 additions & 6 deletions lib/winston/transports/file.js
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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() {
Expand All @@ -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?
Expand All @@ -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', () => {
Expand All @@ -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}`;
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -508,7 +540,6 @@ module.exports = class File extends TransportStream {
_cleanupStream(stream) {
stream.removeListener('error', this._onError);
stream.destroy();

return stream;
}

Expand All @@ -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(() => {
Expand All @@ -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) {
Expand Down
43 changes: 43 additions & 0 deletions test/unit/winston/transports/00-file-stress.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
});
94 changes: 92 additions & 2 deletions test/unit/winston/transports/01-file-maxsize.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
Expand Down Expand Up @@ -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);
});
});
});
});
61 changes: 61 additions & 0 deletions test/unit/winston/transports/file-lazy.test.js
Original file line number Diff line number Diff line change
@@ -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);
});
});
Loading