I have setup mailserver using Postfix and Dovecot. Sending is receiving mail is working perfectly. This is email server is running from last couple of years without any issue. Recently we started getting lots of spam so I decided to setup spam and virus filtering and I followed the official guide available at the following link https://help.ubuntu.com/community/PostfixAmavisNew While testing for amavisd-new gives the following output
root@mail:~# telnet localhost 10024
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
220 [127.0.0.1] ESMTP amavisd-new service ready
While running amavisd-new in debug mode I got the following output
root@mail:~# amavisd-new debug
Sep 17 09:35:14.246 .example.com /usr/sbin/amavisd-new[24625]: starting. /usr/sbin/amavisd-new at .example.com amavisd-new-2.6.4 (20090625), Unicode aware, LANG="en_US.UTF-8"
Sep 17 09:35:14.246 .example.com /usr/sbin/amavisd-new[24625]: user=, EUID: 112 (112); group=, EGID: 124 124 (124 124)
Sep 17 09:35:14.246 .example.com /usr/sbin/amavisd-new[24625]: Perl version 5.010001
Sep 17 09:35:14.310 .example.com /usr/sbin/amavisd-new[24625]: SpamControl: attempting to load scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Sep 17 09:35:14.310 .example.com /usr/sbin/amavisd-new[24625]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
Sep 17 09:35:14.869 .example.com /usr/sbin/amavisd-new[24625]: INFO: SA version: 3.3.1, 3.003001, no optional modules: Encode::Detect IP::Country::Fast Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::TIFF
Sep 17 09:35:14.869 .example.com /usr/sbin/amavisd-new[24625]: SpamControl: init_pre_chroot on SpamAssassin done
Sep 17 09:35:14.870 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: 2015/09/17-09:35:14 Amavis (type Net::Server::PreForkSimple) starting! pid(24625)
Sep 17 09:35:14.876 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: Binding to UNIX socket file /var/lib/amavis/amavisd.sock using SOCK_STREAM
Sep 17 09:35:14.877 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1
Sep 17 09:35:14.878 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: Group Not Defined. Defaulting to EGID '124 124'
Sep 17 09:35:14.878 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: User Not Defined. Defaulting to EUID '112'
Sep 17 09:35:14.878 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: Setting up serialization via flock
Sep 17 09:35:14.879 .example.com /usr/sbin/amavisd-new[24625]: after_chroot_init: EUID: 112 (112); EGID: 124 124 (124 124)
Sep 17 09:35:14.880 .example.com /usr/sbin/amavisd-new[24625]: config files read: /usr/share/amavis/conf.d/10-debian_scripts, /usr/share/amavis/conf.d/20-package, /etc/amavis/conf.d/01-debian, /etc/amavis/conf.d/05-domain_id, /etc/amavis/conf.d/05-node_id, /etc/amavis/conf.d/15-av_scanners, /etc/amavis/conf.d/15-content_filter_mode, /etc/amavis/conf.d/20-debian_defaults, /etc/amavis/conf.d/21-ubuntu_defaults, /etc/amavis/conf.d/25-amavis_helpers, /etc/amavis/conf.d/30-template_localization, /etc/amavis/conf.d/40-policy_banks, /etc/amavis/conf.d/50-user
Sep 17 09:35:14.914 .example.com /usr/sbin/amavisd-new[24625]: Module Amavis::Conf 2.207
Sep 17 09:35:14.914 .example.com /usr/sbin/amavisd-new[24625]: Module Archive::Zip 1.30
Sep 17 09:35:14.915 .example.com /usr/sbin/amavisd-new[24625]: Module BerkeleyDB 0.39
Sep 17 09:35:14.915 .example.com /usr/sbin/amavisd-new[24625]: Module Compress::Zlib 2.02
Sep 17 09:35:14.915 .example.com /usr/sbin/amavisd-new[24625]: Module Convert::TNEF 0.17
Sep 17 09:35:14.915 .example.com /usr/sbin/amavisd-new[24625]: Module Convert::UUlib 1.12
Sep 17 09:35:14.915 .example.com /usr/sbin/amavisd-new[24625]: Module Crypt::OpenSSL::RSA 0.25
Sep 17 09:35:14.916 .example.com /usr/sbin/amavisd-new[24625]: Module DBD::mysql 4.012
Sep 17 09:35:14.916 .example.com /usr/sbin/amavisd-new[24625]: Module DBI 1.609
Sep 17 09:35:14.916 .example.com /usr/sbin/amavisd-new[24625]: Module DB_File 1.82
Sep 17 09:35:14.916 .example.com /usr/sbin/amavisd-new[24625]: Module Digest::MD5 2.39
Sep 17 09:35:14.916 .example.com /usr/sbin/amavisd-new[24625]: Module Digest::SHA 5.47
Sep 17 09:35:14.916 .example.com /usr/sbin/amavisd-new[24625]: Module Digest::SHA1 2.12
Sep 17 09:35:14.917 .example.com /usr/sbin/amavisd-new[24625]: Module IO::Socket::INET6 2.54
Sep 17 09:35:14.918 .example.com /usr/sbin/amavisd-new[24625]: Module MIME::Entity 5.427
Sep 17 09:35:14.918 .example.com /usr/sbin/amavisd-new[24625]: Module MIME::Parser 5.427
Sep 17 09:35:14.918 .example.com /usr/sbin/amavisd-new[24625]: Module MIME::Tools 5.427
Sep 17 09:35:14.919 .example.com /usr/sbin/amavisd-new[24625]: Module Mail::DKIM::Signer 0.38
Sep 17 09:35:14.919 .example.com /usr/sbin/amavisd-new[24625]: Module Mail::DKIM::Verifier 0.38
Sep 17 09:35:14.919 .example.com /usr/sbin/amavisd-new[24625]: Module Mail::Header 2.05
Sep 17 09:35:14.919 .example.com /usr/sbin/amavisd-new[24625]: Module Mail::Internet 2.05
Sep 17 09:35:14.919 .example.com /usr/sbin/amavisd-new[24625]: Module Mail::SPF v2.007
Sep 17 09:35:14.920 .example.com /usr/sbin/amavisd-new[24625]: Module Mail::SpamAssassin 3.003001
Sep 17 09:35:14.921 .example.com /usr/sbin/amavisd-new[24625]: Module Net::DNS 0.65
Sep 17 09:35:14.922 .example.com /usr/sbin/amavisd-new[24625]: Module Net::Server 0.97
Sep 17 09:35:14.922 .example.com /usr/sbin/amavisd-new[24625]: Module NetAddr::IP 4.024
Sep 17 09:35:14.922 .example.com /usr/sbin/amavisd-new[24625]: Module Razor2::Client::Version 2.84
Sep 17 09:35:14.923 .example.com /usr/sbin/amavisd-new[24625]: Module Socket6 0.23
Sep 17 09:35:14.923 .example.com /usr/sbin/amavisd-new[24625]: Module Time::HiRes 1.9719
Sep 17 09:35:14.923 .example.com /usr/sbin/amavisd-new[24625]: Module URI 1.52
Sep 17 09:35:14.924 .example.com /usr/sbin/amavisd-new[24625]: Module Unix::Syslog 1.1
Sep 17 09:35:14.924 .example.com /usr/sbin/amavisd-new[24625]: Amavis::DB code loaded
Sep 17 09:35:14.924 .example.com /usr/sbin/amavisd-new[24625]: Amavis::Cache code loaded
Sep 17 09:35:14.924 .example.com /usr/sbin/amavisd-new[24625]: SQL base code NOT loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: SQL::Log code NOT loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: SQL::Quarantine NOT loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: Lookup::SQL code NOT loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: Lookup::LDAP code NOT loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: AM.PDP-in proto code loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: SMTP-in proto code loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: Courier proto code NOT loaded
Sep 17 09:35:14.925 .example.com /usr/sbin/amavisd-new[24625]: SMTP-out proto code loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: Pipe-out proto code NOT loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: BSMTP-out proto code NOT loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: Local-out proto code loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: OS_Fingerprint code NOT loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: ANTI-VIRUS code loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: ANTI-SPAM code loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: ANTI-SPAM-EXT code NOT loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: ANTI-SPAM-C code NOT loaded
Sep 17 09:35:14.926 .example.com /usr/sbin/amavisd-new[24625]: ANTI-SPAM-SA code loaded
Sep 17 09:35:14.927 .example.com /usr/sbin/amavisd-new[24625]: Unpackers code loaded
Sep 17 09:35:14.927 .example.com /usr/sbin/amavisd-new[24625]: DKIM code loaded
Sep 17 09:35:14.927 .example.com /usr/sbin/amavisd-new[24625]: Tools code NOT loaded
Sep 17 09:35:14.927 .example.com /usr/sbin/amavisd-new[24625]: Found $file at /usr/bin/file
Sep 17 09:35:14.927 .example.com /usr/sbin/amavisd-new[24625]: No $altermime, not using it
Sep 17 09:35:14.928 .example.com /usr/sbin/amavisd-new[24625]: Internal decoder for .mail
Sep 17 09:35:14.928 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .F
Sep 17 09:35:14.928 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .Z at /bin/uncompress
Sep 17 09:35:14.928 .example.com /usr/sbin/amavisd-new[24625]: Internal decoder for .gz
Sep 17 09:35:14.928 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .gz at /bin/gzip -d (backup, not used)
Sep 17 09:35:14.929 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .bz2 at /bin/bzip2 -d
Sep 17 09:35:14.929 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .lzo tried: lzop -d
Sep 17 09:35:14.929 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .rpm tried: rpm2cpio.pl, rpm2cpio
Sep 17 09:35:14.929 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .cpio at /usr/bin/pax
Sep 17 09:35:14.930 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .cpio at /bin/cpio (backup, not used)
Sep 17 09:35:14.930 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .tar at /usr/bin/pax
Sep 17 09:35:14.930 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .tar at /bin/cpio (backup, not used)
Sep 17 09:35:14.930 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .deb at /usr/bin/ar
Sep 17 09:35:14.930 .example.com /usr/sbin/amavisd-new[24625]: Internal decoder for .zip
Sep 17 09:35:14.931 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .7z tried: 7zr, 7za, 7z
Sep 17 09:35:14.931 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .rar tried: unrar-free
Sep 17 09:35:14.931 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .arj at /usr/bin/arj
Sep 17 09:35:14.932 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .arc at /usr/bin/nomarch
Sep 17 09:35:14.932 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .zoo at /usr/bin/zoo
Sep 17 09:35:14.932 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .lha
Sep 17 09:35:14.932 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .doc tried: ripole
Sep 17 09:35:14.932 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .cab at /usr/bin/cabextract
Sep 17 09:35:14.932 .example.com /usr/sbin/amavisd-new[24625]: No decoder for .tnef
Sep 17 09:35:14.933 .example.com /usr/sbin/amavisd-new[24625]: Internal decoder for .tnef
Sep 17 09:35:14.933 .example.com /usr/sbin/amavisd-new[24625]: Found decoder for .exe at /usr/bin/arj
Sep 17 09:35:14.933 .example.com /usr/sbin/amavisd-new[24625]: Using primary internal av scanner code for ClamAV-clamd
Sep 17 09:35:14.933 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: KasperskyLab AVP - aveclient
Sep 17 09:35:14.934 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: KasperskyLab AntiViral Toolkit Pro (AVP)
Sep 17 09:35:14.934 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: KasperskyLab AVPDaemonClient
Sep 17 09:35:14.934 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: CentralCommand Vexira (new) vascan
Sep 17 09:35:14.935 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: Avira AntiVir
Sep 17 09:35:14.935 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: Command AntiVirus for Linux
Sep 17 09:35:14.935 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: Symantec CarrierScan via Symantec CommandLineScanner
Sep 17 09:35:14.935 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: Symantec AntiVirus Scan Engine
Sep 17 09:35:14.936 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: F-Secure Antivirus for Linux servers
Sep 17 09:35:14.936 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: CAI InoculateIT
Sep 17 09:35:14.936 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: CAI eTrust Antivirus
Sep 17 09:35:14.936 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: MkS_Vir for Linux (beta)
Sep 17 09:35:14.937 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: MkS_Vir daemon
Sep 17 09:35:14.937 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: ESET Software ESETS Command Line Interface
Sep 17 09:35:14.937 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: ESET NOD32 for Linux File servers
Sep 17 09:35:14.937 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: Norman Virus Control v5 / Linux
Sep 17 09:35:14.938 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: Panda CommandLineSecure 9 for Linux
Sep 17 09:35:14.938 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: NAI McAfee AntiVirus (uvscan)
Sep 17 09:35:14.938 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: VirusBuster
Sep 17 09:35:14.938 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: CyberSoft VFind
Sep 17 09:35:14.939 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: avast! Antivirus
Sep 17 09:35:14.939 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: Ikarus AntiVirus for Linux
Sep 17 09:35:14.939 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: BitDefender
Sep 17 09:35:14.939 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: BitDefender
Sep 17 09:35:14.940 .example.com /usr/sbin/amavisd-new[24625]: No primary av scanner: ArcaVir for Linux
Sep 17 09:35:14.940 .example.com /usr/sbin/amavisd-new[24625]: Found secondary av scanner ClamAV-clamscan at /usr/bin/clamscan
Sep 17 09:35:14.940 .example.com /usr/sbin/amavisd-new[24625]: No secondary av scanner: F-PROT Antivirus for UNIX
Sep 17 09:35:14.940 .example.com /usr/sbin/amavisd-new[24625]: No secondary av scanner: FRISK F-Prot Antivirus
Sep 17 09:35:14.940 .example.com /usr/sbin/amavisd-new[24625]: No secondary av scanner: Trend Micro FileScanner
Sep 17 09:35:14.941 .example.com /usr/sbin/amavisd-new[24625]: No secondary av scanner: drweb - DrWeb Antivirus
Sep 17 09:35:14.941 .example.com /usr/sbin/amavisd-new[24625]: No secondary av scanner: Kaspersky Antivirus v5.5
Sep 17 09:35:14.941 .example.com /usr/sbin/amavisd-new[24625]: Using internal spam scanner code for SpamAssassin
Sep 17 09:35:14.949 .example.com /usr/sbin/amavisd-new[24625]: Creating db in /var/lib/amavis/db/; BerkeleyDB 0.39, libdb 4.8
Sep 17 09:35:14.960 .example.com /usr/sbin/amavisd-new[24625]: initializing Mail::SpamAssassin
Sep 17 09:35:14.961 .example.com /usr/sbin/amavisd-new[24625]: SpamAssassin debug facilities: info
Sep 17 09:35:20.556 .example.com /usr/sbin/amavisd-new[24625]: SpamAssassin loaded plugins: AutoLearnThreshold, Bayes, BodyEval, Check, DKIM, DNSEval, FreeMail, HTMLEval, HTTPSMismatch, Hashcash, HeaderEval, ImageInfo, MIMEEval, MIMEHeader, Pyzor, Razor2, RelayEval, ReplaceTags, SPF, SpamCop, URIDNSBL, URIDetail, URIEval, VBounce, WLBLEval, WhiteListSubject
Sep 17 09:35:20.557 .example.com /usr/sbin/amavisd-new[24625]: SpamControl: init_pre_fork on SpamAssassin done
Sep 17 09:35:20.558 .example.com /usr/sbin/amavisd-new[24625]: extra modules loaded after daemonizing/chrooting: Mail/SpamAssassin/Plugin/FreeMail.pm
Sep 17 09:35:20.560 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: Beginning prefork (2 processes)
Sep 17 09:35:20.560 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: Starting "2" children
Sep 17 09:35:20.569 .example.com /usr/sbin/amavisd-new[24641]: Net::Server: Child Preforked (24641)
Sep 17 09:35:20.570 .example.com /usr/sbin/amavisd-new[24641]: entered child_init_hook
Sep 17 09:35:20.571 .example.com /usr/sbin/amavisd-new[24625]: Net::Server: Parent ready for children.
Sep 17 09:35:20.572 .example.com /usr/sbin/amavisd-new[24642]: Net::Server: Child Preforked (24642)
Sep 17 09:35:20.573 .example.com /usr/sbin/amavisd-new[24642]: entered child_init_hook
Sep 17 09:35:20.582 .example.com /usr/sbin/amavisd-new[24641]: TIMING [total 12 ms] - bdb-open: 12 (100%)100, rundown: 0 (0%)100
Sep 17 09:35:20.584 .example.com /usr/sbin/amavisd-new[24641]: SpamControl: init_child on SpamAssassin done
Sep 17 09:35:20.584 .example.com /usr/sbin/amavisd-new[24642]: TIMING [total 11 ms] - bdb-open: 11 (100%)100, rundown: 0 (0%)100
Sep 17 09:35:20.586 .example.com /usr/sbin/amavisd-new[24642]: SpamControl: init_child on SpamAssassin done
But spam filtering and virus scanning is not happening. I dont see any X-Spam headers in the incoming messages. I cant seem to figure out that what I am doing wrong. If anyone have solution then that would be great.
I am using UBUNTU-10.04 Server edition
