Amavis 2.10.1 dies and is unusable when put under moderate load

[Quanah Gibson-Mount]

--On Thursday, January 21, 2016 11:08 AM -0800 Quanah Gibson-Mount 
<quanah at zimbra.com> wrote:

> To be clear, this happens on any server (we have hundreds) if we put
> amavis under load.  They have plenty of memory, and are not running out.
> I think this is related to the changes made here:
>
> - use a perl module File::LibMagic when available, instead of spawning
>   a file(1) utility for classifying contents of mail parts.
>   By using a direct interface to a libmagic library the startup cost
>   of spawning an external process is avoided. Benchmarking shows that
>   using libmagic is significantly faster especially for checking a small
>   number of files - takes 4 ms for checking one file with libmagic
>   vs. 27 ms with a spawned file(1); based on a patch by Markus Benning;
>
> or possibly this:
>
>
> - adjusted some timeouts to leave more reserve for later stages of
>   mail processing and forwarding;

Switching to File::LibMagic reduced the failure rate from 6% to 3%, so that 
helped some.  It appears as though the reworking really broke the usage of 
the "file" binary vs previous versions of Amavisd.  Users be warned.

However, we continue to get a 3% error rate, which really is not 
acceptable.  In the latest run, we again see:

Jan 25 06:40:41 zqa-211 amavis[8673]: (08673-01-13) lookup_re("HTML 
document, ASCII text, with very long lines") matches key 
"(?^i:\\btext\\b)", result="asc"
Jan 25 06:40:41 zqa-211 amavis[8673]: (08673-01-13) lookup 
[map_full_type_to_short_type] => true,  "HTML document, ASCII text, with 
very long lines" matches, result="asc", matching_key="(?^i:\\btext\\b)"
Jan 25 06:40:41 zqa-211 amavis[8673]: (08673-01-13) File-type of p001: HTML 
document, ASCII text, with very long lines; (asc)
Jan 25 06:40:41 zqa-211 amavis[8673]: (08673-01-13) do_ascii: Decoding part 
p001
Jan 25 06:40:41 zqa-211 amavis[8673]: (08673-01-13) do_ascii: Setting 
sigaction handler, was 0
Jan 25 06:40:41 zqa-211 amavis[8673]: (08673-01-13) get_deadline 
do_ascii_pre - deadline in 479.8 s, set to 288.000 s
Jan 25 06:40:41 zqa-211 amavis[8673]: (08673-01-13) prolong_timer 
do_ascii_pre: timer 288, was 0, deadline in 479.8 s
Jan 25 06:40:52 zqa-211 amavis-services[22436]: PID 8673 went away, 
08673-01-13

So there seems to be some bug in do_ascii_pre itself as well.  I'll see how 
the function has changed vs 2.9.0 next, I guess.

It would be really helpful if the amavisd source was in a publicly 
accessible SCM like github.

--Quanah



--

Quanah Gibson-Mount
Platform Architect
Zimbra, Inc.
--------------------
Zimbra ::  the leader in open source messaging and collaboration