JDunphy-Amavisd-Debugging: Difference between revisions

Line 205: Line 205:
exit 0
exit 0
= Reference =

More articles written by me, https://wiki.zimbra.com/wiki/JDunphy-Notes
More articles written by me, https://wiki.zimbra.com/wiki/JDunphy-Notes

Revision as of 20:27, 18 October 2020

Debugging Amavisd Problems

   KB 24179        Last updated on 2020-10-18  

(0 votes)


Zimbra uses Amavisd as a content filter. In general unfiltered email will arrive to amavisd (perl program) at port 10024 and amavisd will call clamav and perform SA classification before returning control back to postifx (amavisd/smtpd) for delivery. For every amavisd configured, you can expect to see one folder representing a running amavisd in /opt/zimbra/data/amavisd/tmp. The contents under these directories represent the last processed email message. Zimbra cron will clean these directories out nightly as will zmantispamctl if you issue a start.

# su - zimbra
% zmprov gs `zmhostname` zimbraAmavisMaxServers 
# name mail.example.com
zimbraAmavisMaxServers: 4


amavisd Logging is sent to /var/log/zimbra.log and additional logging can be enabled with this command with levels 1-5:

% su - zimbra
% zmprov ms `zmhostname` zimbraAmavisLogLevel 3
% zmantispamctl restart

Another Debug mode is available can can be set by modifying /opt/zimbra/common/sbin/amavsid and locating the DEBUG statement and changing the value to 1 from 0 then restarting with zmantispamctl.

%  grep -n 'DEBUG = ' amavisd
720:  $DEBUG = 0;

This will present very detailed information of why something is failing which is especially difficult when a SA module or rules is causing the problem.


/opt/zimbra/data/amavisd - where it works from
/opt/zimbra/common/sbin - daemons
/opt/zimbra/common/bin   - amvis-logwatch

Note: amavis-logwatch can parse /var/log/zimbra.log and make some sense of the logs.

% amavis-logwatch /var/log/zimbra.log

Sample Problems

Postfix will pass email for filtering to amavisd on port 10024 and the resulting filtered email with headers added for SA score, etc will be sent back to postfix (amavsid/smtpd in logs). A common error is when postfix notices that the connection isn't finishing correctly. It is expecting a socket close or an exit. You will see something like this even though amavisd is still working on the message.

% grep END-OF-MESSAGE /var/log/maillog 
Oct 17 13:02:03 relay3 postfix/amavisd/smtpd[5726]: timeout after END-OF-MESSAGE from localhost[]
% grep 13:02:03 /var/log/maillog
Oct 17 13:02:03 relay3 postfix/amavisd/smtpd[5726]: disconnect from localhost[] ehlo=1 mail=1 rcpt=1 data=1 commands=4

If you see an amavisd that is 100% cpu bound, there is a good chance that it is a runaway. In the worse examples, an email has triggered a rule in SA that doesn't finish. Sometimes upgrading SA to a newer version will clear the problem unless you can find the rule causing the issue. In situations like this, you will lose the amavisd and it can take approx 903 seconds (15mins) before it dies and is available for new email processing. The email it was working on will be moved to the deferred queue by postfix. The corresponding log message can be found in /var/log/zimbra.log with a message like this:

Oct 17 12:17:21 relay3 postfix/smtp[1720]: B5D38380E5: to=<user@example.com>, orig_to=<user@mail.example.net>, relay=[]:10024, delay=133927, delays=133023/0/0.01/903, dsn=4.4.2, status=deferred (lost connection with[] while sending end of data -- message may be sent more than once)

Utility Tools

Check various queues and system problems.


# Author: Jim Dunphy <jad aesir.com>
# License (ISC): It's yours. Enjoy
# Date: 10/14/2020

export PATH="/opt/zimbra/common/sbin:/opt/zimbra/common/bin:/opt/zimbra/libexec:/opt/zimbra/bin:$PATH"

# usage: check_queue.sh 

# Reference:
#   http://www.postfix.org/postcat.1.html 
#       postcat -h file (-q searches through queues)
#   http://logreporters.sourceforge.net/faq.html#percentiles
#       postfix-logwatch --limit delivered=1.10 /var/log/zimbra.log  # top 10 list
# Message delivery time stamps
# delays=a/b/c/d, where
#   a = time before queue manager, including message transmission
#   b = time in queue manager
#   c = connection setup including DNS, HELO and TLS;
#   d = message transmission time.
# Bugs: Need to fix postfix_logwatch (change cut to =cut)

. /opt/zimbra/.bashrc

usage() {
  echo "

    *** Example usage: ***

     $ check_queue.sh --list
     $ check_queue.sh --qshape   #active queue
     $ check_queue.sh --qshaped  #deferred queue
     $ check_queue.sh --ldl
     $ check_queue.sh -v QueueID
     $ check_queue.sh --all
     $ check_queue.sh --lh listHoldQueue
     $ check_queue.sh --vi QueueID (from hold queue only)

    *** PostFix Options - need to run as root: ***

       View Email Queued being Processed
       -v|--view QueueId
       --vi QueueId (from hold queue only)

       List All Queues and Counts

       List Active Queue

       List Hold Queue

    *** Amavis Options: ***

       Amavis Stats

    *** Log Options: ***
       --ldl      #list deferred logs (reason)
       --prob     #reject|warning|error|fatal|panic
       --delay    # delay=a/b/c/d
       --plog     # postfix_log



args=$(getopt -l "view:,vi:,delay,help,ldl,lh,la,list,plog,prob,amavis,all,qshape,qshaped" -o "v:hla" -- "$@")

eval set -- "$args"

while [ $# -ge 1 ]; do
        case "$1" in
                    # No more options left.
                        ls /opt/zimbra/data/postfix/spool/active
                        exit 0
                        ls /opt/zimbra/data/postfix/spool/hold
                        exit 0
			grep status=deferred /var/log/zimbra.log
                        exit 0
                        exit 0
                        exit 0
                        postfix-logwatch --detail 6 /var/log/zimbra.log
                        exit 0
                        egrep '(reject|warning|error|fatal|panic):' /var/log/zimbra.log
                        exit 0
                        grep -i smtp /var/log/zimbra.log | grep -ioE 'to=.*status=.*[ \t] ' | tail -10
                        #grep -i smtp /var/log/zimbra.log | grep -ioE 'to=.*status=.*[ \t] ' 
                        exit 0
                        su - zimbra -c "qshape"
                        exit 0
                        su - zimbra -c "qshape deferred"
                        exit 0
                        postcat -q $view
                        vi /opt/zimbra/data/postfix/spool/hold/$view

                        exit 0


exit 0



More articles written by me, https://wiki.zimbra.com/wiki/JDunphy-Notes

Jump to: navigation, search