Logging for all transport stop if fluent server is not available

[NetForces]

In the case where the fluent server becomes unavailable the logging for all transports stop logging and not only the fluent one.

I was able to reproduce this with a slightly modified version of the winston example:

const winston = require('winston');
const fluentNodeLogger = require('fluent-logger');

const logger = winston.createLogger({
  transports: [
    new (fluentNodeLogger.support.winstonTransport())(
      '___specialcustomtesttag',
      {
        host: 'localhost',
        port: 24224,
        timeout: 3.0
      }
    ),
    new winston.transports.Console({
      format: winston.format.combine(
        winston.format.colorize(),
        winston.format.printf(info => `${info.level} ${new Date().toISOString()} ${info.message}`)
      ),
    }),
  ],
});

(function repeatLog() {
  setTimeout(() => {
    logger.info('it works');
    repeatLog();
  }, 1000)
})();

Running this without any fluent listening on port 24224 will cause even the console log to stop after 16 loop.

If a fluent server is listening (or emulated with nc -lv 24224) it keeps on going till I stop the fluent server and then it keep on logging on the console for 16 loops and then stops logging. Restarting the fluent server does not make the logging (console and fluent) start again.

[NetForces]

Ok, been troubleshooting a bit and here is as far as I can go...

With the following 'patch':

--- lib/sender.js_orig  2018-10-25 10:55:32.000000000 -0400
+++ lib/sender.js       2018-10-25 11:55:07.000000000 -0400
@@ -106,6 +106,9 @@
     this._push(tag, timestamp, data, callback);
     this._connect(() => {
       this._flushSendQueue();
+      if (this._status !== 'established') {
+        callback && callback();
+      }
     });
   }

@@ -233,6 +236,7 @@
         if (this._socket) {
           this._disconnect();
           this._handleEvent('error', err);
+          callback();
         }
       };
       this._socket.on('error', errorHandler);
@@ -427,7 +431,13 @@
       } else {
         this._sendQueueSize -= sendQueueSize;
         callbacks.forEach((callback) => {
-          callback && callback();
+          try {
+            callback && callback();
+          } catch (err) {
+            console.log("Error occured");
+            console.log(err);
+          }
+
         });
         process.nextTick(() => {
           this._waitToWrite();

• The logger continues to log to console if fluent is not available
• The logger logs to console and fluent if it's available from the start and continues to log to console if it goes away
• If fluent comes back it dumps a big fat ugly error but is reconnects to fluent and resume logging to both transports.

Maybe someone can pick it up from here.

[okkez]

Could you try #116 and https://github.com/nodejs/node/pull/23895 ?

[NetForces]

@okkez with these changes (changes applied to v3.2.1 code) I'm getting an 'Unhandled "error" event' if no fluent server is running:

{10:17}[2.3.5]~/Documents/sources/proxy:bt-tweak-typescript ✗ ➭ node test.js
info 2018-10-26T14:17:24.192Z it works
events.js:188
      throw err;
      ^

Error: Unhandled "error" event. ([object Object])
    at DerivedLogger.emit (events.js:186:19)
    at DerivedLogger.transportError (/Users/courchea/Documents/sources/proxy/node_modules/winston/lib/winston/logger.js:529:12)
    at emitOne (events.js:121:20)
    at FluentTransport.emit (events.js:211:7)
    at sender.emit (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/winston.js:42:16)
    at _connect (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/sender.js:108:28)
    at _doConnect (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/sender.js:212:11)
    at FluentSender._handleEvent (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/sender.js:441:17)
    at Socket.errorHandler (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/sender.js:236:16)
    at emitOne (events.js:116:13)

[NetForces]

@okkez Sorry had not seen the error handler in your test code. With it I do get the exception:

info 2018-10-26T14:47:07.107Z it works it works 1
Fluentd error { Error: connect ECONNREFUSED 127.0.0.1:24224
    at Object._errnoException (util.js:992:11)
    at _exceptionWithHostPort (util.js:1014:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1186:14)
  code: 'ECONNREFUSED',
  errno: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 24224 }
Fluentd will reconnect after 20 seconds
Fluentd error { DataTypeError: data must be an object
    at FluentSender.emit (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/sender.js:101:15)
    at DerivedLogger.logger.on (/Users/courchea/Documents/sources/proxy/test2.js:25:20)
    at emitTwo (events.js:126:13)
    at DerivedLogger.emit (events.js:214:7)
    at DerivedLogger.transportError (/Users/courchea/Documents/sources/proxy/node_modules/winston/lib/winston/logger.js:529:12)
    at emitOne (events.js:121:20)
    at FluentTransport.emit (events.js:211:7)
    at sender.emit (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/winston.js:42:16)
    at _connect (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/sender.js:108:28)
    at _doConnect (/Users/courchea/Documents/sources/proxy/node_modules/fluent-logger/lib/sender.js:212:11)
  name: 'DataTypeError',
  message: 'data must be an object',
  options:
   { tag_prefix: '___specialcustomtesttag',
     label: undefined,
     record: undefined } }
Fluentd will reconnect after 20 seconds

And on continue on logging to the console.

I was able to switch on and off the fluent server multiple times and it would not make the console logging stop. So it looks good to me.

[NetForces]

@okkez regarding the required fix in node... Anyway we could deal with it within the fluent-logger-node library ? The node release cycle is much longer than yours and we can't really wait on them approving the fix and having it make it's way to the next release.

Thanks for the quick answer and help.

[okkez]

It is difficult to handle it in the fluent-logger-node library.

[sphansekar-cci]

I am facing a similar issue. I am having two transport in winston ie. file and fluent-logger. Initially few logs are getting saved to my file(via transport), but later when I stop td-agent then logs are not getting saved in a file too. Once I restart td-agent logs are flushed to td-agent and written to file too. I am not able to understand why it's blocking other transport.