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?

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.

@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.

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.

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

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!

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