[Bug]: Null bytes in log files

[nullromo]

🔎 Search Terms

null bytes character characters

The problem

After my code shuts down un-gracefully and then restarts, I end up with a long string of null bytes in my log file.

The photo below shows what the file looks like. I can't really display the null bytes properly, so I thought a screenshot would show it better.

In the picture, the "Created winston logger" message should be the first one after the restart, and the "DONE WITH /backend/system/logs" message is the last one before the shutdown.

What version of Winston presents the issue?

3.7.2

What version of Node are you using?

18.7.0

If this worked in a previous version of Winston, which was it?

No response

Minimum Working Example

This is hard to reproduce because I only get the problem when I load my code onto a Linux machine and pull the power from the machine while the code is running. It's on an embedded/portable device, so this is not an uncommon situation in practice, but it's a bit hard to test without my hardware.

Additional information

I came up with a workaround that I am using for now, but it's not that great. I have to strip out the null characters when the query function fails.

[wbt]

SIGKILL or something might be a kinder way of testing. I wonder if this has something to do with the way a buffer is flushed?

[nullromo]

Actually now that I think about it more, I wouldn't mind having the null bytes in the file if Winston could handle them correctly. And beyond that, I wouldn't mind this as much if the error were reported correctly. What happens now is that when there are null bytes in a log file, the query function callback can be called with no error but with an Error object as the result.

Here is a minimal example:

import path from 'path';
import winston from 'winston';
import type { QueryOptions } from 'winston';
import DailyRotateFile from 'winston-daily-rotate-file';
import type { DailyRotateFileTransportOptions } from 'winston-daily-rotate-file';

const TIMESTAMP_FORMAT = 'YYYY-MM-DD-HH:mm:ss';
const DATA_DIRECTORY = './data';

const fileTransportOptions: DailyRotateFileTransportOptions = {
    dirname: path.resolve(DATA_DIRECTORY, 'logs'),
    extension: '.log',
    filename: 'server-%DATE%',
    format: winston.format.combine(
        winston.format.timestamp({
            format: TIMESTAMP_FORMAT,
        }),
        winston.format.uncolorize(),
        winston.format.json(),
        winston.format.printf((info) => {
            info.message = (info.message as string).trim();
            return JSON.stringify(info);
        }),
    ),
    json: true,
    maxFiles: '30d',
    watchLog: true,
};

const fileTransport = new DailyRotateFile(fileTransportOptions);

fileTransport.on('new', (newFilename) => {
    logger.info(`Created/picked up log file ${newFilename}`);
});

const logger = winston.createLogger({ transports: [fileTransport] });

const today = new Date();
const options: QueryOptions = {
    fields: ['message', 'timestamp', 'level'],
    order: 'desc',
    until: today,
};
logger.query(options, (error, results) => {
    if (error) {
        console.log(error);
        return;
    } else {
        console.log('no error');
    }

    console.log(results);
});

Run the code and a log file will appear. Run it again and the log file will get appended to. Each time, the results should print out and show a JSON object. Then manually insert a null character into the beginning of one of the lines. Then run the code again. This time, an object like { dailyRotateFile: Error } will print out, but it will still say no error as well.

This should not happen. I think there is room for a quick improvement here related to the reporting of the error, which doesn't fix the underlying problem but it certainly helps.

[maverick1872]

@nullromo Thanks for this report along with the MWE. Currently I don't have capacity as I'm dedicating it to fixing the regressions introduced in v3.7.1 & v3.7.2 as denoted in #2029.

In the meantime I would greatly appreciate if you could retest this with v3.8.x & report your findings.

[nullromo]

Thanks for the reply. The error persists in Winston 3.8.2 unfortunately.

I dug into the code a little and found line 470 of logger.js

result = err || result;

This seems to be partly the source of the problem. The DailyRotateFile transport is calling its callback with (err: Error, result: undefined), which makes sense (see here for reference). Then it gets to this line 470 and just assigns result = err, which allows the result to be an instance of Error. This is added onto the results array. Then next() gets called on line 476, which is defined on line 488. This function is explicitly discarding the error by calling the callback with null as the first argument. Then we're left in the problematic situation where error is nullish and result is an instance of Error, same as I mentioned before.

The following changes seem to work for me:

    // Helper function to accumulate the results from `queryTransport` into
    // the `results`.
    function addResults(transport, next) {
      queryTransport(transport, (err, result) => {
        // queryTransport could potentially invoke the callback multiple times
        // since Transport code can be unpredictable.
        if (next) {
          result = err || result;
          if (result) {
            results[transport.name] = result;
          }

          // eslint-disable-next-line callback-return
-         next();
+         next(err);
        }

        next = null;
      });
    }

    // Iterate over the transports in parallel setting the appropriate key in
    // the `results`.
    asyncForEach(
      this.transports.filter(transport => !!transport.query),
      addResults,
-     () => callback(null, results)
+     (err) => callback(err, results)
    );

However, I have not done extensive testing on this.

[nullromo]

I created a merge request (#2285) for this change.

[maverick1872]

I created a merge request (#2285) for this change.

Ohh this is awesome! Got Friday off of work so if I don't get a chance to look earlier it's on my todo list for then!

[nullromo]

Hi, just a friendly reminder if you get a chance, please take a look at the PR.