Malformed email addresses bring server grinding to a halt (exhaust all memory)

[Ben Johnson]

On 6/29/2012 12:28 PM, Mark Martinec wrote:
> Ben,
> 
>>> Which version of amavisd-new was that?
>>
>> amavisd-new-2.6.4 (20090625)
>>
>>> I'm not aware of similar problem with more recent version of amavisd-new,
>>> I'd need to see a log at level 5 if this is the case.
>>
>> Okay, I will try to reproduce the issue at log level 5. Unfortunately,
>> this will bring down the server in question, but if it sheds some light
>> on the root cause, I'm willing to do it.
> 
> If processing of the problem message never completed (crash
> or aborted), the sample message may still be in a MTA queue,
> or preserved in a temporary directory.

This issue occurred three months ago, so the queue has long since been
cleared. =( I do have the Postfix logs, but they appear not to tell us
much about how Amavis responded to this incident.

> So if the same message can reproduce the problem, it should
> suffice to turn up log level for a short time only, for as long
> as the event is captured.

Somewhat humorously, I'm unable to reproduce the issue because
(presumably) Postfix refuses the connection with:

"The mail server responded:  5.1.3 Bad recipient address syntax. Please
check the message recipient 'ben at indietorrent.org' and try again."

Although, I don't see anything added to the Postfix log when this occurs.

At this point, I'm unsure as to how the end-user was able to push his
message through when this happened three months ago.

I would look to the Amavis log, but it seems that the default is to log
Amavis messages using syslogd, and those files are long gone (because
they are rotated so often).

Out of curiosity, why is logging using syslogd "preferred" on Debian
systems, per the below comment?

-----
$DO_SYSLOG = 1;              # log via syslogd (preferred)
-----

I have tried adding the following to /etc/amavis/conf.d/50-user, but the
Amavis daemon seems to lack the permissions required to write to the log
file:

-----
#
# Enable Logging
#

$DO_SYSLOG = 1;
$LOGFILE = "/var/log/amavis.log";  # (defaults to empty, no log)

# Set the log_level to 5 for debugging
$log_level = 1;                # (defaults to 0)
-----

This configuration results in: "Starting amavisd: Failed to open log
file /var/log/amavis.log: Permission denied at /usr/sbin/amavisd-new
line 1965."

If this is so, then how does Amavis write to /var/log/syslog, by
default? These two logs are in the same directory.

Further, I have concerns about log rotation working correctly if I use a
dedicated log file for Amavis; should I not even mess with it, and leave
the defaults alone?

It just seems less-than-ideal to have to wade through everything in
/var/log/syslog and extract the Amavis-specific entries (and yes, I
realize that I could do that programatically) to do any real debugging.

> Alternative is to run amavisd temporarily from a command line
> while capturing its output and stderr:
>   # amavisd debug 2>&1 | tee 0.log
> The 'debug' option implicitly turns up log level all the way.
> 
> Other more complex choices are to bring up another instance
> of amavisd on a dedicated port, but I'll  not go into that
> for the time being.

Yes, let's not trouble ourselves with that until we can actually
reproduce the issue.

>> I'll post back once I've had a chance to reproduce the issue.

Do you have any other ideas as to how we might push a message that
contains these malformed email addresses through?

Out of curiosity, what happens when you try to do the same thing on your
own server? Does the SMTP software refuse the message?

> Thanks!
> 
> 
>   Mark
> 

Thanks again; your help is very much appreciated!

-Ben