fix: close file transports before reconfigure to avoid write-after-end

lib/winston/logger.js

@@ -99,7 +99,10 @@ class Logger extends Transform {
   } = {}) {
     // Reset transports if we already have them
     if (this.transports.length) {
-      this.clear();
+      // Close before unpipe so File streams end while still attached.
+      // closeTransportsOnce hides close() so the unpipe handler does not
+      // call it a second time.
+      closeTransportsOnce(this.transports.slice(), () => this.clear());
     }
 
     this.silent = silent;
@@ -673,6 +676,44 @@ class Logger extends Transform {
   }
 }
 
+/**
+ * Closes each transport once, then unpipes it.
+ * TransportStream calls close() from its unpipe handler. close() is hidden
+ * until that unpipe finishes so the handler does not close a second time.
+ * A repeated close can throw and abort reconfiguration.
+ * @param {Array} attached - Transports currently piped to the logger.
+ * @param {Function} unpipe - Removes those transports from the logger.
+ * @returns {undefined}
+ */
+function closeTransportsOnce(attached, unpipe) {
+  const closers = [];
+
+  attached.forEach(transport => {
+    if (typeof transport.close !== 'function') {
+      return;
+    }
+
+    closers.push({
+      transport,
+      close: transport.close
+    });
+    transport.close = null;
+  });
+
+  try {
+    closers.forEach(closer => {
+      closer.close.call(closer.transport);
+    });
+    unpipe();
+  } finally {
+    closers.forEach(closer => {
+      if (closer.transport.close === null) {
+        closer.transport.close = closer.close;
+      }
+    });
+  }
+}
+
 function getLevelValue(levels, level) {
   const value = levels[level];
   if (!value && value !== 0) {

test/unit/winston/logger.test.js

@@ -9,6 +9,7 @@
 'use strict';
 
 const assume = require('assume');
+const fs = require('fs');
 const path = require('path');
 const { EOL } = require('os');
 const isStream = require('is-stream');
@@ -49,6 +50,91 @@ describe('Logger Instance', function () {
       assume(logger.transports[0].name).equals('console');
     });
 
+    it('closes existing file transports before reconfiguration', async function () {
+      const oldLogFile = path.join(testLogFixturesPath, 'configure-old.log');
+      const newLogFile = path.join(testLogFixturesPath, 'configure-new.log');
+      [oldLogFile, newLogFile].forEach(file => {
+        if (fs.existsSync(file)) fs.unlinkSync(file);
+      });
+
+      const oldTransport = new winston.transports.File({ filename: oldLogFile });
+      const close = jest.spyOn(oldTransport, 'close');
+      const logger = winston.createLogger({ transports: [oldTransport] });
+      const clear = logger.clear.bind(logger);
+      jest.spyOn(logger, 'clear').mockImplementation(() => {
+        expect(close).toHaveBeenCalled();
+        return clear();
+      });
+      let loggerFinished = false;
+
+      try {
+        logger.info('before reconfiguration');
+        logger.configure({
+          transports: [
+            new winston.transports.File({ filename: newLogFile })
+          ]
+        });
+
+        expect(close).toHaveBeenCalledTimes(1);
+        assume(oldTransport._stream._writableState.ending).true();
+        logger.info('after reconfiguration');
+        await new Promise((resolve, reject) => {
+          logger.once('finish', () => {
+            loggerFinished = true;
+            resolve();
+          });
+          logger.once('error', reject);
+          logger.end();
+        });
+
+        assume(fs.readFileSync(newLogFile, 'utf8')).includes('after reconfiguration');
+      } finally {
+        if (!loggerFinished) {
+          logger.end();
+        }
+        if (!oldTransport._stream.writableEnded) {
+          oldTransport.close();
+        }
+        [oldLogFile, newLogFile].forEach(file => {
+          if (fs.existsSync(file)) fs.unlinkSync(file);
+        });
+      }
+    });
+
+    it('invokes each transport close once when reconfiguring', function () {
+      function createTransport() {
+        let closes = 0;
+        const transport = new TransportStream({
+          log(info, callback) {
+            callback();
+          },
+          close() {
+            closes += 1;
+            if (closes > 1) {
+              throw new Error('close called twice');
+            }
+          }
+        });
+        transport.closes = () => closes;
+        return transport;
+      }
+
+      const first = createTransport();
+      const second = createTransport();
+      const logger = winston.createLogger({ transports: [first, second] });
+
+      logger.configure({
+        transports: [new winston.transports.Console()]
+      });
+
+      assume(first.closes()).equals(1);
+      assume(second.closes()).equals(1);
+      assume(typeof first.close).equals('function');
+      assume(typeof second.close).equals('function');
+      assume(logger.transports.length).equals(1);
+      assume(logger.transports[0].name).equals('console');
+    });
+
     it('.configure({ transports, format })', function () {
       let logger = winston.createLogger(),
           format = logger.format;