NethServer Version: 6.8
Module: email
A primary, production email server, ns6.8, originally running with Anti-virus but Not Anti-spam, in an attempt to deal with endless .top spam, I noted that the rbl that amavis uses seems to be set to mark .top mail as spam, so I thought I’d try the Anti-spam. It didn’t work out, in addition, users sending mail were seeing long send times and timeouts correlating with high server load and clam av scanner fails. So I unchecked Anti-spam.
Now, with Anti-spam off, and having rebooted the server, NS is still sorting mail into junk, it shouldn’t be doing this.
Would you guys mind looking through the logs to see what you see?
Post reboot;
Apr 14 13:15:36 server9b amavis[2063]: SpamControl: init_pre_chroot on SpamAssassin done
Apr 14 13:15:36 server9b amavis[2063]: socket module IO::Socket::INET6, protocol families available: INET, INET6
Apr 14 13:15:36 server9b amavis[2063]: bind to 127.0.0.100:10024/tcp, 127.0.0.1:10024/tcp, [::1]:10024/tcp
Apr 14 13:15:36 server9b amavis[2066]: Net::Server: Process Backgrounded
Apr 14 13:15:36 server9b amavis[2066]: Net::Server: 2017/04/14-13:15:36 Amavis (type Net::Server::PreFork) starting! pid(2066)
Apr 14 13:15:36 server9b amavis[2066]: Net::Server: Binding to TCP port 10024 on host 127.0.0.100 with IPv4
Apr 14 13:15:36 server9b amavis[2066]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Apr 14 13:15:36 server9b amavis[2066]: Net::Server: Binding to TCP port 10024 on host ::1 with IPv6
Apr 14 13:15:36 server9b amavis[2066]: Net::Server: Group Not Defined. Defaulting to EGID ‘494 493 494’
Apr 14 13:15:36 server9b amavis[2066]: Net::Server: User Not Defined. Defaulting to EUID ‘494’
Apr 14 13:15:36 server9b amavis[2066]: config files read: /etc/amavisd.conf
Apr 14 13:15:36 server9b amavis[2066]: Module Amavis::Conf 2.321
Apr 14 13:15:36 server9b amavis[2066]: Module Archive::Zip 1.30
Apr 14 13:15:36 server9b amavis[2066]: Module Compress::Raw::Zlib 2.021
Apr 14 13:15:36 server9b amavis[2066]: Module Compress::Zlib 2.021
Apr 14 13:15:36 server9b amavis[2066]: Module Crypt::OpenSSL::RSA 0.25
Apr 14 13:15:36 server9b amavis[2066]: Module DB_File 1.82
Apr 14 13:15:36 server9b amavis[2066]: Module Digest::MD5 2.39
Apr 14 13:15:36 server9b amavis[2066]: Module Digest::SHA 5.47
Apr 14 13:15:36 server9b amavis[2066]: Module Encode 2.35
Apr 14 13:15:36 server9b amavis[2066]: Module File::Temp 0.22
Apr 14 13:15:36 server9b amavis[2066]: Module IO::Socket::INET6 2.56
Apr 14 13:15:36 server9b amavis[2066]: Module MIME::Entity 5.427
Apr 14 13:15:36 server9b amavis[2066]: Module MIME::Parser 5.427
Apr 14 13:15:36 server9b amavis[2066]: Module MIME::Tools 5.427
Apr 14 13:15:36 server9b amavis[2066]: Module Mail::DKIM::Verifier 0.37
Apr 14 13:15:36 server9b amavis[2066]: Module Mail::Header 2.04
Apr 14 13:15:36 server9b amavis[2066]: Module Mail::Internet 2.04
Apr 14 13:15:36 server9b amavis[2066]: Module Mail::SPF v2.008
Apr 14 13:15:36 server9b amavis[2066]: Module Mail::SpamAssassin 3.004001
Apr 14 13:15:36 server9b amavis[2066]: Module Net::DNS 0.65
Apr 14 13:15:36 server9b amavis[2066]: Module Net::Server 2.007
Apr 14 13:15:36 server9b amavis[2066]: Module NetAddr::IP 4.027
Apr 14 13:15:36 server9b amavis[2066]: Module Razor2::Client::Version 2.84
Apr 14 13:15:36 server9b amavis[2066]: Module Scalar::Util 1.21
Apr 14 13:15:36 server9b amavis[2066]: Module Socket 1.82
Apr 14 13:15:36 server9b amavis[2066]: Module Socket6 0.23
Apr 14 13:15:36 server9b amavis[2066]: Module Time::HiRes 1.9721
Apr 14 13:15:36 server9b amavis[2066]: Module URI 1.40
Apr 14 13:15:36 server9b amavis[2066]: Module Unix::Syslog 1.1
Apr 14 13:15:36 server9b amavis[2066]: Amavis::ZMQ code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: Amavis::DB code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: SQL base code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: SQL::Log code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: SQL::Quarantine NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: Lookup::SQL code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: Lookup::LDAP code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: AM.PDP-in proto code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: SMTP-in proto code loaded
Apr 14 13:15:36 server9b amavis[2066]: Courier proto code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: SMTP-out proto code loaded
Apr 14 13:15:36 server9b amavis[2066]: Pipe-out proto code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: BSMTP-out proto code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: Local-out proto code loaded
Apr 14 13:15:36 server9b amavis[2066]: OS_Fingerprint code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: ANTI-VIRUS code loaded
Apr 14 13:15:36 server9b amavis[2066]: ANTI-SPAM code loaded
Apr 14 13:15:36 server9b amavis[2066]: ANTI-SPAM-EXT code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: ANTI-SPAM-C code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: ANTI-SPAM-SA code loaded
Apr 14 13:15:36 server9b amavis[2066]: Unpackers code loaded
Apr 14 13:15:36 server9b amavis[2066]: DKIM code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: Tools code NOT loaded
Apr 14 13:15:36 server9b amavis[2066]: Found $file at /usr/bin/file
Apr 14 13:15:36 server9b amavis[2066]: Found $altermime at /usr/bin/altermime
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .mail
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .asc
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .uue
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .hqx
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .ync
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .F at /usr/bin/unfreeze
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .Z at /usr/bin/gzip -d
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .gz at /usr/bin/gzip -d
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .gz (backup, not used)
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .bz2 at /usr/bin/bzip2 -d
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .lzo at /usr/bin/lzop -d
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .rpm at /usr/bin/rpm2cpio
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .cpio at /usr/bin/pax
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .tar at /usr/bin/pax
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .deb at /usr/bin/ar
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .zip
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .7z at /usr/bin/7za
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .rar at /usr/bin/unrar
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .arj at /usr/bin/arj
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .arc at /usr/bin/nomarch
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .zoo at /usr/bin/unzoo
Apr 14 13:15:36 server9b amavis[2066]: No ext program for .lha, tried: lha
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .doc at /usr/bin/ripole
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .cab at /usr/bin/cabextract
Apr 14 13:15:36 server9b amavis[2066]: No ext program for .tnef, tried: tnef
Apr 14 13:15:36 server9b amavis[2066]: Internal decoder for .tnef
Apr 14 13:15:36 server9b amavis[2066]: Found decoder for .exe at /usr/bin/unrar
Apr 14 13:15:36 server9b amavis[2066]: No decoder for .lha
Apr 14 13:15:36 server9b amavis[2066]: Using primary internal av scanner code for ClamAV-clamd
Apr 14 13:15:36 server9b amavis[2066]: initializing Mail::SpamAssassin (0)
Apr 14 13:15:36 server9b amavis[2066]: SpamAssassin debug facilities: info
Apr 14 13:15:38 server9b postfix/postfix-script[2147]: starting the Postfix mail system
Apr 14 13:15:38 server9b postfix/master[2149]: daemon started – version 2.10.3, configuration /etc/postfix
Apr 14 13:15:41 server9b amavis[2066]: SpamAssassin loaded plugins: AskDNS, 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
Apr 14 13:15:41 server9b amavis[2066]: SpamControl: init_pre_fork on SpamAssassin done
Apr 14 13:15:41 server9b amavis[2066]: extra modules loaded after daemonizing/chrooting: /usr/lib64/perl5/auto/NetAddr/IP/Util/inet_n2dx.al, /usr/lib64/perl5/auto/NetAddr/IP/Util/ipv6_n2d.al, /usr/lib64/perl5/auto/NetAddr/IP/Util/ipv6_n2x.al, /usr/share/perl5/Net/libnet.cfg, Mail/SpamAssassin/Plugin/FreeMail.pm, Mail/SpamAssassin/Plugin/SpamCop.pm, Net/Cmd.pm, Net/Config.pm, Net/SMTP.pm`
Clam error;
Apr 14 12:52:57 server9b amavis[28039]: (28039-26) (!)ClamAV-clamd av-scanner FAILED: run_av error: ask_daemon_internal: Exceeded allowed time at (eval 99) line 606.\n Apr 14 12:52:57 server9b amavis[28039]: (28039-26) (!)WARN: all primary virus scanners failed, considering backups Apr 14 12:52:57 server9b amavis[28039]: (28039-26) (!!)AV: ALL VIRUS SCANNERS FAILED Apr 14 12:52:57 server9b amavis[28039]: (28039-26) (!!)TROUBLE in check_mail: virus_scan FAILED: AV: ALL VIRUS SCANNERS FAILED
Clam log;
`
Fri Apr 14 11:55:28 2017 -> Reading databases from /var/lib/clamav
Fri Apr 14 11:55:46 2017 -> Database correctly reloaded (6409137 signatures)
Fri Apr 14 12:06:06 2017 -> SelfCheck: Database status OK.
Fri Apr 14 12:17:56 2017 -> SelfCheck: Database status OK.
Fri Apr 14 12:30:59 2017 -> SelfCheck: Database status OK.
Fri Apr 14 12:44:42 2017 -> SelfCheck: Database status OK.
Fri Apr 14 12:54:20 2017 -> Reading databases from /var/lib/clamav
Fri Apr 14 12:54:42 2017 -> Database correctly reloaded (6409147 signatures)`
Email sent to junk that shouldn’t be (it is junk though);
`
Apr 14 13:26:32 server9b transfer/smtpd[2820]: connect from garnished.pnnmist.top[216.245.203.27]
Apr 14 13:26:33 server9b transfer/smtpd[2820]: NOQUEUE: client=garnished.pnnmist.top[216.245.203.27]
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) ESMTP:[127.0.0.1]:10024 /var/spool/amavisd/tmp/amavis-20170414T132347-02827-t_Jdwi0a: Home.Solar.Installation@garnished.pnnmist.top -> user@domain.com RET=HDRS Received: from server9b.domain.com ([127.0.0.1]) by localhost (server9b.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for user@domain.com; Fri, 14 Apr 2017 13:26:33 -0700 (MST)
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) Checking: 6ymLZeFrIIlK [216.245.203.27] Home.Solar.Installation@garnished.pnnmist.top -> user@domain.com
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) p003 1 Content-Type: multipart/alternative
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) p001 1/1 Content-Type: text/plain, size: 101 B, name:
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) p002 1/2 Content-Type: text/html, size: 3860 B, name:
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) mangling NO: 0 (was: disclaimer), discl_allowed=0, Home.Solar.Installation@garnished.pnnmist.top -> user@domain.com
Apr 14 13:26:33 server9b queue/smtpd[3343]: connect from localhost[127.0.0.1]
Apr 14 13:26:33 server9b queue/smtpd[3343]: 9B92EE387F: client=localhost[127.0.0.1], orig_client=garnished.pnnmist.top[216.245.203.27]
Apr 14 13:26:33 server9b postfix/cleanup[3345]: 9B92EE387F: message-id=4515310d513e10d542945a1d76a6fde3.Splinter.Brooms.user@domain.com
Apr 14 13:26:33 server9b postfix/qmgr[2152]: 9B92EE387F: from=Home.Solar.Installation@garnished.pnnmist.top, size=5347, nrcpt=1 (queue active)
Apr 14 13:26:33 server9b queue/smtpd[3343]: disconnect from localhost[127.0.0.1]
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) 6ymLZeFrIIlK FWD from Home.Solar.Installation@garnished.pnnmist.top -> user@domain.com, RET=HDRS BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 9B92EE387F
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) Passed CLEAN {RelayedInbound}, [216.245.203.27]:40088 [216.245.203.27] Home.Solar.Installation@garnished.pnnmist.top -> user@domain.com, Message-ID: 4515310d513e10d542945a1d76a6fde3.Splinter.Brooms.user@domain.com, mail_id: 6ymLZeFrIIlK, Hits: -, size: 4878, queued_as: 9B92EE387F, 292 ms
Apr 14 13:26:33 server9b transfer/smtpd[2820]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 9B92EE387F; from=Home.Solar.Installation@garnished.pnnmist.top to=user@domain.com proto=ESMTP helo=<garnished.pnnmist.top>
Apr 14 13:26:33 server9b amavis[2827]: (02827-02) size: 4878, TIMING [total 293 ms] - SMTP greeting: 0.8 (0%)0, SMTP EHLO: 0.4 (0%)0, SMTP pre-MAIL: 0.2 (0%)0, SMTP pre-DATA-flush: 24 (8%)9, SMTP DATA: 0.2 (0%)9, check_init: 0.1 (0%)9, digest_hdr: 0.2 (0%)9, digest_body: 0.1 (0%)9, collect_info: 0.7 (0%)9, mime_decode: 4.2 (1%)10, get-file-type2: 42 (14%)25, decompose_part: 0.4 (0%)25, parts_decode: 0.1 (0%)25, check_header: 0.3 (0%)25, AV-scan-1: 141 (48%)73, decide_mail_destiny: 0.4 (0%)73, notif-quar: 0.5 (0%)73, fwd-connect: 24 (8%)81, fwd-xforward: 0.2 (0%)82, fwd-mail-pip: 7 (2%)84, fwd-rcpt-pip: 0.1 (0%)84, fwd-data-chkpnt: 0.0 (0%)84, write-header: 0.2 (0%)84, fwd-data-contents: 0.1 (0%)84, fwd-end-chkpnt: 40 (14%)98, prepare-dsn: 0.5 (0%)98, report: 1.2 (0%)98, main_log_entry: 3.5 (1%)100, SMTP pre-response: 0.1 (0%)100, SMTP response: 0.5 (0%)100, unlink-2-files: 0.2 (0%)100, rundown: 0.6 (0%)100
Apr 14 13:26:33 server9b transfer/smtpd[2820]: disconnect from garnished.pnnmist.top[216.245.203.27]
Apr 14 13:26:33 server9b dovecot: lmtp(3348): Connect from local
Apr 14 13:26:33 server9b dovecot: lmtp(3348, user): SO9CLXkw8VgUDQAAYcTBPg: sieve: msgid=4515310d513e10d542945a1d76a6fde3.Splinter.Brooms.user@domain.com: stored mail into mailbox ‘Junk’
Apr 14 13:26:33 server9b delivery/lmtp[3347]: 9B92EE387F: to=user@server9b.domain.com, orig_to=user@domain.com, relay=server9b.domain.com[/var/run/dovecot/lmtp], delay=0.32, delays=0.05/0.01/0.07/0.19, dsn=2.0.0, status=sent (250 2.0.0 user@server9b.domain.com SO9CLXkw8VgUDQAAYcTBPg Saved)
Apr 14 13:26:33 server9b dovecot: lmtp(3348): Disconnect from local: Client quit (in reset)
Apr 14 13:26:33 server9b postfix/qmgr[2152]: 9B92EE387F: removed
Apr 14 13:27:13 server9b dovecot: pop3-login: Disconnected (no auth attempts in 0 secs): user=<>, rip=192.168.124.107, lip=192.168.148.224, session=
`
Hi load, note times;
