Skip Menu |

This queue is for tickets about the Log-Syslog-Fast CPAN distribution.

Report information
The Basics
Id: 63034
Status: resolved
Priority: 0/
Queue: Log-Syslog-Fast

People
Owner: Nobody in particular
Requestors: POWERMAN [...] cpan.org
Cc:
AdminCc:

Bug Information
Severity: Important
Broken in: 0.45
Fixed in: (no value)



Subject: die on EAGAIN
When sending too many log messages too fast Log::Syslog::Fast will die because it got EAGAIN in LogSyslogFast.c at LSF_send(). I've tested this using UNIX socket on Linux, but this can happens with any socket type. It's possible to fix it this way: int ret = send(logger->sock, logger->linebuf, logger->prefix_len + msg_len, MSG_DONTWAIT); if (ret < 0) { if (errno == EAGAIN) ret = send(logger->sock, logger->linebuf, logger- Show quoted text
>prefix_len + msg_len, 0);
if (ret < 0) logger->err = strerror(errno); } but in my tests this solution has same speed as much simpler fix: int ret = send(logger->sock, logger->linebuf, logger->prefix_len + msg_len, 0); if (ret < 0) logger->err = strerror(errno);
What is the advantage of handling these retries here rather than after catching the exception? On Tue Nov 16 06:04:16 2010, POWERMAN wrote: Show quoted text
> When sending too many log messages too fast Log::Syslog::Fast will die > because it got EAGAIN in LogSyslogFast.c at LSF_send(). I've tested > this using UNIX socket on Linux, but this can happens with any socket > type. > > It's possible to fix it this way: > > int ret = send(logger->sock, logger->linebuf, logger->prefix_len + > msg_len, MSG_DONTWAIT); > if (ret < 0) { > if (errno == EAGAIN) > ret = send(logger->sock, logger->linebuf, logger-
> >prefix_len + msg_len, 0);
> if (ret < 0) > logger->err = strerror(errno); > } > > but in my tests this solution has same speed as much simpler fix: > > int ret = send(logger->sock, logger->linebuf, logger->prefix_len + > msg_len, 0); > if (ret < 0) > logger->err = strerror(errno);
On Tue Nov 16 18:07:50 2010, ATHOMASON wrote: Show quoted text
> What is the advantage of handling these retries here rather than after > catching the exception?
Advantage? Raising exception while, possibly, logging another exception isn't good idea at all! Especially in this situation, because it isn't real error, it's just EAGAIN. How user can handle it? Retry sending same message to log in loop until success or some other, real error? The right question is what advantage in using non-blocking send() there?
On Tue Nov 16 19:58:40 2010, POWERMAN wrote: Show quoted text
> On Tue Nov 16 18:07:50 2010, ATHOMASON wrote:
> > What is the advantage of handling these retries here rather than after > > catching the exception?
> > Advantage? Raising exception while, possibly, logging another exception > isn't good idea at all!
Why not? Just wrap the send call in an eval. Show quoted text
> Especially in this situation, because it isn't > real error, it's just EAGAIN.
That is a real error for applications for which blocking on I/O is unacceptable. Show quoted text
> How user can handle it? Retry sending same > message to log in loop until success or some other, real error?
Unless I'm missing something, a single retry is exactly what you're proposing. But since that's a policy decision that may be undesirable to some clients, and it's doable at a higher level, I don't think it's appropriate to address here. Show quoted text
> > The right question is what advantage in using non-blocking send() there?
For applications which are not ever allowed to block (like event-loop based multiplexing servers), immediate return of an undeliverable message is the only acceptable behavior. The exception is thrown so that buffering and retries can be done at a higher layer if desirable.
On Tue Nov 16 20:40:39 2010, ATHOMASON wrote: Show quoted text
> Unless I'm missing something, a single retry is exactly what you're > proposing.
I've proposed single _blocking_ retry call. But I got your point now, and it have sense, thanks. Probably your implied policy have to be documented. Actually, current documentation doesn't match that policy: 1) METHODS - new() - $proto states $logger->send() will block for LOG_UNIX 2) UNREACHABLE SERVERS - LOG_UNIX doesn't mention raised exception on EAGAIN, and that's only place where exceptions documented. BTW, I'm using only non-blocking I/O for years in nearly all projects, so I understood your needs, but don't 100% agree with proposed solution. In event-loop based applications with non-blocking I/O it's usual to have all sockets managed by epoll()-like thing. There usually some low level engine, which control _all_ sockets, automatically handle EAGAIN, keep outgoing buffers for all sockets, etc. So, if you design your logger module for such environment it have much more sense to provide some way to delegate managing of log socket to same low- level engine used in user's application (like EV or AnyEvent modules). And throw exception/send error event to user only when buffer is full or something like that, not on every EAGAIN. IMHO handing EAGAIN on user level is just plain wrong in such applications - that's too low level thing, it require complex enough handing (especially when log socket doesn't delegated to epoll and user can't just get event notification when socket will be ready to accept more data), and there not much things user can do with this.
On Tue Nov 16 22:00:58 2010, POWERMAN wrote: Show quoted text
> On Tue Nov 16 20:40:39 2010, ATHOMASON wrote:
> > Unless I'm missing something, a single retry is exactly what you're > > proposing.
> I've proposed single _blocking_ retry call. > But I got your point now, and it have sense, thanks. > > Probably your implied policy have to be documented. Actually, current > documentation doesn't match that policy: > > 1) METHODS - new() - $proto states $logger->send() will block for > LOG_UNIX > 2) UNREACHABLE SERVERS - LOG_UNIX doesn't mention raised exception on > EAGAIN, and that's only place where exceptions documented.
Oh, this is about LOG_UNIX? I just assumed you were using LOG_UDP since that's the only one that's configured to be non-blocking (see https://github.com/athomason/Log-Syslog-Fast/blob/master/LogSyslogFast.c#L143). AFAIK LOG_UNIX should never have an EAGAIN error since send(2) is only supposed to return that for a nonblocking socket. Do you have a test case showing that behavior? Show quoted text
> > BTW, I'm using only non-blocking I/O for years in nearly all projects, > so I understood your needs, but don't 100% agree with proposed > solution. In event-loop based applications with non-blocking I/O it's > usual to have all sockets managed by epoll()-like thing. There usually > some low level engine, which control _all_ sockets, automatically > handle EAGAIN, keep outgoing buffers for all sockets, etc. So, if you > design your logger module for such environment it have much more sense > to provide some way to delegate managing of log socket to same low- > level engine used in user's application (like EV or AnyEvent modules). > And throw exception/send error event to user only when buffer is full > or something like that, not on every EAGAIN.
Indeed, that's what something like Log::Syslog::DangaSocket is for (using the Danga::Socket epoll-based event loop). The assumption in L::S::Fast is that use of the unreliable UDP transport goes with a desire for "fire and forget" logging. Show quoted text
> > IMHO handing EAGAIN on user level is just plain wrong in such > applications - that's too low level thing, it require complex enough > handing (especially when log socket doesn't delegated to epoll and user > can't just get event notification when socket will be ready to accept > more data), and there not much things user can do with this.
There's not much the module can do either; the "right" behavior on failure depends on the application. In the frequent case where the retry fails as well, the policy decision needs to be made again. But that decision should be at a higher level; not necessarily as high as the client code, but possibly as a subclass which overrides send() to handle retries.
On Tue Nov 16 22:12:35 2010, ATHOMASON wrote: Show quoted text
> Oh, this is about LOG_UNIX? I just assumed you were using LOG_UDP
since Show quoted text
> that's the only one that's configured to be non-blocking (see https://
github.com/athomason/Log-Syslog-Fast/blob/master/LogSyslogFast.c#L143). Show quoted text
> AFAIK LOG_UNIX should never have an EAGAIN error since send(2) is only > supposed to return that for a nonblocking socket. Do you have a test > case showing that behavior?
Yeah, it's about LOG_UNIX. You're using send(MSG_DONTWAIT), and this force non-blocking behavior even on blocking sockets. Test case (carefully, it will flood your system's syslog): $ LANG= ./lsf_EAGAIN [iteration 340] Error while sending: Resource temporarily unavailable at ./lsf_EAGAIN line 9. $ LANG= ./lsf_EAGAIN [iteration 2499] Error while sending: Resource temporarily unavailable at ./lsf_EAGAIN line 9. $ cat ./lsf_EAGAIN #!/usr/bin/perl use warnings; use strict; use Log::Syslog::Fast qw(:all); my $logger = Log::Syslog::Fast->new(LOG_UNIX, '/dev/log', 0, LOG_USER, LOG_INFO, 'myhost', 'myapp'); $logger->set_priority(LOG_USER, LOG_DEBUG); for (1 .. 10000) { eval { $logger->send('x' x 40) }; die "[iteration $_] $@\n" if $@; }
Ah now I see, that was unintentionally left from when it was a pure-UDP module. I'll remove it since the UDP sockets are already marked non-blocking. Thanks. On Tue Nov 16 22:43:14 2010, POWERMAN wrote: Show quoted text
> On Tue Nov 16 22:12:35 2010, ATHOMASON wrote:
> > Oh, this is about LOG_UNIX? I just assumed you were using LOG_UDP
> since
> > that's the only one that's configured to be non-blocking (see https://
> github.com/athomason/Log-Syslog-Fast/blob/master/LogSyslogFast.c#L143).
> > AFAIK LOG_UNIX should never have an EAGAIN error since send(2) is only > > supposed to return that for a nonblocking socket. Do you have a test > > case showing that behavior?
> > Yeah, it's about LOG_UNIX. You're using send(MSG_DONTWAIT), and this > force non-blocking behavior even on blocking sockets. > Test case (carefully, it will flood your system's syslog): > > $ LANG= ./lsf_EAGAIN > [iteration 340] Error while sending: Resource temporarily unavailable > at ./lsf_EAGAIN line 9. > > $ LANG= ./lsf_EAGAIN > [iteration 2499] Error while sending: Resource temporarily unavailable > at ./lsf_EAGAIN line 9. > > $ cat ./lsf_EAGAIN > #!/usr/bin/perl > use warnings; > use strict; > use Log::Syslog::Fast qw(:all); > my $logger = Log::Syslog::Fast->new(LOG_UNIX, '/dev/log', 0, > LOG_USER, LOG_INFO, 'myhost', 'myapp'); > $logger->set_priority(LOG_USER, LOG_DEBUG); > for (1 .. 10000) { > eval { $logger->send('x' x 40) }; > die "[iteration $_] $@\n" if $@; > }
Non-blocking behavior for TCP and UNIX sockets is removed in 0.46.