Bug 6028 - [review] Logger in infinite loop when logging encounters an error
Summary: [review] Logger in infinite loop when logging encounters an error
Status: RESOLVED FIXED
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: Libraries (show other bugs)
Version: SVN Trunk (Latest Devel Version)
Hardware: All All
: P5 normal
Target Milestone: 3.3.0
Assignee: SpamAssassin Developer Mailing List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-12-10 03:41 UTC by Mark Martinec
Modified: 2009-01-07 02:20 UTC (History)
0 users



Attachment Type Modified Status Actions Submitter/CLA Status

Note You need to log in before you can comment on or make changes to this bug.
Description Mark Martinec 2008-12-10 03:41:32 UTC
I'm opening this PR to explain my change r724958.

The immediate problem the change solves is that a command-line
'spamassassin -D' when piping its stderr and stdout into another
program like more(1) or less(1) can enter an infinite loop
when a pipe breaks.

In my particular case I admit the problem was caused by my
addition of a call to 'warn' in Logger::Stderr::log_message,
so if print failed a warn was called, which was intercepted
by a __WARN__ handler and log_message called again.

Several solutions come to mind:
- ban calling warn or die or dbg from any routine that may be
  called from Logger::log_message. That is doable, but requires
  some discipline, and if a caller supplies his own logging
  modules we still have no control over it;
- override __WARN__ and __DIE__ handlers within Logger::log_message
- or like I did, add a flag (poor man semaphore) to protect
  the inside of Logger::log_message from re-entering.

Probably the #2 is cleanest, but I thought testing and flipping
a single boolean scalar is the cheapest, so I chose #3.


I also added a:
  local $SIG{PIPE} = 'IGNORE';
into Logger::Stderr::log_message to prevent broken pipe signalling,
but I'm now considering reverting that change because is is not
particularly lightweight, involving several system service calls.
I see that sa-learn.raw and spamassassin.raw already neutralize
the PIPE signal, so it is unnecessary to do it again in logger,
although I'm not sure about other callers (spamd, mass-check,
third-party code).
Comment 1 Justin Mason 2008-12-10 03:49:05 UTC
(In reply to comment #0)
> I'm opening this PR to explain my change r724958.
> 
> The immediate problem the change solves is that a command-line
> 'spamassassin -D' when piping its stderr and stdout into another
> program like more(1) or less(1) can enter an infinite loop
> when a pipe breaks.
> 
> In my particular case I admit the problem was caused by my
> addition of a call to 'warn' in Logger::Stderr::log_message,
> so if print failed a warn was called, which was intercepted
> by a __WARN__ handler and log_message called again.
> 
> Several solutions come to mind:
> - ban calling warn or die or dbg from any routine that may be
>   called from Logger::log_message. That is doable, but requires
>   some discipline, and if a caller supplies his own logging
>   modules we still have no control over it;
> - override __WARN__ and __DIE__ handlers within Logger::log_message
> - or like I did, add a flag (poor man semaphore) to protect
>   the inside of Logger::log_message from re-entering.
> 
> Probably the #2 is cleanest, but I thought testing and flipping
> a single boolean scalar is the cheapest, so I chose #3.

cool, fine by me.  +1

Thanks for the explanation!


> I also added a:
>   local $SIG{PIPE} = 'IGNORE';
> into Logger::Stderr::log_message to prevent broken pipe signalling,
> but I'm now considering reverting that change because is is not
> particularly lightweight, involving several system service calls.
> I see that sa-learn.raw and spamassassin.raw already neutralize
> the PIPE signal, so it is unnecessary to do it again in logger,
> although I'm not sure about other callers (spamd, mass-check,
> third-party code).

I agree that reverting it would be best.  The callers need to monitor the status of SIGPIPE, imo; it's not appropriate for the logging code to do it, and as you note, it imposes a performance penalty.
Comment 2 Mark Martinec 2008-12-11 03:37:35 UTC
> > I also added a:
> >   local $SIG{PIPE} = 'IGNORE';
> > into Logger::Stderr::log_message to prevent broken pipe signalling,
> > but I'm now considering reverting that change ...
> 
> I agree that reverting it would be best.  The callers need to monitor the
> status of SIGPIPE, imo; it's not appropriate for the logging code to do it,
> and as you note, it imposes a performance penalty.

Ok, done that.

$ svn -m 'Logger/Stderr.pm: remove expensive neutralization of $SIG{PIPE}
  (bug 6028, partially reverting r724958)' ci
Sending        lib/Mail/SpamAssassin/Logger/Stderr.pm
Committed revision 725664.
Comment 3 Mark Martinec 2009-01-06 16:41:48 UTC
Ok, so this is fixed now in 3.3.
Do I just close this PR, or does it need voting?
Comment 4 Justin Mason 2009-01-07 02:20:19 UTC
(In reply to comment #3)
> Ok, so this is fixed now in 3.3.
> Do I just close this PR, or does it need voting?

just close.  hey, I'll do it for you since I'm here anyway ;)