You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Munroe Sollog <so...@digiraticonsulting.com> on 2008/08/01 19:36:38 UTC
SA getting stuck on a message
I have only seen this happen on Cron messages generated by our apt-cacher.
I am running a Debian Lenny machine with:
SpamAssassin version 3.2.5
running on Perl version 5.10.0
I am calling spamassassin through amavid-new 2.6.0
I have pastebinned my debug output, I'm not sure what else whould be
helpful to include:
http://www.pastebin.ca/1089935
--
Munroe Sollog
Systems Engineer
Digirati Consulting, Inc
sollog@digiraticonsulting.com
Re: SA getting stuck on a message
Posted by Mark Martinec <Ma...@ijs.si>.
Munroe,
> SA getting stuck on a message
> I have only seen this happen on Cron messages generated by our
> apt-cacher. I am running a Debian Lenny machine with:
> SpamAssassin version 3.2.5, Perl version 5.10.0, amavid-new 2.6.0
> Aug 1 13:02:19.507 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
> rules: running body tests; score so far=-0.304
> Aug 1 13:04:18.109 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
> rules: ran body rule __NONEMPTY_BODY ======> got hit: "C"
> Aug 1 13:04:28.608 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
> rules: running uri tests; score so far=-0.304
> Aug 1 13:04:28.609 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
> rules: ran uri rule __DOS_HAS_ANY_URI ======> got hit: "h"
My prime suspect would be some regular expression in some .cf file,
more likely than not from SARE. I'd use a bisection removing rulesets,
and see which .cf file is a culprit. For starters, try re-sending the
problem message through a content filter with most .cf files removed.
Mark
Re: SA getting stuck on a message
Posted by Michelle Konzack <li...@tamay-dogan.net>.
Am 2008-08-03 13:06:20, schrieb Robert - elists:
> SNIP - almost 300k of debug baloney
>
> Munroe,
>
> Sending out 300k on a mailing list is not a very bright decision
The message had 92 kByte...
> That is why pastebin etc is used.
>
> You probably sent out many gigabytes of data via the list server
ACK!
Thanks, Greetings and nice Day/Evening
Michelle Konzack
Systemadministrator
24V Electronic Engineer
Tamay Dogan Network
Debian GNU/Linux Consultant
--
Linux-User #280138 with the Linux Counter, http://counter.li.org/
##################### Debian GNU/Linux Consultant #####################
Michelle Konzack Apt. 917 ICQ #328449886
+49/177/9351947 50, rue de Soultz MSN LinuxMichi
+33/6/61925193 67100 Strasbourg/France IRC #Debian (irc.icq.com)
RE: SA getting stuck on a message
Posted by Robert - elists <li...@abbacomm.net>.
> -----Original Message-----
> From: Munroe Sollog [mailto:sollog@digiraticonsulting.com]
> Sent: Sunday, August 03, 2008 12:51 PM
> To: users@spamassassin.apache.org
> Subject: Re: SA getting stuck on a message
>
> I realize that the pastebin while useful in IRC is decidedly unhelpful
> on a mailing list. Here is my debug output:
>
>
>
> Trying to run amavisd-new in debug-sa mode...
> Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: logging initialized,
> log level 5, syslog: amavis.mail
> Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: starting.
> /usr/sbin/amavisd-new at amavisd-new-2.6.0 (20080423), Unicode aware,
> LANG="en_US.UTF-8"
> Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: user=, EUID: 110
> (110); group=, EGID: 112 112 (112 112)
> Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: Perl
SNIP - almost 300k of debug baloney
Munroe,
Sending out 300k on a mailing list is not a very bright decision
That is why pastebin etc is used.
You probably sent out many gigabytes of data via the list server
- rh
Re: SA getting stuck on a message
Posted by Munroe Sollog <so...@digiraticonsulting.com>.
I realize that the pastebin while useful in IRC is decidedly unhelpful
on a mailing list. Here is my debug output:
Trying to run amavisd-new in debug-sa mode...
Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: logging initialized,
log level 5, syslog: amavis.mail
Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: starting.
/usr/sbin/amavisd-new at amavisd-new-2.6.0 (20080423), Unicode aware,
LANG="en_US.UTF-8"
Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: user=, EUID: 110
(110); group=, EGID: 112 112 (112 112)
Aug 1 13:01:28.691 /usr/sbin/amavisd-new[4380]: Perl
version 5.010000
Aug 1 13:01:28.736 /usr/sbin/amavisd-new[4380]: INFO: no optional
modules: IO::Socket::INET6
Aug 1 13:01:29.479 /usr/sbin/amavisd-new[4380]: INFO: SA version:
3.2.5, 3.002005, no optional modules: Encode::Detect
Mail::SpamAssassin::Plugin::DKIM Razor2::Client::Agent IP::Country::Fast
Mail::DKIM Mail::DKIM::Verifier Image::Info Image::Info::GIF
Image::Info::JPEG Image::Info::PNG Image::Info::TIFF Mail::SPF
Mail::SPF::Server Mail::SPF::Request Mail::SPF::Mech Mail::SPF::Mech::A
Mail::SPF::Mech::PTR Mail::SPF::Mech::All Mail::SPF::Mech::Exists
Mail::SPF::Mech::IP4 Mail::SPF::Mech::IP6 Mail::SPF::Mech::Include
Mail::SPF::Mech::MX Mail::SPF::Mod Mail::SPF::Mod::Exp
Mail::SPF::Mod::Redirect Mail::SPF::SenderIPAddrMech
Mail::SPF::v1::Record Mail::SPF::v2::Record NetAddr::IP
NetAddr::IP::Util auto::NetAddr::IP::Util::inet_n2dx
auto::NetAddr::IP::Util::ipv6_n2d Crypt::OpenSSL::RSA
auto::Crypt::OpenSSL::RSA::new_public_key
auto::Crypt::OpenSSL::RSA::new_key_from_parameters
auto::Crypt::OpenSSL::RSA::get_key_parameters
auto::Crypt::OpenSSL::RSA::import_random_seed Error
Aug 1 13:01:29.479 /usr/sbin/amavisd-new[4380]: SpamControl:
init_pre_chroot on SpamAssassin done
Aug 1 13:01:29.480 /usr/sbin/amavisd-new[4380]: Net::Server:
2008/08/01-13:01:29 Amavis (type Net::Server::PreForkSimple) starting!
pid(4380)
Aug 1 13:01:29.485 /usr/sbin/amavisd-new[4380]: Net::Server: Binding
to UNIX socket file /var/lib/amavis/amavisd.sock using SOCK_STREAM
Aug 1 13:01:29.486 /usr/sbin/amavisd-new[4380]: Net::Server: Binding
to TCP port 10024 on host 127.0.0.1
Aug 1 13:01:29.486 /usr/sbin/amavisd-new[4380]: Net::Server: Group
Not Defined. Defaulting to EGID '112 112'
Aug 1 13:01:29.486 /usr/sbin/amavisd-new[4380]: Net::Server: User Not
Defined. Defaulting to EUID '110'
Aug 1 13:01:29.487 /usr/sbin/amavisd-new[4380]: Net::Server: Setting
up serialization via flock
Aug 1 13:01:29.488 /usr/sbin/amavisd-new[4380]: after_chroot_init:
EUID: 110 (110); EGID: 112 112 (112 112)
Aug 1 13:01:29.488 /usr/sbin/amavisd-new[4380]: 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/25-amavis_helpers,
/etc/amavis/conf.d/30-template_localization, /etc/amavis/conf.d/50-user
Aug 1 13:01:29.515 /usr/sbin/amavisd-new[4380]: Module
Amavis::Conf 2.102
Aug 1 13:01:29.516 /usr/sbin/amavisd-new[4380]: Module
Archive::Zip 1.18
Aug 1 13:01:29.517 /usr/sbin/amavisd-new[4380]: Module
BerkeleyDB 0.34
Aug 1 13:01:29.517 /usr/sbin/amavisd-new[4380]: Module
Compress::Zlib 2.011
Aug 1 13:01:29.517 /usr/sbin/amavisd-new[4380]: Module
Convert::TNEF 0.17
Aug 1 13:01:29.517 /usr/sbin/amavisd-new[4380]: Module
Convert::UUlib 1.11
Aug 1 13:01:29.517 /usr/sbin/amavisd-new[4380]: Module
DBD::Pg 2.8.2
Aug 1 13:01:29.517 /usr/sbin/amavisd-new[4380]: Module
DBD::mysql 4.007
Aug 1 13:01:29.518 /usr/sbin/amavisd-new[4380]: Module
DBI 1.605
Aug 1 13:01:29.518 /usr/sbin/amavisd-new[4380]: Module
DB_File 1.816_1
Aug 1 13:01:29.518 /usr/sbin/amavisd-new[4380]: Module
Digest::MD5 2.36_01
Aug 1 13:01:29.518 /usr/sbin/amavisd-new[4380]: Module
Digest::SHA 5.45
Aug 1 13:01:29.518 /usr/sbin/amavisd-new[4380]: Module
Digest::SHA1 2.11
Aug 1 13:01:29.519 /usr/sbin/amavisd-new[4380]: Module
MIME::Entity 5.427
Aug 1 13:01:29.519 /usr/sbin/amavisd-new[4380]: Module
MIME::Parser 5.427
Aug 1 13:01:29.520 /usr/sbin/amavisd-new[4380]: Module
MIME::Tools 5.427
Aug 1 13:01:29.520 /usr/sbin/amavisd-new[4380]: Module
Mail::Header 2.03
Aug 1 13:01:29.520 /usr/sbin/amavisd-new[4380]: Module
Mail::Internet 2.03
Aug 1 13:01:29.520 /usr/sbin/amavisd-new[4380]: Module
Mail::SPF::Query 1.999001
Aug 1 13:01:29.520 /usr/sbin/amavisd-new[4380]: Module
Mail::SpamAssassin 3.002005
Aug 1 13:01:29.521 /usr/sbin/amavisd-new[4380]: Module
Net::DNS 0.63
Aug 1 13:01:29.522 /usr/sbin/amavisd-new[4380]: Module
Net::Server 0.97
Aug 1 13:01:29.522 /usr/sbin/amavisd-new[4380]: Module
Socket6 0.20
Aug 1 13:01:29.522 /usr/sbin/amavisd-new[4380]: Module
Time::HiRes 1.9711
Aug 1 13:01:29.522 /usr/sbin/amavisd-new[4380]: Module
URI 1.35
Aug 1 13:01:29.523 /usr/sbin/amavisd-new[4380]: Module
Unix::Syslog 1.1
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: Amavis::DB code
loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: Amavis::Cache code
loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: SQL base code
NOT loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: SQL::Log code
NOT loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: SQL::Quarantine
NOT loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: Lookup::SQL code
NOT loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: Lookup::LDAP code
NOT loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: AM.PDP-in proto code
loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: SMTP-in proto code
loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: Courier proto code
NOT loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: SMTP-out proto code
loaded
Aug 1 13:01:29.524 /usr/sbin/amavisd-new[4380]: Pipe-out proto code
NOT loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: BSMTP-out proto code
NOT loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: Local-out proto code
loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: OS_Fingerprint code
NOT loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: ANTI-VIRUS code
loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: ANTI-SPAM code
loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: ANTI-SPAM-SA code
loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: Unpackers code
loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: DKIM code
NOT loaded
Aug 1 13:01:29.525 /usr/sbin/amavisd-new[4380]: Tools code
NOT loaded
Aug 1 13:01:29.526 /usr/sbin/amavisd-new[4380]: Found
$file at /usr/bin/file
Aug 1 13:01:29.526 /usr/sbin/amavisd-new[4380]: No
$dspam, not using it
Aug 1 13:01:29.526 /usr/sbin/amavisd-new[4380]: No
$altermime, not using it
Aug 1 13:01:29.526 /usr/sbin/amavisd-new[4380]: Internal decoder for
.mail
Aug 1 13:01:29.526 /usr/sbin/amavisd-new[4380]: Internal decoder for
.asc
Aug 1 13:01:29.526 /usr/sbin/amavisd-new[4380]: Internal decoder for
.uue
Aug 1 13:01:29.526 /usr/sbin/amavisd-new[4380]: Internal decoder for
.hqx
Aug 1 13:01:29.527 /usr/sbin/amavisd-new[4380]: Internal decoder for
.ync
Aug 1 13:01:29.527 /usr/sbin/amavisd-new[4380]: No decoder for
.F
Aug 1 13:01:29.527 /usr/sbin/amavisd-new[4380]: Found decoder for
.Z at /bin/uncompress
Aug 1 13:01:29.527 /usr/sbin/amavisd-new[4380]: Internal decoder for
.gz
Aug 1 13:01:29.527 /usr/sbin/amavisd-new[4380]: Found decoder for
.gz at /bin/gzip -d (backup, not used)
Aug 1 13:01:29.527 /usr/sbin/amavisd-new[4380]: Found decoder for
.bz2 at /bin/bzip2 -d
Aug 1 13:01:29.528 /usr/sbin/amavisd-new[4380]: No decoder for
.lzo tried: lzop -d
Aug 1 13:01:29.528 /usr/sbin/amavisd-new[4380]: No decoder for
.rpm tried: rpm2cpio.pl, rpm2cpio
Aug 1 13:01:29.528 /usr/sbin/amavisd-new[4380]: No decoder for
.cpio tried: pax
Aug 1 13:01:29.528 /usr/sbin/amavisd-new[4380]: Found decoder for
.cpio at /bin/cpio
Aug 1 13:01:29.528 /usr/sbin/amavisd-new[4380]: No decoder for
.tar tried: pax
Aug 1 13:01:29.528 /usr/sbin/amavisd-new[4380]: Found decoder for
.tar at /bin/cpio
Aug 1 13:01:29.529 /usr/sbin/amavisd-new[4380]: Found decoder for
.deb at /usr/bin/ar
Aug 1 13:01:29.529 /usr/sbin/amavisd-new[4380]: Internal decoder for
.zip
Aug 1 13:01:29.529 /usr/sbin/amavisd-new[4380]: No decoder for
.7z tried: 7zr, 7za, 7z
Aug 1 13:01:29.529 /usr/sbin/amavisd-new[4380]: No decoder for
.rar
Aug 1 13:01:29.529 /usr/sbin/amavisd-new[4380]: No decoder for
.arj tried: arj, unarj
Aug 1 13:01:29.530 /usr/sbin/amavisd-new[4380]: No decoder for
.arc tried: nomarch, arc
Aug 1 13:01:29.530 /usr/sbin/amavisd-new[4380]: No decoder for
.zoo tried: zoo
Aug 1 13:01:29.530 /usr/sbin/amavisd-new[4380]: No decoder for
.lha
Aug 1 13:01:29.530 /usr/sbin/amavisd-new[4380]: No decoder for
.doc tried: ripole
Aug 1 13:01:29.530 /usr/sbin/amavisd-new[4380]: No decoder for
.cab tried: cabextract
Aug 1 13:01:29.530 /usr/sbin/amavisd-new[4380]: No decoder for
.tnef
Aug 1 13:01:29.530 /usr/sbin/amavisd-new[4380]: Internal decoder for
.tnef
Aug 1 13:01:29.531 /usr/sbin/amavisd-new[4380]: No decoder for
.exe tried: arj, unarj
Aug 1 13:01:29.531 /usr/sbin/amavisd-new[4380]: Using primary
internal av scanner code for ClamAV-clamd
Aug 1 13:01:29.531 /usr/sbin/amavisd-new[4380]: No primary av
scanner: KasperskyLab AVP - aveclient
Aug 1 13:01:29.531 /usr/sbin/amavisd-new[4380]: No primary av
scanner: KasperskyLab AntiViral Toolkit Pro (AVP)
Aug 1 13:01:29.531 /usr/sbin/amavisd-new[4380]: No primary av
scanner: KasperskyLab AVPDaemonClient
Aug 1 13:01:29.532 /usr/sbin/amavisd-new[4380]: No primary av
scanner: H+BEDV AntiVir or CentralCommand Vexira Antivirus
Aug 1 13:01:29.532 /usr/sbin/amavisd-new[4380]: No primary av
scanner: Command AntiVirus for Linux
Aug 1 13:01:29.532 /usr/sbin/amavisd-new[4380]: No primary av
scanner: Symantec CarrierScan via Symantec CommandLineScanner
Aug 1 13:01:29.532 /usr/sbin/amavisd-new[4380]: No primary av
scanner: Symantec AntiVirus Scan Engine
Aug 1 13:01:29.532 /usr/sbin/amavisd-new[4380]: No primary av
scanner: F-Secure Antivirus
Aug 1 13:01:29.533 /usr/sbin/amavisd-new[4380]: No primary av
scanner: CAI InoculateIT
Aug 1 13:01:29.533 /usr/sbin/amavisd-new[4380]: No primary av
scanner: CAI eTrust Antivirus
Aug 1 13:01:29.533 /usr/sbin/amavisd-new[4380]: No primary av
scanner: MkS_Vir for Linux (beta)
Aug 1 13:01:29.533 /usr/sbin/amavisd-new[4380]: No primary av
scanner: MkS_Vir daemon
Aug 1 13:01:29.533 /usr/sbin/amavisd-new[4380]: No primary av
scanner: ESET Software NOD32 Command Line Interface v 2.51
Aug 1 13:01:29.533 /usr/sbin/amavisd-new[4380]: No primary av
scanner: Norman Virus Control v5 / Linux
Aug 1 13:01:29.534 /usr/sbin/amavisd-new[4380]: No primary av
scanner: Panda Antivirus for Linux
Aug 1 13:01:29.534 /usr/sbin/amavisd-new[4380]: No primary av
scanner: NAI McAfee AntiVirus (uvscan)
Aug 1 13:01:29.534 /usr/sbin/amavisd-new[4380]: No primary av
scanner: VirusBuster
Aug 1 13:01:29.534 /usr/sbin/amavisd-new[4380]: No primary av
scanner: CyberSoft VFind
Aug 1 13:01:29.534 /usr/sbin/amavisd-new[4380]: No primary av
scanner: avast! Antivirus
Aug 1 13:01:29.534 /usr/sbin/amavisd-new[4380]: No primary av
scanner: Ikarus AntiVirus for Linux
Aug 1 13:01:29.535 /usr/sbin/amavisd-new[4380]: No primary av
scanner: BitDefender
Aug 1 13:01:29.535 /usr/sbin/amavisd-new[4380]: Using primary
internal av scanner code for check-jpeg
Aug 1 13:01:29.535 /usr/sbin/amavisd-new[4380]: Found secondary av
scanner ClamAV-clamscan at /usr/bin/clamscan
Aug 1 13:01:29.535 /usr/sbin/amavisd-new[4380]: No secondary av
scanner: FRISK F-Prot Antivirus
Aug 1 13:01:29.535 /usr/sbin/amavisd-new[4380]: No secondary av
scanner: Trend Micro FileScanner
Aug 1 13:01:29.535 /usr/sbin/amavisd-new[4380]: No secondary av
scanner: drweb - DrWeb Antivirus
Aug 1 13:01:29.536 /usr/sbin/amavisd-new[4380]: No secondary av
scanner: KasperskyLab kavscanner
Aug 1 13:01:29.539 /usr/sbin/amavisd-new[4380]: Creating db in
/var/lib/amavis/db/; BerkeleyDB 0.34, libdb 4.6
Aug 1 13:01:29.564 /usr/sbin/amavisd-new[4380]: SpamControl:
initializing Mail::SpamAssassin
Aug 1 13:01:29.564 /usr/sbin/amavisd-new[4380]: SpamAssassin debug
facilities: info,all
Aug 1 13:01:29.565 /usr/sbin/amavisd-new[4380]: SA dbg: logger:
adding facilities: info, all
Aug 1 13:01:29.565 /usr/sbin/amavisd-new[4380]: SA dbg: logger:
logging level is DBG
Aug 1 13:01:29.565 /usr/sbin/amavisd-new[4380]: SA dbg: generic:
SpamAssassin version 3.2.5
Aug 1 13:01:29.566 /usr/sbin/amavisd-new[4380]: SA dbg: config: score
set 0 chosen.
Aug 1 13:01:29.567 /usr/sbin/amavisd-new[4380]: SA dbg: util: running
in taint mode? yes
Aug 1 13:01:29.567 /usr/sbin/amavisd-new[4380]: SA dbg: util: taint
mode: deleting unsafe environment variables, resetting PATH
Aug 1 13:01:29.567 /usr/sbin/amavisd-new[4380]: SA dbg: util: PATH
included '/usr/local/sbin', keeping
Aug 1 13:01:29.567 /usr/sbin/amavisd-new[4380]: SA dbg: util: PATH
included '/usr/local/bin', keeping
Aug 1 13:01:29.568 /usr/sbin/amavisd-new[4380]: SA dbg: util: PATH
included '/usr/sbin', keeping
Aug 1 13:01:29.568 /usr/sbin/amavisd-new[4380]: SA dbg: util: PATH
included '/sbin', keeping
Aug 1 13:01:29.568 /usr/sbin/amavisd-new[4380]: SA dbg: util: PATH
included '/usr/bin', keeping
Aug 1 13:01:29.568 /usr/sbin/amavisd-new[4380]: SA dbg: util: PATH
included '/bin', keeping
Aug 1 13:01:29.568 /usr/sbin/amavisd-new[4380]: SA dbg: util: final
PATH set to: /usr/local/sbin:/usr/local/bin:/usr/sbin:/sbin:/usr/bin:/bin
Aug 1 13:01:29.569 /usr/sbin/amavisd-new[4380]: SA dbg: dns: no ipv6
Aug 1 13:01:29.570 /usr/sbin/amavisd-new[4380]: SA dbg: dns: is
Net::DNS::Resolver available? yes
Aug 1 13:01:29.570 /usr/sbin/amavisd-new[4380]: SA dbg: dns: Net::DNS
version: 0.63
Aug 1 13:01:29.570 /usr/sbin/amavisd-new[4380]: SA dbg: ignore: test
message to precompile patterns and load modules
Aug 1 13:01:29.570 /usr/sbin/amavisd-new[4380]: SA dbg: config: using
"/etc/spamassassin" for site rules pre files
Aug 1 13:01:29.571 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /etc/spamassassin/init.pre
Aug 1 13:01:29.571 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /etc/spamassassin/v310.pre
Aug 1 13:01:29.572 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /etc/spamassassin/v312.pre
Aug 1 13:01:29.572 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /etc/spamassassin/v320.pre
Aug 1 13:01:29.572 /usr/sbin/amavisd-new[4380]: SA dbg: config: using
"/usr/share/spamassassin" for sys rules pre files
Aug 1 13:01:29.573 /usr/sbin/amavisd-new[4380]: SA dbg: config: using
"/usr/share/spamassassin" for default rules dir
Aug 1 13:01:29.574 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/10_default_prefs.cf
Aug 1 13:01:29.575 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_advance_fee.cf
Aug 1 13:01:29.575 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_body_tests.cf
Aug 1 13:01:29.576 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_compensate.cf
Aug 1 13:01:29.577 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_dnsbl_tests.cf
Aug 1 13:01:29.658 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_drugs.cf
Aug 1 13:01:29.658 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_dynrdns.cf
Aug 1 13:01:29.659 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_fake_helo_tests.cf
Aug 1 13:01:29.661 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_head_tests.cf
Aug 1 13:01:29.662 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_html_tests.cf
Aug 1 13:01:29.662 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_imageinfo.cf
Aug 1 13:01:29.663 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_meta_tests.cf
Aug 1 13:01:29.663 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_net_tests.cf
Aug 1 13:01:29.664 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_phrases.cf
Aug 1 13:01:29.664 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_porn.cf
Aug 1 13:01:29.665 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_ratware.cf
Aug 1 13:01:29.666 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_uri_tests.cf
Aug 1 13:01:29.667 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/20_vbounce.cf
Aug 1 13:01:29.667 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/23_bayes.cf
Aug 1 13:01:29.667 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_accessdb.cf
Aug 1 13:01:29.668 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_antivirus.cf
Aug 1 13:01:29.668 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_asn.cf
Aug 1 13:01:29.668 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_dcc.cf
Aug 1 13:01:29.669 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_dkim.cf
Aug 1 13:01:29.669 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_domainkeys.cf
Aug 1 13:01:29.669 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_hashcash.cf
Aug 1 13:01:29.670 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_pyzor.cf
Aug 1 13:01:29.670 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_razor2.cf
Aug 1 13:01:29.671 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_replace.cf
Aug 1 13:01:29.671 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_spf.cf
Aug 1 13:01:29.672 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_textcat.cf
Aug 1 13:01:29.672 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/25_uribl.cf
Aug 1 13:01:29.673 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/30_text_de.cf
Aug 1 13:01:29.675 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/30_text_fr.cf
Aug 1 13:01:29.675 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/30_text_it.cf
Aug 1 13:01:29.676 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/30_text_nl.cf
Aug 1 13:01:29.677 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/30_text_pl.cf
Aug 1 13:01:29.678 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/30_text_pt_br.cf
Aug 1 13:01:29.680 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/50_scores.cf
Aug 1 13:01:29.681 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/60_awl.cf
Aug 1 13:01:29.681 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/60_shortcircuit.cf
Aug 1 13:01:29.682 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/60_whitelist.cf
Aug 1 13:01:29.682 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/60_whitelist_dk.cf
Aug 1 13:01:29.683 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/60_whitelist_dkim.cf
Aug 1 13:01:29.683 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/60_whitelist_spf.cf
Aug 1 13:01:29.683 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/60_whitelist_subject.cf
Aug 1 13:01:29.690 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/72_active.cf
Aug 1 13:01:29.691 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /usr/share/spamassassin/72_removed.cf
Aug 1 13:01:29.694 /usr/sbin/amavisd-new[4380]: SA dbg: config: using
"/etc/spamassassin" for site rules dir
Aug 1 13:01:29.694 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /etc/spamassassin/65_debian.cf
Aug 1 13:01:29.695 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /etc/spamassassin/local.cf
Aug 1 13:01:29.695 /usr/sbin/amavisd-new[4380]: SA dbg: config: using
"/var/lib/amavis/.spamassassin/user_prefs" for user prefs file
Aug 1 13:01:29.696 /usr/sbin/amavisd-new[4380]: SA dbg: config: read
file /var/lib/amavis/.spamassassin/user_prefs
Aug 1 13:01:29.733 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::URIDNSBL from @INC
Aug 1 13:01:29.734 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::Hashcash from @INC
Aug 1 13:01:29.735 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::SPF from @INC
Aug 1 13:01:29.736 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::Pyzor from @INC
Aug 1 13:01:29.736 /usr/sbin/amavisd-new[4380]: SA dbg: pyzor:
network tests on, attempting Pyzor
Aug 1 13:01:29.736 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::Razor2 from @INC
Aug 1 13:01:29.737 /usr/sbin/amavisd-new[4380]: SA dbg: razor2:
razor2 is not available
Aug 1 13:01:29.737 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::SpamCop from @INC
Aug 1 13:01:29.738 /usr/sbin/amavisd-new[4380]: SA dbg: reporter:
network tests on, attempting SpamCop
Aug 1 13:01:29.738 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::AWL from @INC
Aug 1 13:01:29.739 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::AutoLearnThreshold from @INC
Aug 1 13:01:29.739 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::WhiteListSubject from @INC
Aug 1 13:01:29.740 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::MIMEHeader from @INC
Aug 1 13:01:29.741 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::ReplaceTags from @INC
Aug 1 13:01:29.742 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::Check from @INC
Aug 1 13:01:29.742 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::HTTPSMismatch from @INC
Aug 1 13:01:29.743 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::URIDetail from @INC
Aug 1 13:01:29.743 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::Bayes from @INC
Aug 1 13:01:29.744 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::BodyEval from @INC
Aug 1 13:01:29.744 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::DNSEval from @INC
Aug 1 13:01:29.745 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::HTMLEval from @INC
Aug 1 13:01:29.746 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::HeaderEval from @INC
Aug 1 13:01:29.746 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::MIMEEval from @INC
Aug 1 13:01:29.747 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::RelayEval from @INC
Aug 1 13:01:29.747 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::URIEval from @INC
Aug 1 13:01:29.748 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::WLBLEval from @INC
Aug 1 13:01:29.749 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::VBounce from @INC
Aug 1 13:01:29.749 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
loading Mail::SpamAssassin::Plugin::ImageInfo from @INC
Aug 1 13:01:31.060 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_9B90B merged duplicates: __MO_OL_C65FA
Aug 1 13:01:31.060 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__XM_OL_22B61 merged duplicates: __XM_OL_A842E
Aug 1 13:01:31.060 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_07794 merged duplicates: __MO_OL_8627E __MO_OL_F3B05
Aug 1 13:01:31.061 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__XM_OL_07794 merged duplicates: __XM_OL_25340 __XM_OL_3857F
__XM_OL_4F240 __XM_OL_58CB5 __XM_OL_6554A __XM_OL_812FF __XM_OL_C65FA
__XM_OL_CF0C0 __XM_OL_F475E __XM_OL_F6D01
Aug 1 13:01:31.061 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
FH_MSGID_01C67 merged duplicates: __MSGID_VGA
Aug 1 13:01:31.061 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
FS_NEW_SOFT_UPLOAD merged duplicates: HS_SUBJ_NEW_SOFTWARE
Aug 1 13:01:31.061 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__FH_HAS_XMSMAIL merged duplicates: __HAS_MSMAIL_PRI
Aug 1 13:01:31.062 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_015D5 merged duplicates: __MO_OL_6554A
Aug 1 13:01:31.062 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__XM_OL_015D5 merged duplicates: __XM_OL_4BF4C __XM_OL_4EEDB
__XM_OL_5B79A __XM_OL_9B90B __XM_OL_ADFF7 __XM_OL_B30D1 __XM_OL_B4B40
__XM_OL_BC7E6 __XM_OL_F3B05 __XM_OL_FF5C8
Aug 1 13:01:31.062 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_91287 merged duplicates: __MO_OL_B30D1 __MO_OL_CF0C0
Aug 1 13:01:31.062 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
KAM_STOCKOTC merged duplicates: KAM_STOCKTIP15 KAM_STOCKTIP20
KAM_STOCKTIP21 KAM_STOCKTIP4 KAM_STOCKTIP6
Aug 1 13:01:31.062 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_22B61 merged duplicates: __MO_OL_4F240 __MO_OL_ADFF7
Aug 1 13:01:31.063 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_812FF merged duplicates: __MO_OL_BC7E6
Aug 1 13:01:31.063 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_25340 merged duplicates: __MO_OL_4EEDB __MO_OL_7533E
Aug 1 13:01:31.063 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_58CB5 merged duplicates: __MO_OL_B4B40
Aug 1 13:01:31.063 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__DOS_HAS_ANY_URI merged duplicates: __HAS_ANY_URI
Aug 1 13:01:31.064 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
AXB_RCVD_ZOOBSEND merged duplicates: BROKEN_RATWARE_BOM CTYPE_001C_A
DEAR_HOMEOWNER DIV_CENTER_A_HREF DRUG_RA_PRICE FM_DDDD_TIMES_2
FM_SEX_HOSTDDDD HG_HORMONE HS_PHARMA_1 HS_UPLOADED_SOFTWARE OEBOUND
STOX_RCVD_N_NN_N URIBL_RHS_ABUSE URIBL_RHS_BOGUSMX URIBL_RHS_DSN
URIBL_RHS_POST URIBL_RHS_TLD_WHOIS URIBL_RHS_WHOIS URIBL_XS_SURBL
URI_L_PHP XMAILER_MIMEOLE_OL_5E7ED XMAILER_MIMEOLE_OL_C7C33
XMAILER_MIMEOLE_OL_D03AB X_LIBRARY YOUR_CRD_RATING
Aug 1 13:01:31.064 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_72641 merged duplicates: __MO_OL_A842E
Aug 1 13:01:31.064 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_F475E merged duplicates: __MO_OL_FF5C8
Aug 1 13:01:31.064 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
__MO_OL_4BF4C merged duplicates: __MO_OL_F6D01
Aug 1 13:01:31.065 /usr/sbin/amavisd-new[4380]: SA dbg: conf: finish
parsing
Aug 1 13:01:31.087 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
Mail::SpamAssassin::Plugin::ReplaceTags=HASH(0xa25fd20) implements
'finish_parsing_end', priority 0
Aug 1 13:01:31.088 /usr/sbin/amavisd-new[4380]: SA dbg: replacetags:
replacing tags
Aug 1 13:01:31.109 /usr/sbin/amavisd-new[4380]: SA dbg: replacetags:
done replacing tags
Aug 1 13:01:31.111 /usr/sbin/amavisd-new[4380]: SA dbg: bayes:
tie-ing to DB file R/O /etc/mail/spamassassin/bayes/bayes_toks
Aug 1 13:01:31.113 /usr/sbin/amavisd-new[4380]: SA dbg: bayes:
tie-ing to DB file R/O /etc/mail/spamassassin/bayes/bayes_seen
Aug 1 13:01:31.114 /usr/sbin/amavisd-new[4380]: SA dbg: bayes: found
bayes db version 3
Aug 1 13:01:31.115 /usr/sbin/amavisd-new[4380]: SA dbg: bayes: DB
journal sync: last sync: 1217607482
Aug 1 13:01:31.115 /usr/sbin/amavisd-new[4380]: SA dbg: config: score
set 3 chosen.
Aug 1 13:01:31.116 /usr/sbin/amavisd-new[4380]: SA dbg: message: main
message type: text/plain
Aug 1 13:01:31.116 /usr/sbin/amavisd-new[4380]: SA dbg: message: ----
MIME PARSER START ----
Aug 1 13:01:31.116 /usr/sbin/amavisd-new[4380]: SA dbg: message:
parsing normal part
Aug 1 13:01:31.116 /usr/sbin/amavisd-new[4380]: SA dbg: message: ----
MIME PARSER END ----
Aug 1 13:01:31.117 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
Mail::SpamAssassin::Plugin::DNSEval=HASH(0xa2607b0) implements
'check_start', priority 0
Aug 1 13:01:31.118 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
Mail::SpamAssassin::Plugin::Check=HASH(0xa5e6870) implements
'check_main', priority 0
Aug 1 13:01:31.119 /usr/sbin/amavisd-new[4380]: SA dbg: conf:
trusted_networks are not configured; it is recommended that you
configure trusted_networks manually
Aug 1 13:01:31.119 /usr/sbin/amavisd-new[4380]: SA dbg: metadata:
X-Spam-Relays-Trusted:
Aug 1 13:01:31.120 /usr/sbin/amavisd-new[4380]: SA dbg: metadata:
X-Spam-Relays-Untrusted:
Aug 1 13:01:31.120 /usr/sbin/amavisd-new[4380]: SA dbg: metadata:
X-Spam-Relays-Internal:
Aug 1 13:01:31.120 /usr/sbin/amavisd-new[4380]: SA dbg: metadata:
X-Spam-Relays-External:
Aug 1 13:01:31.121 /usr/sbin/amavisd-new[4380]: SA dbg: message: no
encoding detected
Aug 1 13:01:31.121 /usr/sbin/amavisd-new[4380]: SA dbg: plugin:
Mail::SpamAssassin::Plugin::URIDNSBL=HASH(0xa21aa80) implements
'parsed_metadata', priority 0
Aug 1 13:01:31.121 /usr/sbin/amavisd-new[4380]: SA dbg: dns:
is_dns_available() last checked 1217610091.0 seconds ago; re-checking
Aug 1 13:01:31.122 /usr/sbin/amavisd-new[4380]: SA dbg: dns: no ipv6
Aug 1 13:01:31.122 /usr/sbin/amavisd-new[4380]: SA dbg: dns: is
Net::DNS::Resolver available? yes
Aug 1 13:01:31.122 /usr/sbin/amavisd-new[4380]: SA dbg: dns: Net::DNS
version: 0.63
Aug 1 13:01:31.122 /usr/sbin/amavisd-new[4380]: SA dbg: dns: name
server: 206.71.169.49, LocalAddr: 0.0.0.0
Aug 1 13:01:31.123 /usr/sbin/amavisd-new[4380]: SA dbg: dns: resolver
socket rx buffer size is 110592 bytes
Aug 1 13:01:31.123 /usr/sbin/amavisd-new[4380]: SA dbg: dns: testing
resolver nameservers: 206.71.169.49, 209.216.206.167, 206.251.228.22
Aug 1 13:01:31.124 /usr/sbin/amavisd-new[4380]: SA dbg: dns: trying
(3) msn.com...
Aug 1 13:01:31.124 /usr/sbin/amavisd-new[4380]: SA dbg: dns: looking
up NS for 'msn.com'
Aug 1 13:01:31.126 /usr/sbin/amavisd-new[4380]: SA dbg: dns: NS
lookup of msn.com using 206.71.169.49 succeeded => DNS available (set
dns_available to override)
Aug 1 13:01:31.127 /usr/sbin/amavisd-new[4380]: SA dbg: dns: name
server: 209.216.206.167, LocalAddr: 0.0.0.0
Aug 1 13:01:31.127 /usr/sbin/amavisd-new[4380]: SA dbg: dns: resolver
socket rx buffer size is 110592 bytes
Aug 1 13:01:31.127 /usr/sbin/amavisd-new[4380]: SA dbg: dns: trying
(3) akamai.com...
Aug 1 13:01:31.128 /usr/sbin/amavisd-new[4380]: SA dbg: dns: looking
up NS for 'akamai.com'
Aug 1 13:01:31.131 /usr/sbin/amavisd-new[4380]: SA dbg: dns: NS
lookup of akamai.com using 209.216.206.167 succeeded => DNS available
(set dns_available to override)
Aug 1 13:01:31.131 /usr/sbin/amavisd-new[4380]: SA dbg: dns: name
server: 206.251.228.22, LocalAddr: 0.0.0.0
Aug 1 13:01:31.132 /usr/sbin/amavisd-new[4380]: SA dbg: dns: resolver
socket rx buffer size is 110592 bytes
Aug 1 13:01:31.132 /usr/sbin/amavisd-new[4380]: SA dbg: dns: trying
(3) ebay.com...
Aug 1 13:01:31.132 /usr/sbin/amavisd-new[4380]: SA dbg: dns: looking
up NS for 'ebay.com'
Aug 1 13:01:31.135 /usr/sbin/amavisd-new[4380]: SA dbg: dns: NS
lookup of ebay.com using 206.251.228.22 succeeded => DNS available (set
dns_available to override)
Aug 1 13:01:31.135 /usr/sbin/amavisd-new[4380]: SA dbg: dns: name
server: 206.251.228.22, LocalAddr: 0.0.0.0
Aug 1 13:01:31.136 /usr/sbin/amavisd-new[4380]: SA dbg: dns: resolver
socket rx buffer size is 110592 bytes
Aug 1 13:01:31.136 /usr/sbin/amavisd-new[4380]: SA dbg: dns: NS list:
206.71.169.49, 209.216.206.167, 206.251.228.22
Aug 1 13:01:31.136 /usr/sbin/amavisd-new[4380]: SA dbg: dns: name
server: 206.71.169.49, LocalAddr: 0.0.0.0
Aug 1 13:01:31.137 /usr/sbin/amavisd-new[4380]: SA dbg: dns: resolver
socket rx buffer size is 110592 bytes
Aug 1 13:01:31.137 /usr/sbin/amavisd-new[4380]: SA dbg: dns: is DNS
available? 1
Aug 1 13:01:31.139 /usr/sbin/amavisd-new[4380]: SA dbg: uridnsbl:
domains to query:
Aug 1 13:01:31.140 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL sa-other.bondedsender.org., set bsp-untrusted
Aug 1 13:01:31.140 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL plus.bondedsender.org., set ssc-firsttrusted
Aug 1 13:01:31.140 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL combined.njabl.org., set njabl
Aug 1 13:01:31.141 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL bl.spamcop.net., set spamcop
Aug 1 13:01:31.142 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL zen.spamhaus.org., set zen-lastexternal
Aug 1 13:01:31.142 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL dnsbl.sorbs.net., set sorbs-lastexternal
Aug 1 13:01:31.142 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL dnsbl.sorbs.net., set sorbs
Aug 1 13:01:31.143 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL zen.spamhaus.org., set zen-lastexternal
Aug 1 13:01:31.143 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL sa-accredit.habeas.com., set habeas-firsttrusted
Aug 1 13:01:31.143 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL list.dnswl.org., set dnswl-firsttrusted
Aug 1 13:01:31.144 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL list.dsbl.org., set dsbl-lastexternal
Aug 1 13:01:31.144 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL sa-trusted.bondedsender.org., set bsp-firsttrusted
Aug 1 13:01:31.144 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL zen.spamhaus.org., set zen
Aug 1 13:01:31.145 /usr/sbin/amavisd-new[4380]: SA dbg: dns: checking
RBL iadb.isipp.com., set iadb-firsttrusted
Aug 1 13:01:31.146 /usr/sbin/amavisd-new[4380]: SA dbg: check:
running tests for priority: -1000
Aug 1 13:01:31.146 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running head tests; score so far=0
Aug 1 13:01:31.147 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled head tests
Aug 1 13:01:31.149 /usr/sbin/amavisd-new[4380]: SA dbg: eval: all
'*From' addrs: ignore@compiling.spamassassin.taint.org
Aug 1 13:01:31.150 /usr/sbin/amavisd-new[4380]: SA dbg: eval: all
'*To' addrs:
Aug 1 13:01:31.151 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running body tests; score so far=0
Aug 1 13:01:31.151 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled body tests
Aug 1 13:01:31.152 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running uri tests; score so far=0
Aug 1 13:01:31.152 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled uri tests
Aug 1 13:01:31.153 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running rawbody tests; score so far=0
Aug 1 13:01:31.153 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled rawbody tests
Aug 1 13:01:31.154 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running full tests; score so far=0
Aug 1 13:01:31.154 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled full tests
Aug 1 13:01:31.154 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running meta tests; score so far=0
Aug 1 13:01:31.155 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled meta tests
Aug 1 13:01:31.155 /usr/sbin/amavisd-new[4380]: SA dbg: check:
running tests for priority: -950
Aug 1 13:01:31.156 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running head tests; score so far=0
Aug 1 13:01:31.156 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled head tests
Aug 1 13:01:31.157 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running body tests; score so far=0
Aug 1 13:01:31.158 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled body tests
Aug 1 13:01:31.158 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running uri tests; score so far=0
Aug 1 13:01:31.159 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled uri tests
Aug 1 13:01:31.159 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running rawbody tests; score so far=0
Aug 1 13:01:31.160 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled rawbody tests
Aug 1 13:01:31.160 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running full tests; score so far=0
Aug 1 13:01:31.161 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled full tests
Aug 1 13:01:31.257 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running meta tests; score so far=0
Aug 1 13:01:31.258 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled meta tests
Aug 1 13:01:31.258 /usr/sbin/amavisd-new[4380]: SA dbg: check:
running tests for priority: -900
Aug 1 13:01:31.258 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running head tests; score so far=0
Aug 1 13:01:31.259 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled head tests
Aug 1 13:01:31.260 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running body tests; score so far=0
Aug 1 13:01:31.261 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled body tests
Aug 1 13:01:31.261 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running uri tests; score so far=0
Aug 1 13:01:31.262 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled uri tests
Aug 1 13:01:31.262 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running rawbody tests; score so far=0
Aug 1 13:01:31.263 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled rawbody tests
Aug 1 13:01:31.263 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running full tests; score so far=0
Aug 1 13:01:31.264 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled full tests
Aug 1 13:01:31.264 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running meta tests; score so far=0
Aug 1 13:01:31.265 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled meta tests
Aug 1 13:01:31.265 /usr/sbin/amavisd-new[4380]: SA dbg: check:
running tests for priority: -400
Aug 1 13:01:31.265 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running head tests; score so far=0
Aug 1 13:01:31.266 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled head tests
Aug 1 13:01:31.266 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running body tests; score so far=0
Aug 1 13:01:31.267 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled body tests
Aug 1 13:01:31.267 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running uri tests; score so far=0
Aug 1 13:01:31.267 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled uri tests
Aug 1 13:01:31.268 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running rawbody tests; score so far=0
Aug 1 13:01:31.269 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled rawbody tests
Aug 1 13:01:31.269 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running full tests; score so far=0
Aug 1 13:01:31.270 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled full tests
Aug 1 13:01:31.270 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running meta tests; score so far=0
Aug 1 13:01:31.271 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled meta tests
Aug 1 13:01:31.271 /usr/sbin/amavisd-new[4380]: SA dbg: check:
running tests for priority: 0
Aug 1 13:01:31.271 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running head tests; score so far=0
Aug 1 13:01:31.472 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled head tests
Aug 1 13:01:31.473 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
header rule __MISSING_REF ======> got hit: "UNSET"
Aug 1 13:01:31.474 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
header rule __MSGID_OK_HOST ======> got hit: "@spamassassin_spamd_init>"
Aug 1 13:01:31.474 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
header rule __MSGID_OK_DIGITS ======> got hit: "1217610089"
Aug 1 13:01:31.475 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
header rule __MSOE_MID_WRONG_CASE ======> got hit: "
Aug 1 13:01:31.475 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
Message-Id: "
Aug 1 13:01:31.476 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
header rule __HAS_MSGID ======> got hit: "<"
Aug 1 13:01:31.476 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
header rule __SANE_MSGID ======> got hit:
"<12...@spamassassin_spamd_init>
Aug 1 13:01:31.476 /usr/sbin/amavisd-new[4380]: SA dbg: rules: "
Aug 1 13:01:31.477 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
header rule MISSING_DATE ======> got hit: "UNSET"
Aug 1 13:01:31.490 /usr/sbin/amavisd-new[4380]: SA dbg: spf: checking
to see if the message has a Received-SPF header that we can use
Aug 1 13:01:31.491 /usr/sbin/amavisd-new[4380]: SA dbg: spf: cannot
load Mail::SPF module or create Mail::SPF::Server object: Can't locate
Mail/SPF.pm in @INC (@INC contains: /etc/perl /usr/local/lib/perl/5.10.0
/usr/local/share/perl/5.10.0 /usr/lib/perl5 /usr/share/perl5
/usr/lib/perl/5.10 /usr/share/perl/5.10 /usr/local/lib/site_perl) at
/usr/share/perl5/Mail/SpamAssassin/Plugin/SPF.pm line 390.
Aug 1 13:01:31.491 /usr/sbin/amavisd-new[4380]: SA dbg: spf:
attempting to use legacy Mail::SPF::Query module instead
Aug 1 13:01:31.491 /usr/sbin/amavisd-new[4380]: SA dbg: spf: using
Mail::SPF::Query for SPF checks
Aug 1 13:01:31.491 /usr/sbin/amavisd-new[4380]: SA dbg: spf: no
suitable relay for spf use found, skipping SPF-helo check
Aug 1 13:01:31.492 /usr/sbin/amavisd-new[4380]: SA dbg: spf: already
checked for Received-SPF headers, proceeding with DNS based checks
Aug 1 13:01:31.493 /usr/sbin/amavisd-new[4380]: SA dbg: spf: no
suitable relay for spf use found, skipping SPF check
Aug 1 13:01:31.494 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
eval rule NO_RELAYS ======> got hit (1)
Aug 1 13:01:31.496 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
eval rule __GATED_THROUGH_RCVD_REMOVER ======> got hit (1)
Aug 1 13:01:31.498 /usr/sbin/amavisd-new[4380]: SA dbg: spf:
def_spf_whitelist_from: already checked spf and didn't get pass,
skipping whitelist check
Aug 1 13:01:31.501 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
eval rule MISSING_HEADERS ======> got hit (1)
Aug 1 13:01:31.501 /usr/sbin/amavisd-new[4380]: SA dbg: spf:
whitelist_from_spf: already checked spf and didn't get pass, skipping
whitelist check
Aug 1 13:01:31.501 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running body tests; score so far=1.292
Aug 1 13:01:31.738 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled body tests
Aug 1 13:01:31.873 /usr/sbin/amavisd-new[4380]: SA dbg: rules: ran
body rule __NONEMPTY_BODY ======> got hit: "I"
Aug 1 13:01:31.877 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running uri tests; score so far=1.292
Aug 1 13:01:31.884 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled uri tests
Aug 1 13:01:31.914 /usr/sbin/amavisd-new[4380]: SA dbg: eval: stock
info total: 0
Aug 1 13:01:31.921 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running rawbody tests; score so far=1.292
Aug 1 13:01:31.925 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled rawbody tests
Aug 1 13:01:31.927 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running full tests; score so far=1.292
Aug 1 13:01:31.928 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled full tests
Aug 1 13:01:31.930 /usr/sbin/amavisd-new[4380]: SA dbg: util: current
PATH is: /usr/local/sbin:/usr/local/bin:/usr/sbin:/sbin:/usr/bin:/bin
Aug 1 13:01:31.930 /usr/sbin/amavisd-new[4380]: SA dbg: pyzor: pyzor
is not available: no pyzor executable found
Aug 1 13:01:31.930 /usr/sbin/amavisd-new[4380]: SA dbg: pyzor: no
pyzor found, disabling Pyzor
Aug 1 13:01:31.931 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running meta tests; score so far=1.292
Aug 1 13:01:31.931 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled meta tests
Aug 1 13:01:31.932 /usr/sbin/amavisd-new[4380]: SA dbg: check:
running tests for priority: 500
Aug 1 13:01:31.932 /usr/sbin/amavisd-new[4380]: SA dbg: dns:
harvest_dnsbl_queries
Aug 1 13:01:31.933 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running head tests; score so far=1.292
Aug 1 13:01:31.933 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled head tests
Aug 1 13:01:31.934 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running body tests; score so far=1.292
Aug 1 13:01:31.934 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled body tests
Aug 1 13:01:31.934 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running uri tests; score so far=1.292
Aug 1 13:01:31.935 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled uri tests
Aug 1 13:01:31.935 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running rawbody tests; score so far=1.292
Aug 1 13:01:31.936 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled rawbody tests
Aug 1 13:01:31.936 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running full tests; score so far=1.292
Aug 1 13:01:31.937 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled full tests
Aug 1 13:01:31.937 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running meta tests; score so far=1.292
Aug 1 13:01:31.938 /usr/sbin/amavisd-new[4380]: SA dbg: rules: meta
test DIGEST_MULTIPLE has undefined dependency 'DCC_CHECK'
Aug 1 13:01:32.077 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled meta tests
Aug 1 13:01:32.079 /usr/sbin/amavisd-new[4380]: SA dbg: check:
running tests for priority: 1000
Aug 1 13:01:32.080 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running head tests; score so far=3.053
Aug 1 13:01:32.080 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled head tests
Aug 1 13:01:32.082 /usr/sbin/amavisd-new[4380]: SA dbg: locker:
safe_lock: created /var/lib/amavis/.spamassassin/auto-whitelist.lock. .4380
Aug 1 13:01:32.082 /usr/sbin/amavisd-new[4380]: SA dbg: locker:
safe_lock: trying to get lock on
/var/lib/amavis/.spamassassin/auto-whitelist with 0 retries
Aug 1 13:01:32.082 /usr/sbin/amavisd-new[4380]: SA dbg: locker:
safe_lock: link to /var/lib/amavis/.spamassassin/auto-whitelist.lock:
link ok
Aug 1 13:01:32.083 /usr/sbin/amavisd-new[4380]: SA dbg:
auto-whitelist: tie-ing to DB file of type DB_File R/W in
/var/lib/amavis/.spamassassin/auto-whitelist
Aug 1 13:01:32.084 /usr/sbin/amavisd-new[4380]: SA dbg:
auto-whitelist: db-based ignore@compiling.spamassassin.taint.org|ip=none
scores 0/0
Aug 1 13:01:32.084 /usr/sbin/amavisd-new[4380]: SA dbg:
auto-whitelist: AWL active, pre-score: 3.053, autolearn score: 3.053,
mean: undef, IP: undef
Aug 1 13:01:32.084 /usr/sbin/amavisd-new[4380]: SA dbg:
auto-whitelist: DB addr list: untie-ing and unlocking
Aug 1 13:01:32.085 /usr/sbin/amavisd-new[4380]: SA dbg:
auto-whitelist: DB addr list: file locked, breaking lock
Aug 1 13:01:32.085 /usr/sbin/amavisd-new[4380]: SA dbg: locker:
safe_unlock: unlink /var/lib/amavis/.spamassassin/auto-whitelist.lock
Aug 1 13:01:32.085 /usr/sbin/amavisd-new[4380]: SA dbg:
auto-whitelist: post auto-whitelist score: 3.053
Aug 1 13:01:32.086 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running body tests; score so far=3.053
Aug 1 13:01:32.086 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled body tests
Aug 1 13:01:32.086 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running uri tests; score so far=3.053
Aug 1 13:01:32.087 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled uri tests
Aug 1 13:01:32.087 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running rawbody tests; score so far=3.053
Aug 1 13:01:32.088 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled rawbody tests
Aug 1 13:01:32.088 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running full tests; score so far=3.053
Aug 1 13:01:32.089 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled full tests
Aug 1 13:01:32.089 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
running meta tests; score so far=3.053
Aug 1 13:01:32.090 /usr/sbin/amavisd-new[4380]: SA dbg: rules:
compiled meta tests
Aug 1 13:01:32.090 /usr/sbin/amavisd-new[4380]: SA dbg: check: is
spam? score=3.053 required=5
Aug 1 13:01:32.090 /usr/sbin/amavisd-new[4380]: SA dbg: check:
tests=MISSING_DATE,MISSING_HEADERS,MISSING_SUBJECT,NO_RECEIVED,NO_RELAYS
Aug 1 13:01:32.091 /usr/sbin/amavisd-new[4380]: SA dbg: check:
subtests=__GATED_THROUGH_RCVD_REMOVER,__HAS_MSGID,__MISSING_REF,__MSGID_OK_DIGITS,__MSGID_OK_HOST,__MSOE_MID_WRONG_CASE,__NONEMPTY_BODY,__SANE_MSGID,__UNUSABLE_MSGID
Aug 1 13:01:32.092 /usr/sbin/amavisd-new[4380]: SA dbg: bayes: untie-ing
Aug 1 13:01:32.093 /usr/sbin/amavisd-new[4380]: SpamControl:
init_pre_fork on SpamAssassin done
Aug 1 13:01:32.094 /usr/sbin/amavisd-new[4380]: Net::Server:
Beginning prefork (2 processes)
Aug 1 13:01:32.094 /usr/sbin/amavisd-new[4380]: Net::Server: Starting
"2" children
Aug 1 13:01:32.099 /usr/sbin/amavisd-new[4388]: Net::Server: Child
Preforked (4388)
Aug 1 13:01:32.100 /usr/sbin/amavisd-new[4388]: entered child_init_hook
Aug 1 13:01:32.107 /usr/sbin/amavisd-new[4388]: TIMING [total 7 ms] -
bdb-open: 7 (100%)100, rundown: 0 (0%)100
Aug 1 13:01:32.108 /usr/sbin/amavisd-new[4388]: SpamControl:
init_child on SpamAssassin done
Aug 1 13:01:32.113 /usr/sbin/amavisd-new[4389]: Net::Server: Child
Preforked (4389)
Aug 1 13:01:32.114 /usr/sbin/amavisd-new[4389]: entered child_init_hook
Aug 1 13:01:32.120 /usr/sbin/amavisd-new[4389]: TIMING [total 6 ms] -
bdb-open: 6 (100%)100, rundown: 0 (0%)100
Aug 1 13:01:32.121 /usr/sbin/amavisd-new[4380]: Net::Server: Parent
ready for children.
Aug 1 13:01:32.221 /usr/sbin/amavisd-new[4389]: SpamControl:
init_child on SpamAssassin done
Aug 1 13:01:39.900 /usr/sbin/amavisd-new[4388]: Net::Server:
2008/08/01-13:01:39 CONNECT TCP Peer: "127.0.0.1:34891" Local:
"127.0.0.1:10024"
Aug 1 13:01:39.901 /usr/sbin/amavisd-new[4388]: loaded base policy bank
Aug 1 13:01:39.902 /usr/sbin/amavisd-new[4388]: lookup_ip_acl
(inet_acl): key="127.0.0.1" matches "127.0.0.1", result=1
Aug 1 13:01:39.903 /usr/sbin/amavisd-new[4388]: process_request:
fileno sock=13, STDIN=0, STDOUT=1
Aug 1 13:01:39.903 /usr/sbin/amavisd-new[4388]: switch_to_my_time
480 s, new request
Aug 1 13:01:39.904 /usr/sbin/amavisd-new[4388]: process_request:
suggested_protocol="" on TCP
Aug 1 13:01:39.905 /usr/sbin/amavisd-new[4388]: (04388-01) SMTP> 220
[127.0.0.1] ESMTP amavisd-new service ready
Aug 1 13:01:39.906 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_client_time 480 s, smtp response sent
Aug 1 13:01:39.906 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
4: was busy, 5.7 ms, total idle 0.000 s, busy 0.006 s
Aug 1 13:01:39.906 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
5: was idle, 0.2 ms, total idle 0.000 s, busy 0.006 s
Aug 1 13:01:39.906 /usr/sbin/amavisd-new[4388]: (04388-01) SMTP<
EHLO \r\n
Aug 1 13:01:39.906 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_my_time 480 s, SMTP EHLO received
Aug 1 13:01:39.907 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP>
250-[127.0.0.1]
Aug 1 13:01:39.907 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP>
250-VRFY
Aug 1 13:01:39.907 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP>
250-PIPELINING
Aug 1 13:01:39.907 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP>
250-SIZE
Aug 1 13:01:39.907 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP>
250-ENHANCEDSTATUSCODES
Aug 1 13:01:39.907 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP>
250-8BITMIME
Aug 1 13:01:39.907 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP> 250-DSN
Aug 1 13:01:39.908 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP> 250
XFORWARD NAME ADDR PORT PROTO HELO SOURCE
Aug 1 13:01:39.908 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_client_time 480 s, smtp response sent
Aug 1 13:01:39.908 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
6: was busy, 2.2 ms, total idle 0.000 s, busy 0.008 s
Aug 1 13:01:39.908 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
5: was idle, 0.2 ms, total idle 0.000 s, busy 0.008 s
Aug 1 13:01:39.908 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP<
MAIL FROM:<ro...@queen.digirati.lan> SIZE=2733459\r\n
Aug 1 13:01:39.909 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_my_time 480 s, SMTP MAIL received
Aug 1 13:01:39.909 /usr/sbin/amavisd-new[4388]: (04388-01)
check_mail_begin_task: task_count=1
Aug 1 13:01:39.909 /usr/sbin/amavisd-new[4388]: (04388-01)
TempDir::prepare: creating directory
/var/lib/amavis/tmp/amavis-20080801T130139-04388
Aug 1 13:01:39.909 /usr/sbin/amavisd-new[4388]: (04388-01)
TempDir::prepare_file: creating file
/var/lib/amavis/tmp/amavis-20080801T130139-04388/email.txt
Aug 1 13:01:39.910 /usr/sbin/amavisd-new[4388]: (04388-01)
TempDir::prepare_file: layers: unix,perlio
Aug 1 13:01:39.910 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_ip_acl (mynetworks): key="0.0.0.0", no match
Aug 1 13:01:39.911 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(debug_sender) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:39.912 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP> 250
2.1.0 Sender <ro...@queen.digirati.lan> OK
Aug 1 13:01:39.912 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_client_time 480 s, smtp response sent
Aug 1 13:01:39.912 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
6: was busy, 3.7 ms, total idle 0.000 s, busy 0.012 s
Aug 1 13:01:39.912 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
5: was idle, 0.1 ms, total idle 0.001 s, busy 0.012 s
Aug 1 13:01:39.912 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP<
RCPT TO:<ro...@queen.digirati.lan> ORCPT=rfc822;root@queen.digirati.lan\r\n
Aug 1 13:01:39.912 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_my_time 480 s, SMTP RCPT received
Aug 1 13:01:39.913 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP> 250
2.1.5 Recipient <ro...@queen.digirati.lan> OK
Aug 1 13:01:39.913 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_client_time 480 s, smtp response sent
Aug 1 13:01:39.913 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
6: was busy, 1.2 ms, total idle 0.001 s, busy 0.013 s
Aug 1 13:01:39.913 /usr/sbin/amavisd-new[4388]: (04388-01) idle_proc,
5: was idle, 0.1 ms, total idle 0.001 s, busy 0.013 s
Aug 1 13:01:39.914 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP<
DATA\r\n
Aug 1 13:01:39.914 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_my_time 480 s, SMTP DATA received
Aug 1 13:01:39.914 /usr/sbin/amavisd-new[4388]: (04388-01)
ESMTP::10024 /var/lib/amavis/tmp/amavis-20080801T130139-04388:
<ro...@queen.digirati.lan> -> <ro...@queen.digirati.lan> SIZE=2733459
Received: from ([127.0.0.1]) by localhost ( [127.0.0.1])
(amavisd-new, port 10024) with ESMTP for <ro...@queen.digirati.lan>;
Fri, 1 Aug 2008 13:01:39 -0400 (EDT)
Aug 1 13:01:39.915 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP> 354
End data with <CR><LF>.<CR><LF>
Aug 1 13:01:39.915 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_client_time 480 s, smtp response sent
Aug 1 13:01:39.915 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_client_time 480 s, receiving data
Aug 1 13:01:40.090 /usr/sbin/amavisd-new[4388]: (04388-01)
switch_to_my_time 480 s, data-end received
Aug 1 13:01:40.090 /usr/sbin/amavisd-new[4388]: (04388-01) ESMTP<
.<CR><LF>
Aug 1 13:01:40.090 /usr/sbin/amavisd-new[4388]: (04388-01) Actual
message size 2713596 B less than the declared 2733459 B
Aug 1 13:01:40.091 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer digest_init: timer set to 480 s
Aug 1 13:01:40.091 /usr/sbin/amavisd-new[4388]: (04388-01)
get_body_digest: reading header section
Aug 1 13:01:40.092 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer digest_hdr: timer set to 480 s
Aug 1 13:01:40.092 /usr/sbin/amavisd-new[4388]: (04388-01)
get_body_digest: reading mail body
Aug 1 13:01:40.132 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer digest_body: timer set to 480 s
Aug 1 13:01:40.132 /usr/sbin/amavisd-new[4388]: (04388-01) body type
(ESMTP BODY): unlabeled, good (h=0, b=0)
Aug 1 13:01:40.132 /usr/sbin/amavisd-new[4388]: (04388-01) body hash:
da3dfbcd9506f411355ed6c3583ffdfc
Aug 1 13:01:40.136 /usr/sbin/amavisd-new[4388]: (04388-01)
parse_ip_address_from_received:
Aug 1 13:01:40.136 /usr/sbin/amavisd-new[4388]: (04388-01) client IP
address unknown, fetching from Received:
Aug 1 13:01:40.136 /usr/sbin/amavisd-new[4388]: (04388-01) Original
mail size: 2713596; quota set to: 314572800 bytes
Aug 1 13:01:40.137 /usr/sbin/amavisd-new[4388]: (04388-01) Checking:
Oky4sjTQN-3Y <ro...@queen.digirati.lan> -> <ro...@queen.digirati.lan>
Aug 1 13:01:40.137 /usr/sbin/amavisd-new[4388]: (04388-01) 2822.From:
<ro...@queen.digirati.lan>
Aug 1 13:01:40.137 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_acl(root@queen.digirati.lan), no match
Aug 1 13:01:40.137 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(snp1) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.138 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_acl(root@queen.digirati.lan), no match
Aug 1 13:01:40.138 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(snp2) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.138 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:40.138 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:40.139 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_acl(root@queen.digirati.lan), no match
Aug 1 13:01:40.139 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(local_domains) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.139 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:40.139 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:40.139 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(bypass_banned_checks) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.140 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:40.140 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:40.140 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(bypass_spam_checks) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.141 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:40.141 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:40.141 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(bypass_virus_checks) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.142 /usr/sbin/amavisd-new[4388]: (04388-01) Extracting
mime components
Aug 1 13:01:40.352 /usr/sbin/amavisd-new[4388]: (04388-01) Issued a
new file name: p001
Aug 1 13:01:40.373 /usr/sbin/amavisd-new[4388]: (04388-01) Charging
2691839 bytes to remaining quota 314572800 (out of 314572800, (1%)) - by
mime_decode
Aug 1 13:01:40.374 /usr/sbin/amavisd-new[4388]: (04388-01) p001 1
Content-Type: text/plain, size: 2691839 B, name:
Aug 1 13:01:40.375 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer mime_decode: remaining time = 480 s
Aug 1 13:01:40.375 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer mime_decode-1: remaining time = 480 s
Aug 1 13:01:40.375 /usr/sbin/amavisd-new[4388]: (04388-01)
decode_parts: level=1, #parts=1 : p001
Aug 1 13:01:40.375 /usr/sbin/amavisd-new[4388]: (04388-01) running
file(1) on 1 files, arglist size 18
Aug 1 13:01:40.381 /usr/sbin/amavisd-new[4388]: (04388-01)
run_command: [4404] /usr/bin/file p001 </dev/null 2>&1
Aug 1 13:01:40.442 /usr/sbin/amavisd-new[4388]: (04388-01) result
line from file(1): p001: ASCII text\n
Aug 1 13:01:40.443 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_re("ASCII text") matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
Aug 1 13:01:40.444 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(map_full_type_to_short_type) => true, "ASCII text" matches,
result="asc", matching_key="(?i-xsm:^(ASCII|text)\\b)"
Aug 1 13:01:40.444 /usr/sbin/amavisd-new[4388]: (04388-01) File-type
of p001: ASCII text; (asc)
Aug 1 13:01:40.445 /usr/sbin/amavisd-new[4388]: (04388-01) do_ascii:
Decoding part p001
Aug 1 13:01:40.446 /usr/sbin/amavisd-new[4388]: (04388-01) do_ascii:
Setting sigaction handler, was 0
Aug 1 13:01:40.446 /usr/sbin/amavisd-new[4388]: (04388-01) timer set
to 320 s (was 480 s)
Aug 1 13:01:40.878 /usr/sbin/amavisd-new[4388]: (04388-01) do_ascii:
Decoding part p001 (0 items), uulib V0.5pl20
Aug 1 13:01:40.878 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer do_ascii: timer set to 480 s
Aug 1 13:01:40.878 /usr/sbin/amavisd-new[4388]: (04388-01)
decompose_part: p001 - atomic
Aug 1 13:01:40.878 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer parts_decode: remaining time = 480 s
Aug 1 13:01:40.879 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:40.879 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:40.879 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(bypass_header_checks) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.881 /usr/sbin/amavisd-new[4388]: (04388-01)
check_header: 0, OK
Aug 1 13:01:40.977 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:40.977 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:40.978 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(bypass_header_checks) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:40.978 /usr/sbin/amavisd-new[4388]: (04388-01) Checking
for banned types and filenames
Aug 1 13:01:40.978 /usr/sbin/amavisd-new[4388]: (04388-01) lookup:
(scalar) matches, result="DEFAULT"
Aug 1 13:01:40.978 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(banned_filename), 1 matches for "root@queen.digirati.lan", results:
"(constant:DEFAULT)"=>"DEFAULT"
Aug 1 13:01:40.978 /usr/sbin/amavisd-new[4388]: (04388-01) collect
banned table[0]: root@queen.digirati.lan, tables:
DEFAULT=>Amavis::Lookup::RE=ARRAY(0x8dd64d0)
Aug 1 13:01:40.978 /usr/sbin/amavisd-new[4388]: (04388-01) starting
banned checks - traversing message structure tree
Aug 1 13:01:40.979 /usr/sbin/amavisd-new[4388]: (04388-01)
check_for_banned (p001) text/plain,.asc
Aug 1 13:01:40.979 /usr/sbin/amavisd-new[4388]: (04388-01) doing
banned check for root@queen.digirati.lan on text/plain,.asc
Aug 1 13:01:40.979 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_re(["text/plain",".asc"]), no matches
Aug 1 13:01:40.979 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(check_bann:root@queen.digirati.lan) => undef, ["text/plain",".asc"]
does not match
Aug 1 13:01:40.979 /usr/sbin/amavisd-new[4388]: (04388-01) p.path
root@queen.digirati.lan: "P=p001,L=1,M=text/plain,T=asc"
Aug 1 13:01:40.980 /usr/sbin/amavisd-new[4388]: (04388-01) banned
check: any=0, all=N (1)
Aug 1 13:01:40.980 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_re("MAIL"), no matches
Aug 1 13:01:40.980 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(keep_decoded_original) => undef, "MAIL" does not match
Aug 1 13:01:40.981 /usr/sbin/amavisd-new[4388]: (04388-01) Calling
virus scanners, 1 files to scan in
/var/lib/amavis/tmp/amavis-20080801T130139-04388/parts
Aug 1 13:01:40.981 /usr/sbin/amavisd-new[4388]: (04388-01) run_av
(ClamAV-clamd): query template(1,0): CONTSCAN {}\n
Aug 1 13:01:40.981 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer run_av: timer set to 480 s
Aug 1 13:01:40.981 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer run_av: timer set to 384 s
Aug 1 13:01:40.981 /usr/sbin/amavisd-new[4388]: (04388-01) ask_av
Using (ClamAV-clamd): CONTSCAN
/var/lib/amavis/tmp/amavis-20080801T130139-04388/parts\n
Aug 1 13:01:40.982 /usr/sbin/amavisd-new[4388]: (04388-01) timer set
to 10 s (was 384 s)
Aug 1 13:01:40.982 /usr/sbin/amavisd-new[4388]: (04388-01)
ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.ctl
Aug 1 13:01:40.982 /usr/sbin/amavisd-new[4388]: (04388-01)
ClamAV-clamd: Sending CONTSCAN
/var/lib/amavis/tmp/amavis-20080801T130139-04388/parts\n to UNIX socket
/var/run/clamav/clamd.ctl
Aug 1 13:01:41.193 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer ask_daemon_internal: timer set to 306 s
Aug 1 13:01:41.194 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer ask_av: timer set to 479 s
Aug 1 13:01:41.194 /usr/sbin/amavisd-new[4388]: (04388-01) ask_av
(ClamAV-clamd) result:
/var/lib/amavis/tmp/amavis-20080801T130139-04388/parts: OK\n
Aug 1 13:01:41.194 /usr/sbin/amavisd-new[4388]: (04388-01) run_av
(ClamAV-clamd): CLEAN
Aug 1 13:01:41.194 /usr/sbin/amavisd-new[4388]: (04388-01) run_av
(ClamAV-clamd) result: clean
Aug 1 13:01:41.194 /usr/sbin/amavisd-new[4388]: (04388-01) run_av
(check-jpeg): query template(1,0): {}/*
Aug 1 13:01:41.194 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer run_av: timer set to 479 s
Aug 1 13:01:41.195 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer run_av: timer set to 383 s
Aug 1 13:01:41.195 /usr/sbin/amavisd-new[4388]: (04388-01) ask_av
Using (check-jpeg):
/var/lib/amavis/tmp/amavis-20080801T130139-04388/parts/p001
Aug 1 13:01:41.195 /usr/sbin/amavisd-new[4388]: (04388-01)
prolong_timer ask_av: timer set to 479 s
Aug 1 13:01:41.195 /usr/sbin/amavisd-new[4388]: (04388-01) ask_av
(check-jpeg) result: not jpeg
Aug 1 13:01:41.195 /usr/sbin/amavisd-new[4388]: (04388-01) run_av
(check-jpeg): CLEAN, but inconclusive
Aug 1 13:01:41.196 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:41.196 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:41.196 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(bypass_virus_checks) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:41.196 /usr/sbin/amavisd-new[4388]: (04388-01) wbl:
checking sender <ro...@queen.digirati.lan>
Aug 1 13:01:41.196 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(blacklist_recip<ro...@queen.digirati.lan>) => undef,
"root@queen.digirati.lan" does not match
Aug 1 13:01:41.197 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:41.197 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:41.197 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(blacklist_sender) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:41.197 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(whitelist_recip<ro...@queen.digirati.lan>) => undef,
"root@queen.digirati.lan" does not match
Aug 1 13:01:41.198 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:41.198 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:41.198 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(whitelist_sender) => undef, "root@queen.digirati.lan" does not match
Aug 1 13:01:41.198 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:41.198 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan) matches keys: "."=>ARRAY(0x8e8f510)
Aug 1 13:01:41.199 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(score_sender), 1 matches for "root@queen.digirati.lan", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x8e8f0e0),HASH(0x8e8f2e0)]
Aug 1 13:01:41.199 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_re("root@queen.digirati.lan"), no matches
Aug 1 13:01:41.199 /usr/sbin/amavisd-new[4388]: (04388-01)
query_keys: root@queen.digirati.lan, root@, queen.digirati.lan,
.queen.digirati.lan, .digirati.lan, .lan, .
Aug 1 13:01:41.199 /usr/sbin/amavisd-new[4388]: (04388-01)
lookup_hash(root@queen.digirati.lan), no matches
Aug 1 13:01:41.199 /usr/sbin/amavisd-new[4388]: (04388-01) lookup
(score_sender<ro...@queen.digirati.lan>) => undef,
"root@queen.digirati.lan" does not match
Aug 1 13:01:41.200 /usr/sbin/amavisd-new[4388]: (04388-01)
SpamControl: calling spam scanner SpamAssassin
Aug 1 13:01:41.200 /usr/sbin/amavisd-new[4388]: (04388-01) spam_scan:
DSPAM not available, skipping it
Aug 1 13:01:41.200 /usr/sbin/amavisd-new[4388]: (04388-01) timer set
to 319 s for SA (was 479 s)
Aug 1 13:01:41.200 /usr/sbin/amavisd-new[4388]: (04388-01) calling SA
parse, SA version 3.2.5, 3.002005, data as GLOB
Aug 1 13:01:41.201 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: name server: 206.71.169.49, LocalAddr: 0.0.0.0
Aug 1 13:01:41.202 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: resolver socket rx buffer size is 110592 bytes
Aug 1 13:01:41.453 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
message: main message type: text/plain
Aug 1 13:01:41.453 /usr/sbin/amavisd-new[4388]: (04388-01) CALLING SA
check
Aug 1 13:01:41.454 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
conf: trusted_networks are not configured; it is recommended that you
configure trusted_networks manually
Aug 1 13:01:41.456 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: parsed as [ ip=207.172.236.173
rdns=207-172-236-173.c3-0.eas-ubr9.atw-eas.pa.cable.rcn.com
helo=king.digirati.lan by= ident= envfrom= intl=0 id=3C69F6A78
auth=ESMTPA msa=0 ]
Aug 1 13:01:41.456 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: authentication method ESMTPA
Aug 1 13:01:41.457 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: relay 207.172.236.173 trusted? yes internal? yes msa? no
Aug 1 13:01:41.457 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: parsed as [ ip=127.0.0.1 rdns=localhost.localdomain
helo=localhost by=king.digirati.lan ident= envfrom= intl=0 id=099AA937CC
auth= msa=0 ]
Aug 1 13:01:41.458 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: 'from' 127.0.0.1 has private IP
Aug 1 13:01:41.458 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: relay 127.0.0.1 trusted? yes internal? yes msa? no
Aug 1 13:01:41.464 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: parsed as [ ip=127.0.0.1 rdns= helo=king.digirati.lan
by=localhost ident= envfrom= intl=0 id=8ScW1rndEdOs auth= msa=0 ]
Aug 1 13:01:41.464 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: 'from' 127.0.0.1 has private IP
Aug 1 13:01:41.464 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: relay 127.0.0.1 trusted? yes internal? yes msa? no
Aug 1 13:01:41.465 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: parsed as [ ip=192.168.42.23 rdns=queen.digirati.lan
helo=queen.digirati.lan by=king.digirati.lan ident= envfrom= intl=0
id=681439379F auth= msa=0 ]
Aug 1 13:01:41.465 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: 'from' 192.168.42.23 has private IP
Aug 1 13:01:41.466 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
received-header: relay 192.168.42.23 trusted? yes internal? yes msa? no
Aug 1 13:01:41.466 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
metadata: X-Spam-Relays-Trusted: [ ip=207.172.236.173
rdns=207-172-236-173.c3-0.eas-ubr9.atw-eas.pa.cable.rcn.com
helo=king.digirati.lan by= ident= envfrom= intl=1 id=3C69F6A78
auth=ESMTPA msa=0 ] [ ip=127.0.0.1 rdns=localhost.localdomain
helo=localhost by=king.digirati.lan ident= envfrom= intl=1 id=099AA937CC
auth= msa=0 ] [ ip=127.0.0.1 rdns= helo=king.digirati.lan by=localhost
ident= envfrom= intl=1 id=8ScW1rndEdOs auth= msa=0 ] [ ip=192.168.42.23
rdns=queen.digirati.lan helo=queen.digirati.lan by=king.digirati.lan
ident= envfrom= intl=1 id=681439379F auth= msa=0 ]
Aug 1 13:01:41.467 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
metadata: X-Spam-Relays-Untrusted:
Aug 1 13:01:41.467 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
metadata: X-Spam-Relays-Internal: [ ip=207.172.236.173
rdns=207-172-236-173.c3-0.eas-ubr9.atw-eas.pa.cable.rcn.com
helo=king.digirati.lan by= ident= envfrom= intl=1 id=3C69F6A78
auth=ESMTPA msa=0 ] [ ip=127.0.0.1 rdns=localhost.localdomain
helo=localhost by=king.digirati.lan ident= envfrom= intl=1 id=099AA937CC
auth= msa=0 ] [ ip=127.0.0.1 rdns= helo=king.digirati.lan by=localhost
ident= envfrom= intl=1 id=8ScW1rndEdOs auth= msa=0 ] [ ip=192.168.42.23
rdns=queen.digirati.lan helo=queen.digirati.lan by=king.digirati.lan
ident= envfrom= intl=1 id=681439379F auth= msa=0 ]
Aug 1 13:01:41.467 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
metadata: X-Spam-Relays-External:
Aug 1 13:01:41.467 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
message: ---- MIME PARSER START ----
Aug 1 13:01:41.468 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
message: parsing normal part
Aug 1 13:01:41.468 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
message: ---- MIME PARSER END ----
Aug 1 13:01:41.629 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
message: no encoding detected
Aug 1 13:01:49.647 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
uridnsbl: domains to query: apt-cacher-lib.pl
Aug 1 13:01:49.649 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: URI-DNSBL, DNSBL:multi.uribl.com.:apt-cacher-lib.pl
(timeout 15.0s, min 3.0s)
Aug 1 13:01:49.649 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_GREY lookup start
Aug 1 13:01:49.650 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: URI-DNSBL, DNSBL:bl.open-whois.org.:apt-cacher-lib.pl
(timeout 15.0s, min 3.0s)
Aug 1 13:01:49.650 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_SECUREWHOIS lookup start
Aug 1 13:01:49.651 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_MYPRIVREG lookup start
Aug 1 13:01:49.651 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_NETSOLPR lookup start
Aug 1 13:01:49.651 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_AITPRIV lookup start
Aug 1 13:01:49.651 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_FINEXE lookup start
Aug 1 13:01:49.651 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_CONTACTPRIV lookup start
Aug 1 13:01:49.652 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_BLACK lookup start
Aug 1 13:01:49.652 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_REGISTER4LESS lookup start
Aug 1 13:01:49.652 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_NETID lookup start
Aug 1 13:01:49.652 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_DYNADOT lookup start
Aug 1 13:01:49.653 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: URI-DNSBL, DNSBL:multi.surbl.org.:apt-cacher-lib.pl
(timeout 15.0s, min 3.0s)
Aug 1 13:01:49.653 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_OB_SURBL lookup start
Aug 1 13:01:49.654 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_DMNBYPROXY lookup start
Aug 1 13:01:49.654 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_MONIKER_PRIV lookup start
Aug 1 13:01:49.654 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_PRIVDOMAIN lookup start
Aug 1 13:01:49.654 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_DREAMPRIV lookup start
Aug 1 13:01:49.654 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_RED lookup start
Aug 1 13:01:49.654 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_SC_SURBL lookup start
Aug 1 13:01:49.655 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_AB_SURBL lookup start
Aug 1 13:01:49.655 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_WHOISGUARD lookup start
Aug 1 13:01:49.655 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_PRIVPROT lookup start
Aug 1 13:01:49.655 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_NAMEKING lookup start
Aug 1 13:01:49.655 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_PH_SURBL lookup start
Aug 1 13:01:49.655 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_DOMPRIVCORP lookup start
Aug 1 13:01:49.656 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_PRIVACYPOST lookup start
Aug 1 13:01:49.657 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: URI-DNSBL,
DNSBL:dob.sibl.support-intelligence.net:apt-cacher-lib.pl (timeout
15.0s, min 3.0s)
Aug 1 13:01:49.657 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_RHS_DOB lookup start
Aug 1 13:01:49.657 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_DOMESCROW lookup start
Aug 1 13:01:49.657 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_WHOISPROT lookup start
Aug 1 13:01:49.658 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_JP_SURBL lookup start
Aug 1 13:01:49.658 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_REGTEK lookup start
Aug 1 13:01:49.658 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_SAFENAMES lookup start
Aug 1 13:01:49.658 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_WS_SURBL lookup start
Aug 1 13:01:49.658 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_NOMINET lookup start
Aug 1 13:01:49.659 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_REGISTERFLY lookup start
Aug 1 13:01:49.659 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: WHOIS_UNLISTED lookup start
Aug 1 13:01:49.660 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: URI-NS, NS:apt-cacher-lib.pl (timeout 15.0s, min 3.0s)
Aug 1 13:01:49.660 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: URIBL_SBL lookup start
Aug 1 13:01:49.661 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL sa-other.bondedsender.org., set bsp-untrusted
Aug 1 13:01:49.661 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL plus.bondedsender.org., set ssc-firsttrusted
Aug 1 13:01:49.661 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL combined.njabl.org., set njabl
Aug 1 13:01:49.662 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL bl.spamcop.net., set spamcop
Aug 1 13:01:49.678 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: _check_rbl_addresses RBL rhsbl.ahbl.org., set ahbl
Aug 1 13:01:49.678 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: launching DNS A query for queen.digirati.lan.rhsbl.ahbl.org. in
background
Aug 1 13:01:49.679 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: DNSBL-A, dns:A:queen.digirati.lan.rhsbl.ahbl.org.
(timeout 15.0s, min 3.0s)
Aug 1 13:01:49.680 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking A and MX for host queen.digirati.lan
Aug 1 13:01:49.680 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: launching DNS A query for queen.digirati.lan in background
Aug 1 13:01:49.681 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: NO_DNS_FOR_FROM, DNSBL-A, dns:A:queen.digirati.lan
(timeout 15.0s, min 3.0s)
Aug 1 13:01:49.681 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: launching DNS MX query for queen.digirati.lan in background
Aug 1 13:01:49.682 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: NO_DNS_FOR_FROM, DNSBL-MX, dns:MX:queen.digirati.lan
(timeout 15.0s, min 3.0s)
Aug 1 13:01:49.682 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL zen.spamhaus.org., set zen-lastexternal
Aug 1 13:01:49.683 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL dnsbl.sorbs.net., set sorbs-lastexternal
Aug 1 13:01:49.683 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL dnsbl.sorbs.net., set sorbs
Aug 1 13:01:49.683 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL zen.spamhaus.org., set zen-lastexternal
Aug 1 13:01:49.684 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL sa-accredit.habeas.com., set habeas-firsttrusted
Aug 1 13:01:49.684 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL list.dnswl.org., set dnswl-firsttrusted
Aug 1 13:01:49.684 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL list.dsbl.org., set dsbl-lastexternal
Aug 1 13:01:49.685 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL sa-trusted.bondedsender.org., set bsp-firsttrusted
Aug 1 13:01:49.685 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL zen.spamhaus.org., set zen
Aug 1 13:01:49.686 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: _check_rbl_addresses RBL bl.open-whois.org., set openwhois
Aug 1 13:01:49.686 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: launching DNS A query for queen.digirati.lan.bl.open-whois.org. in
background
Aug 1 13:01:49.687 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: DNSBL-A, dns:A:queen.digirati.lan.bl.open-whois.org.
(timeout 15.0s, min 3.0s)
Aug 1 13:01:49.687 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: _check_rbl_addresses RBL fulldom.rfc-ignorant.org., set rfci_envfrom
Aug 1 13:01:49.688 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: launching DNS A query for
queen.digirati.lan.fulldom.rfc-ignorant.org. in background
Aug 1 13:01:49.689 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: starting: DNSBL-A,
dns:A:queen.digirati.lan.fulldom.rfc-ignorant.org. (timeout 15.0s, min 3.0s)
Aug 1 13:01:49.689 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: checking RBL iadb.isipp.com., set iadb-firsttrusted
Aug 1 13:01:49.835 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
check: running tests for priority: -1000
Aug 1 13:01:49.840 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: select found 10 responses ready (t.o.=0.0)
Aug 1 13:01:49.841 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.186 s: URI-DNSBL,
DNSBL:bl.open-whois.org.:apt-cacher-lib.pl
Aug 1 13:01:49.841 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.186 s: URI-DNSBL,
DNSBL:multi.uribl.com.:apt-cacher-lib.pl
Aug 1 13:01:49.841 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.183 s: URI-DNSBL,
DNSBL:multi.surbl.org.:apt-cacher-lib.pl
Aug 1 13:01:49.842 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.156 s: NO_DNS_FOR_FROM, DNSBL-MX,
dns:MX:queen.digirati.lan
Aug 1 13:01:49.842 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.151 s: DNSBL-A,
dns:A:queen.digirati.lan.fulldom.rfc-ignorant.org.
Aug 1 13:01:49.842 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.177 s: URI-NS, NS:apt-cacher-lib.pl
Aug 1 13:01:49.842 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.158 s: DNSBL-A,
dns:A:queen.digirati.lan.rhsbl.ahbl.org.
Aug 1 13:01:49.843 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.153 s: DNSBL-A,
dns:A:queen.digirati.lan.bl.open-whois.org.
Aug 1 13:01:49.843 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.157 s: NO_DNS_FOR_FROM, DNSBL-A,
dns:A:queen.digirati.lan
Aug 1 13:01:49.843 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
async: completed in 0.180 s: URI-DNSBL,
DNSBL:dob.sibl.support-intelligence.net:apt-cacher-lib.pl
Aug 1 13:01:49.843 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
dns: harvested completed queries
Aug 1 13:01:49.844 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running head tests; score so far=1.496
Aug 1 13:01:49.844 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
eval: all '*From' addrs: root@queen.digirati.lan
Aug 1 13:01:49.846 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
eval: all '*To' addrs: root@queen.digirati.lan
Aug 1 13:01:49.852 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running body tests; score so far=1.496
Aug 1 13:01:49.853 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running uri tests; score so far=1.496
Aug 1 13:01:49.858 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running rawbody tests; score so far=1.496
Aug 1 13:01:49.859 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running full tests; score so far=1.496
Aug 1 13:01:49.859 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running meta tests; score so far=1.496
Aug 1 13:01:49.859 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
check: running tests for priority: -950
Aug 1 13:01:49.860 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running head tests; score so far=1.496
Aug 1 13:01:49.860 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran eval rule ALL_TRUSTED ======> got hit (1)
Aug 1 13:01:49.866 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running body tests; score so far=-0.304
Aug 1 13:01:49.867 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running uri tests; score so far=-0.304
Aug 1 13:01:49.872 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running rawbody tests; score so far=-0.304
Aug 1 13:01:49.872 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running full tests; score so far=-0.304
Aug 1 13:01:49.873 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running meta tests; score so far=-0.304
Aug 1 13:01:49.873 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
check: running tests for priority: -900
Aug 1 13:01:49.873 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running head tests; score so far=-0.304
Aug 1 13:01:49.879 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running body tests; score so far=-0.304
Aug 1 13:01:49.880 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running uri tests; score so far=-0.304
Aug 1 13:01:49.885 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running rawbody tests; score so far=-0.304
Aug 1 13:01:49.886 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running full tests; score so far=-0.304
Aug 1 13:01:49.886 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running meta tests; score so far=-0.304
Aug 1 13:01:49.886 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
check: running tests for priority: -400
Aug 1 13:01:49.887 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running head tests; score so far=-0.304
Aug 1 13:01:49.892 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running body tests; score so far=-0.304
Aug 1 13:01:49.893 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running uri tests; score so far=-0.304
Aug 1 13:01:49.894 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
plugin: Mail::SpamAssassin::Plugin::WLBLEval=HASH(0xa263b20) implements
'check_wb_list', priority 0
Aug 1 13:01:49.895 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: tie-ing to DB file R/O /etc/mail/spamassassin/bayes/bayes_toks
Aug 1 13:01:49.896 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: tie-ing to DB file R/O /etc/mail/spamassassin/bayes/bayes_seen
Aug 1 13:01:49.997 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: found bayes db version 3
Aug 1 13:01:49.998 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: DB journal sync: last sync: 1217607482
Aug 1 13:01:49.999 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: corpus size: nspam = 7321, nham = 7253
Aug 1 13:02:19.358 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: score = 5.55111512312578e-17
Aug 1 13:02:19.360 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: DB journal sync: last sync: 1217607482
Aug 1 13:02:19.386 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
bayes: untie-ing
Aug 1 13:02:19.434 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running rawbody tests; score so far=-0.304
Aug 1 13:02:19.435 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running full tests; score so far=-0.304
Aug 1 13:02:19.435 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running meta tests; score so far=-0.304
Aug 1 13:02:19.435 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
check: running tests for priority: 0
Aug 1 13:02:19.477 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running head tests; score so far=-0.304
Aug 1 13:02:19.478 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __CT_TEXT_PLAIN ======> got hit: "text/plain"
Aug 1 13:02:19.479 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __CT ======> got hit: "t"
Aug 1 13:02:19.480 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __MISSING_REF ======> got hit: "UNSET"
Aug 1 13:02:19.481 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __X_CRON_ENV ======> got hit: "<"
Aug 1 13:02:19.481 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __CRON_HEADER ======> got hit: "<"
Aug 1 13:02:19.482 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __NAKED_TO ======> got hit: "root@queen.digirati.lan"
Aug 1 13:02:19.483 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __HAS_RCVD ======> got hit: "b"
Aug 1 13:02:19.484 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __DOS_RCVD_THU ======> got hit: " Thu, "
Aug 1 13:02:19.484 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __DOS_RCVD_FRI ======> got hit: " Fri, "
Aug 1 13:02:19.485 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __TOCC_EXISTS ======> got hit: "r"
Aug 1 13:02:19.485 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __MSGID_OK_HOST ======> got hit:
"@queen.digirati.lan>"
Aug 1 13:02:19.486 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __MSGID_OK_DIGITS ======> got hit: "1217500118"
Aug 1 13:02:19.487 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __MSOE_MID_WRONG_CASE ======> got hit: "
Aug 1 13:02:19.487 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: Message-Id: "
Aug 1 13:02:19.487 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __HAS_MSGID ======> got hit: "<"
Aug 1 13:02:19.488 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __SANE_MSGID ======> got hit:
"<12...@queen.digirati.lan>
Aug 1 13:02:19.488 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: "
Aug 1 13:02:19.491 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran header rule __HAS_SUBJECT ======> got hit: "C"
Aug 1 13:02:19.493 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
spf: checking to see if the message has a Received-SPF header that we
can use
Aug 1 13:02:19.494 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
spf: no suitable relay for spf use found, skipping SPF-helo check
Aug 1 13:02:19.495 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
spf: already checked for Received-SPF headers, proceeding with DNS based
checks
Aug 1 13:02:19.496 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
spf: no suitable relay for spf use found, skipping SPF check
Aug 1 13:02:19.499 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran eval rule __ENV_AND_HDR_FROM_MATCH ======> got hit (1)
Aug 1 13:02:19.500 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
spf: def_spf_whitelist_from: already checked spf and didn't get pass,
skipping whitelist check
Aug 1 13:02:19.501 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
spf: whitelist_from_spf: already checked spf and didn't get pass,
skipping whitelist check
Aug 1 13:02:19.507 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running body tests; score so far=-0.304
Aug 1 13:04:18.109 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran body rule __NONEMPTY_BODY ======> got hit: "C"
Aug 1 13:04:28.608 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: running uri tests; score so far=-0.304
Aug 1 13:04:28.609 /usr/sbin/amavisd-new[4388]: (04388-01) SA dbg:
rules: ran uri rule __DOS_HAS_ANY_URI ======> got hit: "h"
Munroe Sollog
Systems Engineer
Digirati Consulting, Inc
sollog@digiraticonsulting.com
Munroe Sollog wrote:
> I have only seen this happen on Cron messages generated by our apt-cacher.
> I am running a Debian Lenny machine with:
> SpamAssassin version 3.2.5
> running on Perl version 5.10.0
>
> I am calling spamassassin through amavid-new 2.6.0
>
> I have pastebinned my debug output, I'm not sure what else whould be
> helpful to include:
>
> http://www.pastebin.ca/1089935
>
>