Error: send 111

[gdw2]

I'm getting an obscure "send 111" error when trying to log using the unix protocol. Any ideas? The node-syslog package works fine, as does using logger at the command line.

var winston = require('winston');
require('winston-syslog').Syslog;
winston.add(winston.transports.Syslog, {protocol:'unix',path:'/dev/log'});
winston.debug('hi')
debug: hi
Error: send 111
  at errnoException (/home/gwarner/winston-syslog/node_modules/unix-dgram/src/unix_dgram.js:25:11)
  at Socket.send (/home/gwarner/winston-syslog/node_modules/unix-dgram/src/unix_dgram.js:75:24)
  at /home/gwarner/winston-syslog/lib/winston-syslog.js:158:21
  at [object Object].Syslog.connect (/home/gwarner/winston-syslog/lib/winston-syslog.js:200:9)
  at [object Object].Syslog.log (/home/gwarner/winston-syslog/lib/winston-syslog.js:131:8)
  at [object Object].Logger.log (/home/gwarner/winston-syslog/node_modules/winston/lib/winston/logger.js:182:17)
  at Object.winston.(anonymous function) [as log] (/home/gwarner/winston-syslog/node_modules/winston/lib/winston.js:82:34)
  at Object.target.(anonymous function) [as debug] (/home/gwarner/winston-syslog/node_modules/winston/lib/winston/common.js:44:21)
  at repl:1:13
  at REPLServer.replDefaults.eval (/usr/lib/node_modules/coffee-script/lib/coffee-script/repl.js:33:42)
  at repl.js:239:12
  at Interface.<anonymous> (/usr/lib/node_modules/coffee-script/lib/coffee-script/repl.js:64:9)
  at Interface.emit (events.js:117:20)
  at Interface._onLine (readline.js:202:10)
  at Interface._line (readline.js:531:8)
  at Interface._ttyWrite (readline.js:760:14)
  at ReadStream.onkeypress (readline.js:99:10)
  at ReadStream.emit (events.js:117:20)
  at emitKey (readline.js:1095:12)
  at ReadStream.onData (readline.js:840:14)
  at ReadStream.emit (events.js:95:17)
  at ReadStream.<anonymous> (_stream_readable.js:748:14)
  at ReadStream.emit (events.js:92:17)
  at emitReadable_ (_stream_readable.js:410:10)
  at emitReadable (_stream_readable.js:406:5)
  at readableAddChunk (_stream_readable.js:168:9)
  at ReadStream.Readable.push (_stream_readable.js:130:10)
  at TTY.onread (net.js:528:21)

[santigimeno]

@gdw2 can you paste the output of:
npm ls
and
strace -f node your_test_program.js

[santigimeno]

Is this still an issue?

[jsbjair]

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.

[santigimeno]

@jsbjair I'm confused, what protocol are you using: unix or unix-connect?

[jsbjair]

@santigimeno
I was using unix, after read code, i've found, that, if you use, unix(anything), as in unix-dgram,unix-connect has the same result;
code

this.isDgram  = /^udp|^unix/.test(this.protocol);
  //
  // Create the appropriate socket type.
  if (this.isDgram) { /*...*/ }

But, if you use unix(anything), the event handler is attached in ._unixDgramConnect(),
and all events from socket is captured

[santigimeno]

Sorry, I don't follow :(. From what I read, the handling is different if you use unix or unix-connect, maybe I'm wrong though...

[jsbjair]

if (!/^udp|unix|unix-connect|tcp/.test(this.protocol)) {
    throw new Error('Invalid syslog protocol: ' + this.protocol);
  }

this test dont fail for "unix-dgram", so you can use any string beginning with unix.
!/^udp|unix|unix-connect|tcp/.test('unix-dgram') evaluate to false.
!/^udp|unix|unix-connect|tcp/.test('unixanything') == false

[santigimeno]

Ok, now I understand what you mean. Thanks. Let me check that

[santigimeno]

@jsbjair what you say it's true, but if you use any different from unix or unix-connect it should throw: https://github.com/winstonjs/winston-syslog/blob/master/lib/winston-syslog.js#L66-L68

[santigimeno]

@jsbjair anyway, the issue seems to be that there are uncaught errors when using unix right?

[jsbjair]

yes

[jsbjair]

here to throw

  if (!/^udp|unix|unix-connect|tcp/.test(this.protocol)) {
    throw new Error('Invalid syslog protocol: ' + this.protocol);
  }

must be

  if (!/^udp$|unix$|unix-connect$|tcp$/.test(this.protocol)) {
    throw new Error('Invalid syslog protocol: ' + this.protocol);
  }

[santigimeno]

Yes, you're right. I would welcome a PR fixing it :)

[indyjo]

I'm also observing the "Error: send -11" variant of this bug as mentioned in #19 (comment)

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.

[gregoreesmaa]

@indyjo #28 seems to suggest using unix-connect instead of unix to solve your problem.

[indyjo]

@gregoreesmaa I've put some time into investigating this issue lately. This is what I observed:

• When using unix-connect instead of unix, there still were errors, albeit different ones ("Error: congestion" instead of "Error: send -11" if I recall correctly). There seems to be code in the unix-connect implementation to handle the congestion situation, but it doesn't seem to work reliably for me (winston 2.5.0).
• Errors were converted into exceptions which propagated through code that didn't expect any errors at all. The result was broken application state.
• Registering an error handler (logger.on('error', ...)) prevented exceptions from being thrown. This solved my problem with unexpected exceptions.

[indyjo]

There's apparently an issue when logging to a congested socket. Why is this relevant? Because under load, any syslog implementation will eventually become congested. What's worse: winston's default behavior is to throw an exception. This means that applications are going to see sporadic failures. Neither unix nor unix-connect seem to handle this properly. Neither seem to be able to recover from a congestion situation.

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.

Here's a test case (the "sender"):

const winston = require('winston');
require('winston-syslog').Syslog;

const transport = new winston.transports.Syslog({
    // protocol: 'unix',
    protocol: 'unix-connect',
    path: 'somesocket',
    app_name: 'logtest'
});

const logger = winston.createLogger({
    levels: winston.config.syslog.levels,
    transports: [transport],
    format: winston.format.simple()
});

let n = 0;

// Comment this out and an exception will be thrown.
logger.on('error', err => console.error(`Error on messsage ${n}: ${err.message}`));

// Log every 20 milliseconds. Add some space characters so that kernel buffer fills quicker.
setInterval(() => logger.info(`Test messsage ${n++} ${' '.repeat(128)}\n`), 20);

To simulate a congested receiver, I execute the following bash command in the same directory:
socat UNIX-RECV:somesocket stdout | (echo "Waiting..."; sleep 15; echo "Reading..."; cat)

This will block for the first 15 seconds and then start sending everything it reads to stdout.

When executed with unix-connect:

The sender outputs:

Error on messsage 469: congestion
Error on messsage 470: congestion
...
Error on messsage 672: congestion
Error on messsage 673: send -9
Error on messsage 674: send -9
... (continues until aborted)

The receiver outputs:

Waiting...
Reading...
<134>May 25 16:22:35 localhost logtest[224119]: info: Test messsage 0                                                                                                                                 
<134>May 25 16:22:35 localhost logtest[224119]: info: Test messsage 1                                                                                                                                 
<134>May 25 16:22:35 localhost logtest[224119]: info: Test messsage 2
...
<134>May 25 16:22:45 localhost logtest[224119]: info: Test messsage 467
(no further output)

When executed with unix:

The sender outputs:

Error on messsage 469: send -11
Error on messsage 470: send -11
...
Error on messsage 670: send -11
Error on messsage 671: send -9
Error on messsage 672: send -9
... (continues until aborted)

The receiver outputs:

Waiting...
Reading...
<134>May 25 16:27:28 localhost logtest[226491]: info: Test messsage 0                                                                                                                                 
<134>May 25 16:27:28 localhost logtest[226491]: info: Test messsage 1                                                                                                                                 
<134>May 25 16:27:28 localhost logtest[226491]: info: Test messsage 2
...
<134>May 25 16:27:37 localhost logtest[226491]: info: Test messsage 467
(no further output)

I tested with winston 3.7.2, winston-syslog 2.5.0 and unix-dgram 2.0.4 on a VM with Linux 5.10.

Maybe the @winstonjs team and @bnoordhuis would like to have a look at the interaction between winston-syslog and unix-dgram here.

[wbt]

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.

[bnoordhuis]

Re: #19 (comment), 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.