search

winstonjs / winston-syslog

A syslog transport for winston
http://github.com/winstonjs/winston-syslog
MIT License
136 stars 123 forks source link

Error: send 111 #19

Open gdw2 opened 10 years ago

gdw2 commented 10 years ago

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 commented 10 years ago

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

santigimeno commented 8 years ago

Is this still an issue?

jsbjair commented 8 years ago

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 commented 8 years ago

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

jsbjair commented 8 years ago

@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 commented 8 years ago

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 commented 8 years ago 
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 commented 8 years ago

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

santigimeno commented 8 years ago

@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 commented 8 years ago

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

jsbjair commented 8 years ago

yes

jsbjair commented 8 years ago

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 commented 8 years ago

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

indyjo commented 2 years ago

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.

gregoreesmaa commented 2 years ago

@indyjo https://github.com/winstonjs/winston-syslog/pull/28 seems to suggest using unix-connect instead of unix to solve your problem.

indyjo commented 2 years ago

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

indyjo commented 2 years ago

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:

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 commented 2 years ago

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 commented 2 years ago

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.