Repository: pinojs/pino
Pull request #1140 (2021-09-24 14:08:59)

Remove in-between Transform for file.js
I have been investigating #1138 for dropped logs, and I found _some_ during process shutdown. Specifically, it is due to the  `Transform` stream emitting `close` while the destination was still shutting down.

We would need some better mechanism to signal pino "the whole pipeline has been shutdown".

mcollina: @Eomm check this out. I feel a few of the other transports would suffer from similar problems.
mcollina: The fun part about this is that on my system we start seeing it after _8_ million lines written.

Patch:
diff --git a/.taprc b/.taprc
index 9c10394..fa972ed 100644
--- a/.taprc
+++ b/.taprc
@@ -1,2 +1,3 @@
 coverage: true
 timeout: 480
+check-coverage: false
diff --git a/file.js b/file.js
index 477fbd5..7968c19 100644
--- a/file.js
+++ b/file.js
@@ -1,20 +1,10 @@
 'use strict'
 
-const { Transform, pipeline } = require('stream')
 const pino = require('./pino')
 const { once } = require('events')
 
 module.exports = async function (opts = {}) {
-  const stream = new Transform({
-    objectMode: true,
-    autoDestroy: true,
-    transform (chunk, enc, cb) {
-      cb(null, chunk.toString())
-    }
-  })
-
   const destination = pino.destination({ dest: opts.destination || 1, sync: false })
   await once(destination, 'ready')
-  pipeline(stream, destination, () => {})
-  return stream
+  return destination
 }


Test patch:
diff --git a/test/fixtures/transport-many-lines.js b/test/fixtures/transport-many-lines.js
new file mode 100644
index 0000000..d8bb5e3
--- /dev/null
+++ b/test/fixtures/transport-many-lines.js
@@ -0,0 +1,29 @@
+'use strict'
+
+const pino = require('../..')
+const transport = pino.transport({
+  targets: [{
+    level: 'info',
+    target: 'pino/file',
+    options: {
+      destination: process.argv[2]
+    }
+  }]
+})
+const logger = pino(transport)
+
+const toWrite = 1000000
+transport.on('ready', run)
+
+let total = 0
+
+function run () {
+  if (total++ === 8) {
+    return
+  }
+
+  for (let i = 0; i < toWrite; i++) {
+    logger.info(`hello ${i}`)
+  }
+  transport.once('drain', run)
+}
diff --git a/test/transport.test.js b/test/transport.test.js
index be5d971..492c7cf 100644
--- a/test/transport.test.js
+++ b/test/transport.test.js
@@ -11,6 +11,13 @@ const url = require('url')
 const strip = require('strip-ansi')
 const execa = require('execa')
 const writer = require('flush-write-stream')
+const { promisify } = require('util')
+const stream = require('stream')
+const { createReadStream } = require('fs')
+const split = require('split2')
+
+const pipeline = promisify(stream.pipeline)
+const { Writable } = stream
 
 const { pid } = process
 const hostname = os.hostname()
@@ -478,3 +485,25 @@ test('transport options with target and stream', async ({ fail, equal }) => {
     equal(err.message, 'only one of option.transport or stream can be specified')
   }
 })
+
+test('eight million lines', async ({ equal, comment }) => {
+  const destination = join(
+    os.tmpdir(),
+    '_' + Math.random().toString(36).substr(2, 9)
+  )
+  const child = execa(process.argv[0], [join(__dirname, 'fixtures', 'transport-many-lines.js'), destination])
+
+  await once(child, 'exit')
+  const toWrite = 8 * 1000000
+  let count = 0
+  await pipeline(createReadStream(destination), split(), new Writable({
+    write (chunk, enc, cb) {
+      if (count % (toWrite / 10) === 0) {
+        comment(`read ${count}`)
+      }
+      count++
+      cb()
+    }
+  }))
+  equal(count, toWrite)
+})