[Bug]: Incompatiblity with mock-fs

[tomfrenken]

🔎 Search Terms

mocking, mock-fs, async

The problem

When I mock away my file system, the read operation seems to happen before Winston starts writing the log.

With the latest version of mock-fs, they've changed on which event loop they operate, they switched from process.nextTick() to setImmediate(), which, as far as I understand the issue, should be fine.

The reason I think this might be a winston issue, and not a mock-fs issue, is because I tried replicating the issue I am facing with many fs-based functions, which all seem to work the intended way, unlike winston.

Here is a minimal example of what I've tried with fs vs what I am trying to get working with Winston.

Mocking and directly using fs functions:

it('tests mock-fs in isolation', async () => {
      const rootNodeModules = path.resolve(
        __dirname,
        '../../../../node_modules'
      );
      mock({
        'test.log': 'content',
        [rootNodeModules]: mock.load(rootNodeModules)
      });
      await fs.promises.writeFile('test.log', 'new-content');
      const content = await fs.promises.readFile('test.log', {
        encoding: 'utf-8'
      });
      expect(content).toEqual('new-content');

      fs.writeFileSync('test.log', 'new-content-2');
      const syncContent = await fs.promises.readFile('test.log', {
        encoding: 'utf-8'
      });
      expect(syncContent).toEqual('new-content-2');

      fs.createWriteStream('test.log').write('new-content-3');
      const streamContent = await fs.promises.readFile('test.log', {
        encoding: 'utf-8'
      });
      expect(streamContent).toEqual('new-content-3');

      // Streaming (this is how winston is doing it?)
      const writeStream = fs.createWriteStream('test.log');
      writeStream.on('open', () => {
        // Write data to the file
        writeStream.write('WriteStream Content');

        // Close the stream
        writeStream.end();
      });
      
      const writeStreamContent = await fs.promises.readFile('test.log', {
        encoding: 'utf-8'
      });
      
      expect(writeStreamContent).toEqual('WriteStream Content');
      mock.restore();

Now here is the Winston example, where I set the file transport and all, but somehow when I read the file, it still contains the old, mocked content, instead of the intended new, overwritten content:

      const rootNodeModules = path.resolve(
     __dirname,
     '../../../../node_modules'
   );
   mock({
     'test.log': 'content',
     [rootNodeModules]: mock.load(rootNodeModules)
   });
   const logger = createLogger() // pseudo code
   const fileTransport = new transports.File({
     filename: 'test.log',
     level: 'info'
   });
   logger.add(fileTransport)
   
   logger.error(
     'logs error only in test.log because the level is less than info'
   );
   const log = await fs.promises.readFile('test.log', { encoding: 'utf-8' });
   expect(log).toMatch(
     /logs error only in test.log because the level is less than info/
   ); // <----  here `log` still contains `content` instead of the new value.

What version of Winston presents the issue?

^3.15.0

What version of Node are you using?

v20.13.1

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

No response

Minimum Working Example

No response

Additional information

No response

[Arc8ne]

Hi, I am willing to try to investigate and fix this bug, is it alright if this issue could be assigned to me?

[Arc8ne]

Hi @tomfrenken, while investigating this issue, I noticed that making the following change to the Winston example (code snippet) that you provided would result in the error log message being successfully written to the test.log file:

const fileTransport = new transports.File(
    {
        // Original
        // filename: 'test.log',
        // New change
        stream: fs.createWriteStream(
            "test.log",
            {
                encoding: "utf-8"
            }
        ),
        level: "info"
    }
);

Until this issue is resolved, perhaps you could consider using the above workaround?

[Arc8ne]

It seems that this issue is caused by an underlying bug in the mock-fs module that was not reported previously.

As a result, I have submitted an issue report for the said bug in the mock-fs module which can be found here: tschaub/mock-fs#411

I have also identified an alternative way to resolve this issue via changes to winston's code which could be used to work around the said bug in the mock-fs module until it is patched, however, I am not sure if doing so might break anything. Hence, I am ideally hoping that the said bug in the mock-fs module can be fixed.