winston-syslog: Error: send 111

I’ve found the same issue, for a different error, related when method connect is called.

//Stack
events.js:72
        throw er; // Unhandled 'error' event
              ^
Error: send -11
    at errnoException (/usr/local/owner/project/node_modules/subProject/node_modules/winston-syslog/node_modules/unix-dgram/lib/unix_dgram.js:18:11)
    at Socket.send (/usr/local/owner/project/node_modules/subProject/node_modules/winston-syslog/node_modules/unix-dgram/lib/unix_dgram.js:93:24)
    at /usr/local/owner/project/node_modules/subProject/node_modules/winston-syslog/lib/winston-syslog.js:191:21
    at Syslog.connect (/usr/local/owner/project/node_modules/subProject/node_modules/winston-syslog/lib/winston-syslog.js:253:9)
    at Syslog.log (/usr/local/owner/project/node_modules/subProject/node_modules/winston-syslog/lib/winston-syslog.js:157:8)
    at transportLog (/usr/local/owner/project/node_modules/subProject/node_modules/winston/lib/winston/logger.js:228:15)
    at /usr/local/owner/project/node_modules/subProject/node_modules/winston/node_modules/async/lib/async.js:157:13
    at _each (/usr/local/owner/project/node_modules/subProject/node_modules/winston/node_modules/async/lib/async.js:57:9)
    at Object.async.each (/usr/local/owner/project/node_modules/subProject/node_modules/winston/node_modules/async/lib/async.js:156:9)
    at Logger.log (/usr/local/owner/project/node_modules/subProject/node_modules/winston/lib/winston/logger.js:240:9)

unix-dgram code of connect():

  // FIXME defer error and callback to next tick?
  if (err < 0)
    this.emit('error', errnoException(err, 'send'));
  else if (err === 1)
    this.emit('congestion');
  else if (typeof callback === 'function')
    callback();

code:

  //
  // Create the appropriate socket type.
  //
  if (this.isDgram) {
    if (self.protocol.match(/^udp/)) {
      this.socket = new dgram.Socket(this.protocol);
    }
    else if (self.protocol === 'unix') {
      this.socket = require('unix-dgram').createSocket('unix_dgram');
    }
    else {
      return this._unixDgramConnect(callback);
    }

    return callback(null);//Here, callback is called as if no error occurred, but no events handlers has been attached to socket yet.
  }

when protocol is equal ‘unix’, the socket is created without events handlers attached, so, all errors events from socket is throw as an Unhandled ‘error’ event. But when protocol is defined as unix-dgram, a call to ._unixDgramConnect() is made, so events handlers is attached to the socket created.

Re: https://github.com/winstonjs/winston-syslog/issues/19#issuecomment-1137377288, I didn’t look into how winston-syslog uses unix-dgram but after a “congestion” event you should pause until the next “writable” event.

“congestion” is only emitted for connected sockets. For unconnected sockets you should just back off a bit and retry.

It sounds like there’s a bug in winston-syslog because that -9 error code is EBADF (bad file descriptor) and suggests it closed the socket while still using it.

Thanks for looking into this!

Expected behavior:

* The logging system should never throw exceptions, even in extreme cases

* In cases of congestion of the logging system, some loss of log messages is acceptable. Ideally, as soon as the congestion has dissolved, there should be a log message warning that "n messages have been dropped".

* After the congestion has ended, logging should resume without loss of further messages.

I don’t completely agree, and have spent much of the past couple days on a problem with a non-Winston logger that is not logging everything it needs to, where the expected behavior is very much to bubble that error up, in this case all the way to a human user, to communicate that the content they think should’ve been logged wasn’t logged successfully and a backup strategy should be invoked.

However, I agree that if an app developer expects that behavior, they should be able to configure the logging library to behave that way, and the method of doing so should be well-documented. (I just don’t think it should be the default, especially if it isn’t currently.)

I don’t currently have the expertise and familiarity with unix-dgram (or even the relevant portions of winston-syslog) to go in and more deeply understand that interaction to get it working more smoothly, nor any funding to prioritize gaining that familiarity. However, I agree it does look like there’s an issue here which could get fixed by someone with the appropriate expertise & motivation.

I’m also observing the “Error: send -11” variant of this bug as mentioned in https://github.com/winstonjs/winston-syslog/issues/19#issuecomment-218474530

I’m using version 2.4.4 of winston-syslog.

Error -11 is EAGAIN, which means that some kind of throttling is going on. Regardless of the root cause, such an error should not propagate to the program that does logging.

I am using protocol “unix” so the referenced PR seems not to have caused an effect.