Unable to flush log in a jest test

[jimsnab]

When using simple-node-logger and jest, the output from jest in stderr might land somewhere in the middle of log output. It requires a sufficient number of log messages.

Jest code:

const log = require('simple-node-logger').createSimpleLogger();

describe("jest logging", () => {
  it("logs some messages", async () => {

    for (let i = 0 ; i < 3000 ; i++) {
      log.info(`Message ${i}`);
    }
  });
});

Results in Cannot log after tests are done. Did you forget to wait for something async in your test?

In trying to work around the error above, I ended up with a different undesirable behavior: stdout messages are delayed, and Jest's stderr messages land in the middle of output. (Adjust "jest logging" for loop count depending on the speed of your computer.)

const logStats = {
  startedCount: 0,
  finishedCount: 0
}

const logOptions = {
  writer: text => {
    if (!process.stdout.write(text + '\n')) {
      process.stdout.once('drain', () => {
        logStats.finishedCount++;
      });
    } else {
      logStats.finishedCount++;
    }
  }
}

const log = require('simple-node-logger').createSimpleLogger(logOptions);

log.originalLog = log.log;
log.log = (level, msg) => { logStats.startedCount++; return log.originalLog(level, msg); }

function delay(ms) {
  return new Promise(resolve => {
    setTimeout(resolve, ms);
  });
}

describe("jest logging", () => {
  it("logs some messages", async () => {

    for (let i = 0 ; i < 300 ; i++) {
      log.info(`Message ${i} A started=${logStats.startedCount} finished=${logStats.finishedCount}`);
      log.info(`Message ${i} B started=${logStats.startedCount} finished=${logStats.finishedCount}`);
      await delay(1);
    }
  });
});

Result: (partial output)

...
11:00:57.645 INFO  Message 275 A started=550 finished=550
11:00:57.645 INFO  Message 275 B started=551 finished=550
 PASS  ./log.test.js
  jest logging
    ✓ logs some messages (500 ms)

Test Suites: 1 passed, 1 total
Tests:       1 passed, 1 total
Snapshots:   0 total
Time:        0.868 s, estimated 1 s
Ran all test suites.
11:00:57.649 INFO  Message 276 A started=552 finished=552
11:00:57.649 INFO  Message 276 B started=553 finished=552
11:00:57.651 INFO  Message 277 A started=554 finished=554
...

To solve this, simple-node-logger needs a proper flush() function.

[jimsnab]

I found a workaround. It's essentially

• Count the number of started log messages
• Hook stdout and count the number of write() bytes
• Add a flush() that waits for started log messages to finish, and then waits for stdout to write all the bytes

This code could be improved.

const tty = require('tty');

function hookStdOut() {
  if (process.stdout.isTTY) {
    process.stdout.writeLength = process.stdout.bytesWritten;
    process.stdout.oldWrite = process.stdout.write;
    process.stdout.write = (data, encoding = 'utf8', cb = undefined) => {
      process.stdout.writeLength += Buffer.byteLength(data, encoding);
      return process.stdout.oldWrite(data, encoding, cb);
    }
  }  
}

hookStdOut();

function flushStdOut(callback) {
  if (process.stdout.isTTY) {
    const waiter = function(innerCallback) {
      if (process.stdout.bytesWritten >= process.stdout.writeLength) {
        innerCallback();
      } else {
        setTimeout(waiter, 1, innerCallback);
      }
    }
    waiter(callback);
  } else {
    callback();
  }
}

const logOptions = {
  writer: text => {
    process.stdout.write(`${text}\n`);
    this.finishedCount++;
  }
};

const log = require('simple-node-logger').createSimpleLogger(logOptions);
log.originalLog = log.log;
log.startedCount = 0;
log.finishedCount = 0;
log.log = (level, message) => { log.startedCount++; log.originalLog(level, message); }

// Add a flush() API to the log
log.flush = function () {
  return new Promise(resolve => {
    const waiter = function (logInstance) {
      
      // wait for log writer(s) to write, then flush stdout
      if (process.stdout.bytesWritten < logInstance.bytesLogged) {
        return setTimeout(waiter, 1, logInstance);
      } else {
        flushStdOut(resolve);
      }
    };

    waiter(log);
  });
};

// test function
function delay(ms) {
  return new Promise(resolve => {
    setTimeout(resolve, ms);
  });
}

// test
describe("jest logging", () => {
  it("logs some messages", async () => {
    for (let i = 0; i < 300; i++) {
      log.info(`Message ${i} A started=${log.startedCount} finished=${log.finishedCount}`);
      log.info(`Message ${i} B started=${log.startedCount} finished=${log.finishedCount}`);
      await delay(1);
    }

    await log.flush();
  });
});