Comments (19)
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.
from winston-syslog.
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.
from winston-syslog.
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.
from winston-syslog.
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.
from winston-syslog.
@gdw2 can you paste the output of:
npm ls
and
strace -f node your_test_program.js
from winston-syslog.
Is this still an issue?
from winston-syslog.
@jsbjair I'm confused, what protocol are you using: unix
or unix-connect
?
from winston-syslog.
@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
from winston-syslog.
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...
from winston-syslog.
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
from winston-syslog.
Ok, now I understand what you mean. Thanks. Let me check that
from winston-syslog.
@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
from winston-syslog.
@jsbjair anyway, the issue seems to be that there are uncaught errors when using unix
right?
from winston-syslog.
yes
from winston-syslog.
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);
}
from winston-syslog.
Yes, you're right. I would welcome a PR fixing it :)
from winston-syslog.
@indyjo #28 seems to suggest using unix-connect
instead of unix
to solve your problem.
from winston-syslog.
@gregoreesmaa I've put some time into investigating this issue lately. This is what I observed:
- When using
unix-connect
instead ofunix
, there still were errors, albeit different ones ("Error: congestion"
instead of"Error: send -11"
if I recall correctly). There seems to be code in theunix-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.
from winston-syslog.
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.
from winston-syslog.
Related Issues (20)
- Winston-syslog doesn't handle connection loss? HOT 5
- Support critical as loglevel
- mTLS connection is not working
- Syslog logs not flushed until app exits, and multiples are concatenated? HOT 6
- Logging via UNIX domains sockets is not quite conformant
- App doesn't stop when I use this library HOT 4
- Timestamp is incorrect when milliseconds < 100
- Usage: please correct "type" options HOT 1
- InFlight counter going negative
- Error healthCheck(dgram)
- Occasional ECONNRESET and EPIPE errors HOT 1
- No logs when running in docker container HOT 1
- Unable to change Destination via Syslog Configuration HOT 1
- cloudflare workers support HOT 7
- winston-syslog hardcodes log level to 'info' HOT 1
- Unable to change appName without reinstantiation HOT 1
- Error Handling on Creating TCP Socket HOT 1
- Winston containers problem with winston-syslog and solution HOT 2
- Implementing in nuxt 3
- Dependency glossy is unmaintained HOT 3
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from winston-syslog.