Re: Amavisd-new and syslog

On May 19, 2007, at 6:29 PM, Jeremy Laidman wrote:

>>pns1walkerclan.us wrote:
>>Hello -
>>
>>    I just installed amavisd-new-2.5.0 on my Mac OS
X system (version
>>10.4.9).  It seems to work fine, except when the
daily log roll happens.
>>When this occurs, logging from amavisd stops for a
while, and then starts
>>up again.

>MacOSX uses postfix right?  Is it possible that postfix
is getting a failure
>trying to connect to localhost (content_filter) while
amavisd is being
>restarted, and so is delaying delivery for a short
while?  Grep your
>/var/log/mail.log for
"status=deferred.*127.0.0.1" around the time of
log
>rotation.
>
>Cheers
>Jeremy

Yes, MaxOSX uses postfix.  I grep'd for this message and I
didn't see it.
I don't think that postfix is getting delayed because I see
log messages
from postfix showing connections and delivery, and even
postfix/lmtp.
My point is that mail still seems to flow, and I'm still
getting log
messages (i.e. from postfix and imapd).  Everything seems to
be working,
except for the logging from amavisd (I even get new
quarantined messages).

Other ideas?  I really think this is a perl/syslog issue,
and I hope there
is a better solution than what I'm trying.

Paul

------------------------------------------------------------
-------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and
take
control of your XML. No limits. Just data. Click to get it
now.
http://sourcefor
ge.net/powerbar/db2/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Paul,

> >>    I just installed amavisd-new-2.5.0 on my
Mac OS X system (version
> >>10.4.9).  It seems to work fine, except when
the daily log roll happens.
> >>When this occurs, logging from amavisd stops
for a while, and then starts
> >>up again.
>
> Yes, MacOSX uses postfix.  I grep'd for this message
and I didn't see it.
> I don't think that postfix is getting delayed because I
see log messages
> from postfix showing connections and delivery, and even
postfix/lmtp.
> My point is that mail still seems to flow, and I'm
still getting log
> messages (i.e. from postfix and imapd).  Everything
seems to be working,
> except for the logging from amavisd (I even get new
quarantined messages).
>
> Other ideas?  I really think this is a perl/syslog
issue, and I hope
> there is a better solution than what I'm trying.

It is quite possible this is a syslog issue (client side).
The problem is that neither the Unix::Syslog nor the
syslog(3)
man page tells anything about status returned or its use of
ERRNO,
so my sub write_log intentionally ignores status and errno
of
a Unix::Syslog::syslog call. This is quite ugly, and could
well explain the problem you are seeing.

Perhaps this is just a documentation omission in
Unix::Syslog
and syslog(3) and a meaningful status _is_ returned - but
since
it is not documented, the behaviour may vary from one Unix
to another.

I'm not sure what would be the best solution. I'd be
interested
if you come up with a reliable solution. Don't forget to
set:
  $! = 0;
before calling Unix::Syslog::syslog, if the intention is to
check the $! after the call.

Note that even if $! is nonzero, there is no guarantee
that some intermediate step within some system routine
would set it to nonzero, but still complete successfully.
This is why system routines return their status as a
function result - with an unfortunate exception of syslog.

  Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and
take
control of your XML. No limits. Just data. Click to get it
now.
http://sourcefor
ge.net/powerbar/db2/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Paul,

could you please try with the following replacement
subroutine write_log:


# Log either to syslog or to a file
sub write_log($$$;) {
  my($level,$am_id,$errmsg,args) = _;
  $am_id = !defined $am_id ? '' : "($am_id) ";
  # treat $errmsg as sprintf format string if additional
arguments provided
  if (args && index($errmsg,'%') >= 0) { $errmsg
= sprintf($errmsg,args) }
  $errmsg = Amavis::Util::sanitize_str($errmsg);
# my($old_locale) = POSIX::setlocale(LC_TIME,"C");
 # English dates required!
# if (length($errmsg) > 2000) {  # crop at some arbitrary
limit (< LINE_MAX)
#   $errmsg = substr($errmsg,0,2000) . "...";
# }
  my($alert_mark) = $level >= 0 ? '' : $level >= -1 ?
'(!)' : '(!!)';
  if ($do_syslog && !$log_to_stderr) {
    # never go below this priority level
    my($prio) =
$syslog_prio_name_to_num{uc(c('syslog_priority'))};
    if    ($level >   2) { $prio = LOG_DEBUG   if $prio
> LOG_DEBUG   }
    elsif ($level >=  1) { $prio = LOG_INFO    if $prio
> LOG_INFO    }
    elsif ($level >=  0) { $prio = LOG_NOTICE  if $prio
> LOG_NOTICE  }
    elsif ($level >= -1) { $prio = LOG_WARNING if $prio
> LOG_WARNING }
    elsif ($level >= -2) { $prio = LOG_ERR     if $prio
> LOG_ERR     }
    else                 { $prio = LOG_CRIT    if $prio >
LOG_CRIT    }
    my($firstlogerr,$lastlogerr); my($retries) = 0;
    for (;;) {  # retry a couple of times in case of syslog
errors
      if (c('syslog_ident')    ne $current_syslog_ident ||
          c('syslog_facility') ne $current_syslog_facility)
{
        close_log()  if !defined($current_syslog_ident)
&&
                        !defined($current_syslog_facility);
        open_log();
      }
      undef $lastlogerr; my($pre) = $alert_mark;
      my($logline_size) = 980;  # less than  (1023 -
prefix)
      while (length($am_id)+length($pre)+length($errmsg)
> $logline_size) {
        my($avail) = $logline_size - length($am_id . $pre .
"...");
        $! = 0;
        syslog($prio, "%s", $am_id . $pre .
substr($errmsg,0,$avail) . "...");
        $lastlogerr = $!  if $! != 0 &&
!defined($lastlogerr);
        $pre = $alert_mark . "...";  $errmsg =
substr($errmsg, $avail);
      }
      $! = 0;  syslog($prio, "%s", $am_id . $pre .
$errmsg);
      $lastlogerr = $!  if $! != 0 &&
!defined($lastlogerr);
      last  if !defined($lastlogerr) || $retries >= 10;
      $firstlogerr =
        $lastlogerr  if defined($lastlogerr) &&
!defined($firstlogerr);
      sleep(1); $retries++;
    }
    if (!defined($lastlogerr) && $retries == 0) {
      # logged successfully on the first attempt
    } elsif (!defined($lastlogerr)) {  # logged on a
subsequent attempt
      syslog(LOG_INFO, "%s",
        sprintf("%sSuccessfully logged after %d
retries: %s",
                 $am_id,$retries,$firstlogerr));
    } else {  # logging failure, desperately try one more
time
      my($msg) = sprintf("%s(!!)Syslog failure, %d
retries: %s",
                         $am_id,$retries,$firstlogerr);
      print STDERR ($msg, "n");
      sleep(10);  syslog(LOG_ERR, "%s", $msg);
    }
  } else {
    my($prefix) = sprintf("%s %s %s[%s]: ",      #
prepare syslog-like prefix
           strftime("%b %e %H:%M:%S",localtime),
c('myhostname'), $myname, $$);
    if (defined $loghandle && !$log_to_stderr) {
      lock($loghandle);
      seek($loghandle,0,2) or die "Can't position log
file to its tail: $!";
      $loghandle->print($prefix, $am_id, $alert_mark,
$errmsg, "n")
        or die "Error writing to log file: $!";
      unlock($loghandle);
    } else {
      print STDERR ($prefix, $am_id, $alert_mark, $errmsg,
"n")
        or die "Error writing to STDERR: $!";
    }
  }
# POSIX::setlocale(LC_TIME, $old_locale);
}


--
  Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and
take
control of your XML. No limits. Just data. Click to get it
now.
http://sourcefor
ge.net/powerbar/db2/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Paul,

> My point is that mail still seems to flow, and I'm
still getting log
> messages (i.e. from postfix and imapd).  Everything
seems to be working,
> except for the logging from amavisd (I even get new
quarantined messages).
>
> Other ideas?  I really think this is a perl/syslog
issue, and I hope there
> is a better solution than what I'm trying.

The 2.5.1-pre1 brings a refinement of the syslog patch I
sent
on Monday. If you have a chance, I'd be interested to know
if it solves the problem.

One indicator of syslog contention is the new counter of
syslog retries. The utility amavisd-agent now shows three
additional indicators. On a busy syslogd, bombarded with
log level 5 logging, it may show something like:

  LogLines          4458915 716900/h 40112.6 % (InMsgs)
  LogRetries            244     39/h     2.2 % (InMsgs)
  ...
  TimeElapsedLogSleep    64 s      0.006 s/msg (InMsgs)

which tells there are about 400 syslog writes (at log level
5)
for each message on the average, that there were 39 retries
per hour on the average, and that the sleeps before each
retry
took 6 ms of inactivity per message on the average.

At log level 2 or above, grepping the log for 'Logged
after'
and 'Syslog failure' would also tell the reason for a
retry.

The relevant text from release notes:

- modified syslog writing to check the (undocumented) status
in errno
  after calling Unix::Syslog::syslog, and to retry a couple
of times
  in case of a failure;  this should prevent or at least
minimize loss
  of logged messages after syslogd daemon is restarted;
unfortunately
  the system routine syslog(3) returns no value according to
documentation,
  so its completion status can not be tested; problem
reported by Paul;

- collect and report statistics on logging, amavisd-agent
now also reports:
    LogLines    ... number of calls to syslog or direct
writes to a log file
    LogRetries  ... number of times a failed syslog call
needed to be retried
    TimeElapsedLogSleep  ... elapsed time in sleep between
syslog retries


Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and
take
control of your XML. No limits. Just data. Click to get it
now.
http://sourcefor
ge.net/powerbar/db2/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/

Paul,

> One problem I did see (and fix) is that syslog returns
an
> empty string if there is no error.

Actually it doesn't. It is explicitly stated in the
documentation
that syslog(3) routine returns no value. And
Unix::Syslog::syslog just
passes-on the result. If anything shows up, it is just a
coincidence.

> So I changed the code you had to use "''"
instead of "0" as the
> test value.  It still sets it to "0" before
the syslog call.

Perl variable $! is double typed: in a numerical context it
returns errno,
in a string context it returns a system error string.
Testing for zero
in a numerical context is cleaner, does not depend on
mapping of an
error number to strings.

> I did some looking at the perl syslog module.  It isn't
pretty,
> and I don't think that code to return an error value is
consistent.
> However, I do think that what you've done should work,
based on my
> limited testing.

I also checked the source of a syslog routine (in FreeBSD
sources,
which should be close to OS X), and it turns out that our
approach
is futile. Ths syslog routine does its own retry on failure,
and
does not care what errno it returns on exit. On a successful
retry
the errno still reflects a previous unsuccessfull attempt.

Checking out amavisd log for the last couple of days
confirms it,
all retries done by amavisd actually resulted in duplicate
log
entries. So I'm abandoning this futile attempts, the
2.5.1-rc1
will no longer do syslog retries.

I also checked Postfix source. No syslog retries there
either.

My guess is that your log rotation stops syslogd for a while
and
restarts it, instead of just renaming files and sending it a
HUP.

Applications really lose their syslog output when syslog
daemon
is unavailable for a while. I've never seen a loss after
sending a HUP to syslog, even though I tried it repeatedly
under a busy logging load.

  Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by DB2 Express
Download DB2 Express C - the FREE version of DB2 express and
take
control of your XML. No limits. Just data. Click to get it
now.
http://sourcefor
ge.net/powerbar/db2/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user

AMaViS-FAQ:http://www.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/