After restart server, last time's newest log file is not archived and oldest log file is not deleted

[k872892]

Description

After restart node server:

1. The last time's newest log file is not archived.

2. The last time's oldest archived log file is not deleted when exceed maxFiles.

Version

4.5.0

Log settings

var transport = new winston.transports.DailyRotateFile({
    filename: './logs/application-%DATE%.log',
    datePattern: 'YYYY-MM-DD-HH-mm:ss',
    zippedArchive: true,
    maxFiles: 5 ,
    maxSize: '1k'
});

Test steps

1. Use test script to generate 5 log files (one file per second).

node test.js 5

2. Check log files

Pin@ubuntu # ll -t -r logs/
-rw-r--r--    1 root     root            69 Oct 12 18:23 application-2020-10-12-18-23:01.log.gz
-rw-r--r--    1 root     root            69 Oct 12 18:23 application-2020-10-12-18-23:02.log.gz
-rw-r--r--    1 root     root            69 Oct 12 18:23 application-2020-10-12-18-23:03.log.gz
-rw-r--r--    1 root     root            50 Oct 12 18:23 application-2020-10-12-18-23:05.log
-rw-r--r--    1 root     root            69 Oct 12 18:23 application-2020-10-12-18-23:04.log.gz
-rw-r--r--    1 root     root          1039 Oct 12 18:23 .4fdb28c558b05eafd9ee9c1d1660cb8f60f66f53-audit.json

3. Use test script to generate 3 log files (one file per second).

node test.js 3

4 Check log files

Pin@ubuntu # ll -t -r logs/
-rw-r--r--    1 root     root            69 Oct 12 18:23 application-2020-10-12-18-23:01.log.gz
-rw-r--r--    1 root     root            50 Oct 12 18:23 application-2020-10-12-18-23:05.log
-rw-r--r--    1 root     root            20 Oct 12 18:23 application-2020-10-12-18-23:08.log.gz
-rw-r--r--    1 root     root            69 Oct 12 18:23 application-2020-10-12-18-23:09.log.gz
-rw-r--r--    1 root     root            50 Oct 12 18:23 application-2020-10-12-18-23:11.log
-rw-r--r--    1 root     root            69 Oct 12 18:23 application-2020-10-12-18-23:10.log.gz
-rw-r--r--    1 root     root          1039 Oct 12 18:23 .4fdb28c558b05eafd9ee9c1d1660cb8f60f66f53-audit.json

Expected:

1. application-2020-10-12-18-23:05.log should be archived
2. application-2020-10-12-18-23:01.log.gz should be deleted

Test Script

test.js

var winston = require('winston');
require('winston-daily-rotate-file')

var transport = new winston.transports.DailyRotateFile({
    filename: './logs/application-%DATE%.log',
    datePattern: 'YYYY-MM-DD-HH-mm:ss',
    zippedArchive: true,
    maxFiles: 5 ,
    maxSize: '1k'
});

var logger = winston.createLogger({
    transports: [
        transport
    ]
});

function makeid(length) {
   var result           = '';
   var characters       = 'ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789';
   var charactersLength = characters.length;
   for ( var i = 0; i < length; i++ ) {
      result += characters.charAt(Math.floor(Math.random() * charactersLength));
   }
   return result;
}

function waitAndDo(times) {
    if (times < 1) {
        return;
    }

    setTimeout(function() {
        logger.info(makeid(20));

        waitAndDo(times-1);
    }, 1000);
}

waitAndDo(process.argv[2]);

[aaronjameslang]

This bug just bit us hard, do we know if this is still an issue in the latest version?

[wbt]

@aaronjameslang seems likely, but if you have a great test case handy you might be in the best position to test it!

[aaronjameslang]

According to our tests this is still an issue in 4.6.1

Our workaround for now is increased disk space monitoring/alerting and investigating options to log to the network rather than disk

[RopoMen]

If option zippedArchive is set to true then deleting gziped files may get broken.

winston-daily-rotate-file uses file-stream-rotator package to rotate log files and deleting old files (not .gz). Audit file which is used is for file-stream-rotator and it does not understand gzip files it only read files listed in that JSON (which are not .gz).

winston-daily-rotate-file is relaying event logRemoved to remove gz files and if file-stream-rotator is not emiting that event, gz files wont get deleted properly.

[RopoMen]

Perhaps more clarification.

winston-daily-rotate-file provides gzip functionality. When log file is rotated by file-stream-rotator it emits event rotateand then winston-daily-rotate-file gzips rotated old file and then unlinks (deletes) the original log file.

Now file-stream-rotator´s audit file contains log file which is already deleted by winston-daily-rotate-file. When file-stream-rotator looks its audit file and starts to delete old files, those are not found on disk and it wont trigger event logRemoved and therof winston-daily-rotate-file will never delete gzip files.

[RopoMen]

I created PR into file-stream-rotator rogerc/file-stream-rotator#100