fix: Error on rotated file if new file takes time to appear

When a file's inode changes, or the `stat` call throws
causes tail-file to read the remainder of the contents
via a FileHandle. If the file disappears, but takes a bit
to re-appear, `_readRemainderFromFileHandle()` is
erroneously called twice; once for the `ENOENT` from the
disappearing file, and once when the new file causes the
inode to change. This commit fixes a bug where the FH is
nullified after the first call, and thus throws on the
subsequent call.

Semver: patch
Fixes: #18

lib/tail-file.js

@@ -120,17 +120,18 @@ class TailFile extends Readable {
   async _readRemainderFromFileHandle() {
     // Read the end of a renamed file before re-opening the new file.
     // Use the file handle since it remains open even if the file name has changed
-    const stats = await this[kFileHandle].stat()
+    const fileHandleTemp = this[kFileHandle] // Prevent races when closing
+    this[kFileHandle] = null
+    const stats = await fileHandleTemp.stat()
     const lengthToEnd = stats.size - this[kStartPos]
-    const {buffer} = await this[kFileHandle].read(
+    const {buffer} = await fileHandleTemp.read(
       Buffer.alloc(lengthToEnd)
     , 0
     , lengthToEnd
     , this[kStartPos]
     )
     this.push(buffer)
-    await this[kFileHandle].close()
-    this[kFileHandle] = null
+    await fileHandleTemp.close()
     return
   }
 
@@ -167,8 +168,20 @@ class TailFile extends Readable {
         // First iteration - nothing has been polled yet
         this[kStartPos] = eof
       } else if (this[kInode] !== stats.ino) {
-        // File renamed/rolled
-        await this._readRemainderFromFileHandle()
+        // File renamed/rolled between polls without triggering `ENOENT`.
+        // Conditional since this *may* have already been done if `ENOENT` threw earlier.
+        if (this[kFileHandle]) {
+          try {
+            await this._readRemainderFromFileHandle()
+          } catch (error) {
+            const err = new Error('Could not read remaining bytes from old FH')
+            err.meta = {
+              error: error.message
+            , code: error.code
+            }
+            this.emit('tail_error', err)
+          }
+        }
         await this._openFile()
         this[kStartPos] = 0
         this[kInode] = stats.ino
@@ -204,6 +217,7 @@ class TailFile extends Readable {
     } catch (err) {
       if (err.code === 'ENOENT') {
         if (this[kFileHandle]) {
+          // The .stat() via polling may have happened during a file rename/roll.
           // Don't lose the last lines in the file if it previously existed.
           // Perhaps it has not been re-created yet (or won't be)
           try {

package.json

@@ -83,6 +83,7 @@
     "jsx": false,
     "check-coverage": true,
     "jobs": 1,
+    "timeout": 60,
     "coverage-report": [
       "text",
       "text-summary",

test/memory-usage/tail-big-log-file.js

@@ -44,8 +44,8 @@ test('Memory consumption', async (t) => {
       clearTimeout(timer)
       if (++counter % 10000 === 0) {
         const usage = process.memoryUsage()
-        if (usage.rss < rssMin) rssMin = usage.rss
-        if (usage.rss > rssMax) rssMax = usage.rss
+        rssMin = Math.min(usage.rss, rssMin)
+        rssMax = Math.max(usage.rss, rssMax)
         t.pass(`Memory usage at ${counter} lines: ${JSON.stringify(usage)}`)
       }
       timer = setTimeout(() => {

test/tail-file.js

@@ -206,7 +206,9 @@ test('Success: tail file from beginning if it is truncated', async (t) => {
   )
 })
 
-test('Success: File may disappear, but continues if the file re-appears', async (t) => {
+test('Success: File may disappear, but continues if the file re-appears', (t) => {
+  t.plan(6)
+
   const name = 'logfile.txt'
   const testDir = t.testdir({
     [name]: ''
@@ -215,24 +217,54 @@ test('Success: File may disappear, but continues if the file re-appears', async
 
   const tail = new TailFile(filename, {
     encoding: 'utf8'
-  , pollFileIntervalMs: 10
+  , pollFileIntervalMs: 100
+  , maxPollFailures: 500 // Do not let max polls throw this test
   })
 
+  const symbols = getSymbols(tail)
+
   t.teardown(() => {
     tail.quit().catch(fail)
   })
 
-  await tail.start()
-  await fs.promises.unlink(filename)
-  await fs.promises.writeFile(filename, 'The file has been re-created\n')
-  const [renamedEvt] = await once(tail, 'renamed')
-  t.match(renamedEvt, {
-    message: 'The file was renamed or rolled.  Tailing resumed from the beginning.'
-  , filename
-  , when: Date
-  }, 'renamed event is correct')
-  const [lineAfterRecreate] = await once(tail, 'data')
-  t.equal(lineAfterRecreate, 'The file has been re-created\n', 'Got line from new file')
+  tail.once('retry', (evt) => {
+    t.match(evt, {
+      message: 'File disappeared. Retrying.'
+    , filename
+    , attempts: 1 // The retry will fire for every retry attempt, so listen only once
+    , when: Date
+    }, 'retry event received')
+  })
+
+  tail.on('renamed', (evt) => {
+    t.match(evt, {
+      message: 'The file was renamed or rolled.  Tailing resumed from the beginning.'
+    , filename
+    , when: Date
+    }, 'renamed event is correct')
+  })
+
+  tail.on('data', (lineAfterRecreate) => {
+    t.equal(lineAfterRecreate, 'The file has been re-created\n', 'Got line from new file')
+  })
+
+  tail.start()
+
+  t.test('Pause briefly after starting', async () => {
+    await sleep(100)
+  })
+
+  t.test('Remove the original file and pause for a long time', async () => {
+    await fs.promises.unlink(filename)
+    // Certain OS's will use the same inode.  Force a different one to test the branch
+    // that would call `_readRemainderFromFileHandle()` twice
+    tail[symbols.inode] = 123456
+    await sleep(500)
+  })
+
+  t.test('Write a new file after a long pause', async (t) => {
+    await fs.promises.writeFile(filename, 'The file has been re-created\n')
+  })
 })
 
 test('Success: Stream backpressure is respected for a large file', (t) => {
@@ -423,7 +455,7 @@ test('Error: Unknown error received during polling causes an exit', (t) => {
   tail.start()
 })
 
-test('Handled: Error reading remaining file bits emits tail_error', async (t) => {
+test('Handled: Error reading old FH emits tail_error after ENOENT', async (t) => {
   const name = 'logfile.txt'
   const testDir = t.testdir({
     [name]: ''
@@ -445,16 +477,54 @@ test('Handled: Error reading remaining file bits emits tail_error', async (t) =>
   await fs.promises.appendFile(filename, 'Here is line 3\n')
   await fs.promises.rename(filename, path.join(testDir, `${name}.rolled`))
   // Manually call poll just to eliminate race conditions with this test
-  // Close the FH first to trigger an error
+  // Close the FH first to trigger an error after `ENOENT` is thrown.
+  const tail_error = once(tail, 'tail_error')
   await tail[symbols.fileHandle].close()
   await tail._pollFileForChanges()
-  const [evt] = await once(tail, 'tail_error')
+  const [evt] = await tail_error
   t.match(evt, {
     name: 'Error'
   , code: 'EBADF'
   }, 'Got tail_error as expected')
 })
 
+test('Handled: Error reading old FH emits tail_error after inode changes', async (t) => {
+  const name = 'logfile.txt'
+  const testDir = t.testdir({
+    [name]: ''
+  })
+  const filename = path.join(testDir, name)
+  const tail = new TailFile(filename, {
+    encoding: 'utf8'
+  , pollFileIntervalMs: 10000000 // We will manually activate polling
+  })
+  const symbols = getSymbols(tail)
+
+  t.teardown(() => {
+    tail.quit().catch(fail)
+  })
+
+  await tail.start()
+  // Manually call poll just to eliminate race conditions with this test
+  // Close the FH first to trigger an error after `ENOENT` is thrown.
+  const tail_error = once(tail, 'tail_error')
+  await tail[symbols.fileHandle].close()
+  tail[symbols.inode] = 12345678
+  await fs.promises.appendFile(filename, 'Here is a new line')
+  await tail._pollFileForChanges()
+  const [evt] = await tail_error
+  t.match(evt, {
+    name: 'Error'
+  , message: 'Could not read remaining bytes from old FH'
+  , meta: {
+      error: String // Error differs per OS
+    , code: 'EBADF'
+    }
+  }, 'Got tail_error as expected')
+  const [newData] = await once(tail, 'data')
+  t.equal(newData, 'Here is a new line', 'New data was read after FH read failure')
+})
+
 test('Quitting destroys any open tail file stream', (t) => {
   t.plan(4)