JDunphy-Amavisd-Debugging

Revision as of 19:56, 18 October 2020 by JDunphy (talk | contribs) (Created page with "=Debugging Amavisd Problems= {{KB|{{Unsupported}}|{{ZCS 8.8}}|{{ZCS 8.7}}|{{ZCS 8.6}}|}} {{WIP}} = Introduction = Zimbra uses Amavisd as a content filter. In general unfilte...")

(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)

Debugging Amavisd Problems

   KB 24179        Last updated on 2020-10-18  




0.00
(0 votes)


Introduction

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

10

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.

Directories

/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. 
<pre>
% grep END-OF-MESSAGE /var/log/maillog 
Oct 17 13:02:03 relay3 postfix/amavisd/smtpd[5726]: timeout after END-OF-MESSAGE from localhost[127.0.0.1]
% grep 13:02:03 /var/log/maillog
Oct 17 13:02:03 relay3 postfix/amavisd/smtpd[5726]: disconnect from localhost[127.0.0.1] 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.

Utility Tools

Check various queues and system problems.

#!/bin/bash 

# 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
       --all

       List Active Queue
       -l|--la|--list   

       List Hold Queue
       --lh

    *** Amavis Options: ***

       Amavis Stats
       -a|--amavis

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

    -h|--help

  "
}

#
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.
                    usage
                    shift
                    break
                   ;;
                -l|--la|--list)
                        ls /opt/zimbra/data/postfix/spool/active
                        exit 0
                        ;;
                --lh)
                        ls /opt/zimbra/data/postfix/spool/hold
                        exit 0
                        ;;
                --ldl)
			grep status=deferred /var/log/zimbra.log
                        exit 0
                        ;;
                -a|--amavis)
			amavisd-status
                        exit 0
                        ;;
                --all)
                        /opt/zimbra/libexec/zmqstat
                        exit 0
                        ;;
                --plog)
                        postfix-logwatch --detail 6 /var/log/zimbra.log
                        exit 0
                        ;;
                --prob)
                        egrep '(reject|warning|error|fatal|panic):' /var/log/zimbra.log
                        exit 0
                        ;;
                --delay)
                        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
                        ;;
                --qshape)
                        su - zimbra -c "qshape"
                        exit 0
                        ;;
                --qshaped)
                        su - zimbra -c "qshape deferred"
                        exit 0
                        ;;
		-v|--view)
                        view="$2"
                        postcat -q $view
                        shift
                        exit
                        ;;
		--vi)
                        view="$2"
                        vi /opt/zimbra/data/postfix/spool/hold/$view
                        shift
                        exit
                        ;;

                -h|--help)
                        usage
                        exit 0
                        ;;
        esac

        shift
done

exit 0


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

Jump to: navigation, search