Боремся со спамом и вирусами: postfix+amavis+clamav+spamassasin

Это продолжение статьи Настройка почтовой связки Postfix+Dovecot+Mysql+Squirrelmail+SSL. В этой будет рассказано, как добавить проверку на спам и вирусы.

Вступление.

amavis — по своей сути является лишь разграничителем между postfix’ом и проверкой. То есть, при поступлении письма, оно передаётся amavis’y, а тот в свою очередь разбивает письмо на части и направляет на проверку clamav’y и spamassasin’y. Вот такая схема.

1) clamav.

Идём в порты и ставим пакет clamav:

#cd /usr/ports/security/clamav && make install clean

и выбираем такие обязательные опции (остальные по желанию)

ARC           Enable arch archives support
ARJ           Enable arj archives support
LHA           Enable lha archives support
UNZOO         Enable zoo archives support
UNRAR         Enable rar archives support
MILTER        Compile the milter interface
ICONV         Enable ICONV support

Редактируем конфиг clamd.conf

LogFile /var/log/clamav/clamd.log
LogFileMaxSize 2M
LogClean yes
LogTime yes
PidFile /var/run/clamav/clamd.pid
LocalSocket /var/run/clamav/clamd   # <--------- Обратите внимание на отсутствие суффикса '.sock'
DatabaseDirectory /var/db/clamav
ScanMail yes

После чего запускаем freshclam и затем стартуем сам clamav, предварительно добавив строчки в /etc/rc.conf

#echo 'clamav_clamd_enable="YES"' >> /etc/rc.conf
#echo 'clamav_freshclam_enable="YES"' >> /etc/rc.conf
#freshclam
#/usr/local/etc/rc.d/clamav-clamd start

2) amavisd-new.

Идём в порты и ставим пакет amavisd-new:

#cd /usr/ports/security/amavisd-new && make install clean

и выбираем такие обязательные опции (остальные по желанию)

SASL          Use SASL authentication
SPAMASSASSIN  Use mail/p5-Mail-SpamAssassin
RAR           RAR support with archivers/rar
UNRAR         RAR support with archivers/unrar
ARJ           ARJ support with archivers/arj
UNARJ         ARJ support with archivers/unarj
LHA           LHA support with archivers/lha
ARC           ARC support with archivers/arc
NOMARCH       ARC support with archivers/nomarch
CAB           CAB support with archivers/cabextract
RPM           RPM support with archivers/rpm2cpio
ZOO           ZOO support with archivers/zoo
UNZOO         ZOO support with archivers/unzoo
LZOP          LZOP support with archivers/lzop
FREEZE        FREEZE support with archivers/freeze
P7ZIP         P7ZIP support with archivers/p7zip

При установке p5-Mail-SpamAssassin выбираем опции

SACOMPILE      sa-compile
MYSQL          Add MySQL support
RELAY_COUNTRY  Relay country support
SSL            Build with SSL support for spamd/spamc

После чего открываем /usr/local/etc/amavisd.conf и меняем такие переменные:

$mydomain = 'domain.tld';   <---- здесь меняем на свой домен
$log_level = 5; <----- только на период отладки, потом поставить в 0.
@mynetworks = qw( 127.0.0.0/8 [::1] [FE80::]/10 [FEC0::]/10
10.0.0.0/8 172.16.0.0/12 192.168.0.0/16 );  <------ добавляем или удаляем лишнии подсети. Пример: @mynetworks = qw( 127.0.0.0/8 10.0.0.0/8 xx.xx.xx.xx);
$max_servers = 8; # num of pre-forked children (2..15 is common)
$max_requests = 8; # retire a child after that many accepts
$daemon_user  = 'vscan'; # (no default;  customary: vscan or amavis), -u
$daemon_group = 'vscan'; # (no default;  customary: vscan or amavis), -g
#эти параметры выставляются эксперементально, путём подбора
$sa_tag_level_deflt  = 2.0;  # add spam info headers if at, or above that level
$sa_tag2_level_deflt = 4.5;  # add 'spam detected' headers at that level
$sa_kill_level_deflt = 6.5;  # triggers spam evasive actions (e.g. blocks mail)
$sa_dsn_cutoff_level = 10;   # spam level beyond which a DSN is not sent
$penpals_bonus_score = 8;    # (no effect without a @storage_sql_dsn database)
@whitelist_sender_maps = ( ['.domain.tld', 'admin@otherdomain.ua'] );
$myhostname = 'srv-test.domain.tld';  # must be a fully-qualified domain name!
$notify_method  = 'smtp:[127.0.0.1]:10025';
$forward_method = 'smtp:[127.0.0.1]:10025';  # set to undef with milter!
$final_virus_destiny      = D_DISCARD;
$final_banned_destiny     = D_BOUNCE;
$final_spam_destiny       = D_BOUNCE;
$final_bad_header_destiny = D_PASS;
#оставляем только clamav, остальное комментируем или удялем
@av_scanners = (
['ClamAV-clamd',
\&ask_daemon, ["CONTSCAN {} ", "/var/run/clamav/clamd"],
qr/\bOK$/, qr/\bFOUND$/,
qr/^.*?: (?!Infected Archive)(.*) FOUND$/ ]
);
@av_scanners_backup = (
['ClamAV-clamscan', 'clamscan',
"--stdout --no-summary -r --tempdir=$TEMPBASE {}",
[0], qr/:.*\sFOUND$/, qr/^.*?: (?!Infected Archive)(.*) FOUND$/ ]
);

После чего добавляем строки в /etc/rc.conf:

amavisd_enable="YES"
spamd_enable="YES"
spamd_flags="-u vscan"

Добавляем строку в /usr/local/etc/postfix/main.cf

content_filter = smtp-amavis:[127.0.0.1]:10024

и ещё парочку в /usr/local/etc/postfix/master.cf

#with virus-scanner amavis
smtp-amavis     unix    -       -       n       -       8      smtp
-o smtp_data_done_timeout=1200
-o smtp_send_xforward_command=yes
-o disable_dns_lookups=yes
-o max_use=8
127.0.0.1:10025 inet    n       -       n       -       -       smtpd
-o content_filter=
-o local_recipient_maps=
-o relay_recipient_maps=
-o smtpd_restriction_classes=
-o smtpd_delay_reject=no
-o smtpd_client_restrictions=permit_mynetworks,reject
-o smtpd_helo_restrictions=
-o smtpd_sender_restrictions=
-o smtpd_recipient_restrictions=permit_mynetworks,reject
-o mynetworks_style=host
-o mynetworks=127.0.0.0/8
-o strict_rfc821_envelopes=yes
-o smtpd_error_sleep_time=0
-o smtpd_soft_error_limit=1001
-o smtpd_hard_error_limit=1000
-o smtpd_client_connection_count_limit=0
-o smtpd_client_connection_rate_limit=0
-o receive_override_options=no_header_body_checks,no_unknown_recipient_checks,no_address_mappings

Теперь делаем следующее:

#cd /usr/local/etc/mail/spamassassin && cp local.cf.sample local.cf

Теперь проведём инициализацию БД spamassasin’a:

#spamassassin 2>&1 -D --lint
#sa-compile -D --list

После чего запускаем amavisd и перечитываем конфиги postfix’a:

#/usr/local/etc/rc.d/amavisd start
#/usr/local/etc/rc.d/postfix reload

Смотрим лог /var/log/maillog: если есть появляется строка наподобии такой:

can't locate mail spamassassin compiledregexps body_0.pm in @inc

то комментируем строку загрузки модуля в /usr/local/etc/mail/spamassassin/v320.pre:

#loadplugin Mail::SpamAssassin::Plugin::Rule2XSBody

Если появляется ошибки:

May 15 00:26:21 srv-test amavis[12486]: (12486-02) (!!)run_av (ClamAV-clamd) FAILED - unexpected , output="/var/amavis/tmp/amavis-20090515T002041-12486/parts: lstat() failed: Permission denied. ERROR "
May 15 00:26:21 srv-test amavis[12486]: (12486-02) (!!)ClamAV-clamd av-scanner FAILED: CODE(0x8dac874) unexpected , output="/var/amavis/tmp/amavis-20090515T002041-12486/parts: lstat() failed: Permission denied. ERROR " at (eval 115) line 544.
May 15 00:26:21 srv-test amavis[12486]: (12486-02) (!!)WARN: all primary virus scanners failed, considering backups

то добавляем юзера clamav в группу vscan, а юзера vscan в группу clamav.

Опять перезапускаем amavisd и смотрим логи на предмет ошибок. Если всё ок, то теперь отправляем письмо и идём смотреть лог /var/log/maillog:

May 21 15:01:46 srv-test amavis[76465]: Net::Server: 2009/05/21-15:01:46 Server closing!
May 21 15:01:46 srv-test amavis[76491]: SpamControl: rundown_child on SpamAssassin done
May 21 15:01:46 srv-test amavis[76490]: (76490-01) smtp session rundown all sessions, idle 388.1 s, smtp:[127.0.0.1]:10025, state ehlo
May 21 15:01:46 srv-test amavis[76490]: (76490-01) smtp session rundown, closing session smtp:[127.0.0.1]:10025
May 21 15:01:46 srv-test amavis[76490]: (76490-01) Amavis::Out::SMTP::Session close, disconnecting
May 21 15:01:46 srv-test amavis[76490]: (76490-01) SpamControl: rundown_child on SpamAssassin done
May 21 15:01:46 srv-test amavis[76490]: (76490-01) child_finish_hook: invoking DESTROY methods
May 21 15:01:46 srv-test amavis[76490]: (76490-01) Amavis::TempDir DESTROY called
May 21 15:01:46 srv-test amavis[76490]: (76490-01) TempDir removal: empty tempdir is being removed: /var/amavis/tmp/amavis-20090521T145504-76490
May 21 15:01:46 srv-test amavis[76490]: (76490-01) rmdir_recursively: /var/amavis/tmp/amavis-20090521T145504-76490, excl=
May 21 15:01:46 srv-test amavis[76491]: child_finish_hook: invoking DESTROY methods
May 21 15:01:46 srv-test amavis[76491]: Amavis::Cache DESTROY called
May 21 15:01:46 srv-test amavis[76490]: (76490-01) rmdir_recursively: /var/amavis/tmp/amavis-20090521T145504-76490/parts, excl=0
May 21 15:01:46 srv-test amavis[76490]: (76490-01) Amavis::Cache DESTROY called
May 21 15:01:46 srv-test amavis[76490]: (76490-01) Amavis::DB::SNMP DESTROY called
May 21 15:01:47 srv-test amavis[76491]: Amavis::DB::SNMP DESTROY called
May 21 15:01:52 srv-test amavis[89910]: logging initialized, log level 5, syslog: amavis.mail
May 21 15:01:52 srv-test amavis[89910]: starting.  /usr/local/sbin/amavisd at srv-test.domain.tld amavisd-new-2.6.3 (20090422), Unicode aware
May 21 15:01:52 srv-test amavis[89910]: user=, EUID: 110 (110);  group=, EGID: 110 110 (110 110)
May 21 15:01:52 srv-test amavis[89910]: Perl version               5.008009
May 21 15:01:52 srv-test amavis[89910]: SpamControl: attempting to load scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
May 21 15:01:52 srv-test amavis[89910]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
May 21 15:01:53 srv-test amavis[89910]: INFO: SA version: 3.2.5, 3.002005, no optional modules: Net::CIDR::Lite IP::Country::Fast 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 M
ail::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::M
od::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 auto::NetAddr::IP::Util::ipv6_n2x Error
May 21 15:01:53 srv-test amavis[89910]: SpamControl: init_pre_chroot on SpamAssassin done
May 21 15:01:53 srv-test amavis[89911]: Net::Server: Process Backgrounded
May 21 15:01:53 srv-test amavis[89911]: Net::Server: 2009/05/21-15:01:53 Amavis (type Net::Server::PreForkSimple) starting! pid(89911)
May 21 15:01:53 srv-test amavis[89911]: Net::Server: Binding to UNIX socket file /var/amavis/amavisd.sock using SOCK_STREAM
May 21 15:01:53 srv-test amavis[89911]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1
May 21 15:01:53 srv-test amavis[89911]: Net::Server: Group Not Defined.  Defaulting to EGID '110 110'
May 21 15:01:53 srv-test amavis[89911]: Net::Server: User Not Defined.  Defaulting to EUID '110'
May 21 15:01:53 srv-test amavis[89911]: Net::Server: Setting up serialization via flock
May 21 15:01:53 srv-test amavis[89911]: after_chroot_init: EUID: 110 (110);  EGID: 110 110 (110 110)
May 21 15:01:53 srv-test amavis[89911]: config files read: /usr/local/etc/amavisd.conf
May 21 15:01:53 srv-test amavis[89911]: Module Amavis::Conf        2.205
May 21 15:01:53 srv-test amavis[89911]: Module Archive::Zip        1.26
May 21 15:01:53 srv-test amavis[89911]: Module BerkeleyDB          0.38
May 21 15:01:53 srv-test amavis[89911]: Module Compress::Zlib      2.017
May 21 15:01:53 srv-test amavis[89911]: Module Convert::TNEF       0.17
May 21 15:01:53 srv-test amavis[89911]: Module Convert::UUlib      1.12
May 21 15:01:53 srv-test amavis[89911]: Module Crypt::OpenSSL::RSA 0.25
May 21 15:01:53 srv-test amavis[89911]: Module DBD::mysql          4.011
May 21 15:01:53 srv-test amavis[89911]: Module DBI                 1.608
May 21 15:01:53 srv-test amavis[89911]: Module DB_File             1.817
May 21 15:01:53 srv-test amavis[89911]: Module Digest::MD5         2.38
May 21 15:01:53 srv-test amavis[89911]: Module Digest::SHA         5.47
May 21 15:01:53 srv-test amavis[89911]: Module Digest::SHA1        2.11
May 21 15:01:53 srv-test amavis[89911]: Module IO::Socket::INET6   2.56
May 21 15:01:53 srv-test amavis[89911]: Module MIME::Entity        5.427
May 21 15:01:53 srv-test amavis[89911]: Module MIME::Parser        5.427
May 21 15:01:53 srv-test amavis[89911]: Module MIME::Tools         5.427
May 21 15:01:53 srv-test amavis[89911]: Module Mail::DKIM::Signer  0.33
May 21 15:01:53 srv-test amavis[89911]: Module Mail::DKIM::Verifier 0.33
May 21 15:01:53 srv-test amavis[89911]: Module Mail::Header        2.04
May 21 15:01:53 srv-test amavis[89911]: Module Mail::Internet      2.04
May 21 15:01:53 srv-test amavis[89911]: Module Mail::SpamAssassin  3.002005
May 21 15:01:53 srv-test amavis[89911]: Module Net::DNS            0.65
May 21 15:01:53 srv-test amavis[89911]: Module Net::Server         0.97
May 21 15:01:53 srv-test amavis[89911]: Module Razor2::Client::Version 2.84
May 21 15:01:53 srv-test amavis[89911]: Module Socket6             0.23
May 21 15:01:53 srv-test amavis[89911]: Module Time::HiRes         1.9719
May 21 15:01:53 srv-test amavis[89911]: Module URI                 1.37
May 21 15:01:53 srv-test amavis[89911]: Module Unix::Syslog        1.1
May 21 15:01:53 srv-test amavis[89911]: Amavis::DB code      loaded
May 21 15:01:53 srv-test amavis[89911]: Amavis::Cache code   loaded
May 21 15:01:53 srv-test amavis[89911]: SQL base code        NOT loaded
May 21 15:01:53 srv-test amavis[89911]: SQL::Log code        NOT loaded
May 21 15:01:53 srv-test amavis[89911]: SQL::Quarantine      NOT loaded
May 21 15:01:53 srv-test amavis[89911]: Lookup::SQL code     NOT loaded
May 21 15:01:53 srv-test amavis[89911]: Lookup::LDAP code    NOT loaded
May 21 15:01:53 srv-test amavis[89911]: AM.PDP-in proto code loaded
May 21 15:01:53 srv-test amavis[89911]: SMTP-in proto code   loaded
May 21 15:01:53 srv-test amavis[89911]: Courier proto code   NOT loaded
May 21 15:01:53 srv-test amavis[89911]: SMTP-out proto code  loaded
May 21 15:01:53 srv-test amavis[89911]: Pipe-out proto code  NOT loaded
May 21 15:01:53 srv-test amavis[89911]: BSMTP-out proto code NOT loaded
May 21 15:01:53 srv-test amavis[89911]: Local-out proto code loaded
May 21 15:01:53 srv-test amavis[89911]: OS_Fingerprint code  NOT loaded
May 21 15:01:53 srv-test amavis[89911]: ANTI-VIRUS code      loaded
May 21 15:01:53 srv-test amavis[89911]: ANTI-SPAM code       loaded
May 21 15:01:53 srv-test amavis[89911]: ANTI-SPAM-EXT code   NOT loaded
May 21 15:01:53 srv-test amavis[89911]: ANTI-SPAM-C code     NOT loaded
May 21 15:01:53 srv-test amavis[89911]: ANTI-SPAM-SA code    loaded
May 21 15:01:53 srv-test amavis[89911]: Unpackers code       loaded
May 21 15:01:53 srv-test amavis[89911]: DKIM code            loaded
May 21 15:01:53 srv-test amavis[89911]: Tools code           NOT loaded
May 21 15:01:53 srv-test amavis[89911]: Found $file            at /usr/local/bin/file
May 21 15:01:53 srv-test amavis[89911]: No $altermime,         not using it
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .mail
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .asc
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .uue
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .hqx
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .ync
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .F    at /usr/local/bin/unfreeze
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .Z    at /usr/bin/uncompress
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .gz   at /usr/bin/gzip -d
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .gz   (backup, not used)
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .bz2  at /usr/bin/bzip2 -d
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .lzo  at /usr/local/bin/lzop -d
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .rpm  at /usr/local/bin/rpm2cpio.pl
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .cpio at /bin/pax
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .tar  at /bin/pax
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .deb  at /usr/bin/ar
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .zip
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .7z   at /usr/local/bin/7zr
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .rar  at /usr/local/bin/rar
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .arj  at /usr/local/bin/arj
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .arc  at /usr/local/bin/nomarch
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .zoo  at /usr/local/bin/zoo
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .lha  at /usr/local/bin/lha
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .cab  at /usr/local/bin/cabextract
May 21 15:01:53 srv-test amavis[89911]: No decoder for       .tnef tried: tnef
May 21 15:01:53 srv-test amavis[89911]: Internal decoder for .tnef
May 21 15:01:53 srv-test amavis[89911]: Found decoder for    .exe  at /usr/local/bin/rar; /usr/local/bin/lha; /usr/local/bin/arj
May 21 15:01:53 srv-test amavis[89911]: Using primary internal av scanner code for ClamAV-clamd
May 21 15:01:53 srv-test amavis[89911]: Found secondary av scanner ClamAV-clamscan at /usr/local/bin/clamscan
May 21 15:01:53 srv-test amavis[89911]: Using internal spam scanner code for SpamAssassin
May 21 15:01:53 srv-test amavis[89911]: Creating db in /var/amavis/db/; BerkeleyDB 0.38, libdb 4.1
May 21 15:01:53 srv-test amavis[89911]: initializing Mail::SpamAssassin
May 21 15:01:53 srv-test amavis[89911]: SpamAssassin debug facilities: info
May 21 15:02:04 srv-test amavis[89911]: SpamAssassin loaded plugins: AWL, AutoLearnThreshold, Bayes, BodyEval, Check, DNSEval, HTMLEval, HTTPSMismatch, Hashcash, HeaderEval, ImageInfo, MIMEEval, MIMEHeader, Pyzor, Razor2, RelayEval, ReplaceTags, SPF, SpamCop, URIDNSBL, URIDetail, URIEval, VBounce, WLBLEval, WhiteListSubject
May 21 15:02:04 srv-test amavis[89911]: SpamControl: init_pre_fork on SpamAssassin done
May 21 15:02:04 srv-test amavis[89911]: Net::Server: Beginning prefork (2 processes)
May 21 15:02:04 srv-test amavis[89911]: Net::Server: Starting "2" children
May 21 15:02:04 srv-test amavis[89917]: Net::Server: Child Preforked (89917)
May 21 15:02:04 srv-test amavis[89911]: Net::Server: Parent ready for children.
May 21 15:02:04 srv-test amavis[89917]: entered child_init_hook
May 21 15:02:04 srv-test amavis[89917]: TIMING - bdb-open: 13 (100%)100, rundown: 0 (0%)100
May 21 15:02:04 srv-test amavis[89918]: Net::Server: Child Preforked (89918)
May 21 15:02:04 srv-test amavis[89917]: SpamControl: init_child on SpamAssassin done
May 21 15:02:04 srv-test amavis[89918]: entered child_init_hook
May 21 15:02:04 srv-test amavis[89918]: TIMING - bdb-open: 13 (100%)100, rundown: 0 (0%)100
May 21 15:02:04 srv-test amavis[89918]: SpamControl: init_child on SpamAssassin done
May 21 15:02:16 srv-test postfix/smtpd[89919]: connect from skeletor[10.10.10.111]
May 21 15:02:16 srv-test postfix/smtpd[89919]: setting up TLS connection from skeletor[10.10.10.111]
May 21 15:02:16 srv-test postfix/smtpd[89919]: Anonymous TLS connection established from skeletor[10.10.10.111]: TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)
May 21 15:02:16 srv-test postfix/smtpd[89919]: D7558170CA: client=skeletor[10.10.10.111], sasl_method=PLAIN, sasl_username=admin@domain.tld
May 21 15:02:16 srv-test postfix/cleanup[89921]: D7558170CA: message-id=<4A154296.6080800@domain.tld>
May 21 15:02:16 srv-test postfix/qmgr[76330]: D7558170CA: from=, size=610, nrcpt=1 (queue active)
May 21 15:02:16 srv-test postfix/smtpd[89919]: disconnect from skeletor[10.10.10.111]
May 21 15:02:16 srv-test amavis[89917]: Net::Server: 2009/05/21-15:02:16 CONNECT TCP Peer: "127.0.0.1:65353" Local: "127.0.0.1:10024"
May 21 15:02:16 srv-test amavis[89917]: loaded base policy bank
May 21 15:02:16 srv-test amavis[89917]: lookup_ip_acl (inet_acl): key="127.0.0.1" matches "127.0.0.1", result=1
May 21 15:02:16 srv-test amavis[89917]: process_request: fileno sock=13, STDIN=0, STDOUT=1
May 21 15:02:16 srv-test amavis[89917]: switch_to_my_time     480 s, new request
May 21 15:02:16 srv-test amavis[89917]: process_request: suggested_protocol="" on TCP
May 21 15:02:16 srv-test amavis[89917]: (89917-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 4: was busy, 29.1 ms, total idle 0.000 s, busy 0.029 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 5: was idle, 1.2 ms, total idle 0.001 s, busy 0.029 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) SMTP< EHLO srv-test.domain.tld
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, SMTP EHLO received
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250-[127.0.0.1]
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250-VRFY
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250-PIPELINING
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250-SIZE
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250-ENHANCEDSTATUSCODES
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250-8BITMIME
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250-DSN
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO SOURCE
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 6: was busy, 6.0 ms, total idle 0.001 s, busy 0.035 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 5: was idle, 0.4 ms, total idle 0.002 s, busy 0.035 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP< XFORWARD NAME=skeletor ADDR=10.10.10.111 PORT=4369
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, SMTP XFORWARD received
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250 2.5.0 Ok XFORWARD
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 6: was busy, 2.8 ms, total idle 0.002 s, busy 0.038 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 5: was idle, 0.4 ms, total idle 0.002 s, busy 0.038 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP< XFORWARD PROTO=ESMTP HELO=[10.10.10.111] SOURCE=REMOTE
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, SMTP XFORWARD received
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250 2.5.0 Ok XFORWARD
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 6: was busy, 2.1 ms, total idle 0.002 s, busy 0.040 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 5: was idle, 0.4 ms, total idle 0.002 s, busy 0.040 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP< MAIL FROM: SIZE=610
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, SMTP MAIL received
May 21 15:02:16 srv-test amavis[89917]: (89917-01) check_mail_begin_task: task_count=1
May 21 15:02:16 srv-test amavis[89917]: (89917-01) TempDir::prepare: creating directory /var/amavis/tmp/amavis-20090521T150216-89917
May 21 15:02:16 srv-test amavis[89917]: (89917-01) TempDir::prepare_file: creating file /var/amavis/tmp/amavis-20090521T150216-89917/email.txt
May 21 15:02:16 srv-test amavis[89917]: (89917-01) TempDir::prepare_file: layers: stdio
May 21 15:02:16 srv-test amavis[89917]: (89917-01) lookup_ip_acl: key="10.10.10.111" matches "10.0.0.0/8", result=1
May 21 15:02:16 srv-test amavis[89917]: (89917-01) loaded policy bank "MYNETS"
May 21 15:02:16 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250 2.1.0 Sender OK
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 6: was busy, 16.2 ms, total idle 0.002 s, busy 0.056 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 5: was idle, 0.4 ms, total idle 0.003 s, busy 0.056 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP< RCPT TO: ORCPT=rfc822;admin@domain.tld
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, SMTP RCPT received
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP> 250 2.1.5 Recipient OK
May 21 15:02:16 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 6: was busy, 12.2 ms, total idle 0.003 s, busy 0.068 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) idle_proc, 5: was idle, 0.4 ms, total idle 0.003 s, busy 0.068 s
May 21 15:02:16 srv-test amavis[89917]: (89917-01) ESMTP< DATA
May 21 15:02:17 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, SMTP DATA received
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ESMTP::10024 /var/amavis/tmp/amavis-20090521T150216-89917: -> SIZE=610 Received: from srv-test.domain.tld ([127.0.0.1]) by localhost (srv-test.domain.tld [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for ; Thu, 21 May 2009 15:02:16 +0300 (EEST)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ESMTP> 354 End data with .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:17 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, receiving data
May 21 15:02:17 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, data-end received
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ESMTP< .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer digest_init: timer set to 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) get_body_digest: reading header section
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer digest_hdr: timer set to 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) get_body_digest: reading mail body
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer digest_body: timer set to 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) body hash: d19cdb54d5b91663defed6852f47bb3b
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Original mail size: 610; quota set to: 305000 bytes
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Checking: I9A+8btgq79D MYNETS [10.10.10.111] ->
May 21 15:02:17 srv-test amavis[89917]: (89917-01) 2822.From:
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_acl(admin@domain.tld) matches key ".domain.tld", result=1
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="1", matching_key=".domain.tld"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Extracting mime components
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Issued a new file name: p001
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Charging 5 bytes to remaining quota 305000 (out of 305000, (0%)) - by mime_decode
May 21 15:02:17 srv-test amavis[89917]: (89917-01) p001 1 Content-Type: text/plain, size: 5 B, name:
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer mime_decode: remaining time = 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer mime_decode-1: remaining time = 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) inspect_dsn: parts: text/plain
May 21 15:02:17 srv-test amavis[89917]: (89917-01) inspect_dsn: not a bounce
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer dsn_parse: remaining time = 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) decode_parts: level=1, #parts=1 : p001
May 21 15:02:17 srv-test amavis[89917]: (89917-01) running file(1) on 1 files, arglist size 24
May 21 15:02:17 srv-test amavis[89923]: (89917-01) open_on_specific_fd: target fd0 closing, to become < /dev/null
May 21 15:02:17 srv-test amavis[89923]: (89917-01) open_on_specific_fd: target fd1 closing, to become > &=16
May 21 15:02:17 srv-test amavis[89923]: (89917-01) open_on_specific_fd: target fd1 dup2 from fd16 > &=16
May 21 15:02:17 srv-test amavis[89923]: (89917-01) open_on_specific_fd: source fd16 closed
May 21 15:02:17 srv-test amavis[89923]: (89917-01) open_on_specific_fd: target fd2 closing, to become > &1
May 21 15:02:17 srv-test amavis[89923]: (89917-01) open_on_specific_fd: target fd2 dup2 from fd1 > &1
May 21 15:02:17 srv-test amavis[89917]: (89917-01) run_command: [89923] /usr/local/bin/file p001 &1
May 21 15:02:17 srv-test amavis[89917]: (89917-01) result line from file(1): p001: ASCII text
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_re("ASCII text") matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => true,  "ASCII text" matches, result="asc", matching_key="(?i-xsm:^(ASCII|text)\\b)"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) File-type of p001: ASCII text; (asc)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) do_ascii: Decoding part p001
May 21 15:02:17 srv-test amavis[89917]: (89917-01) do_ascii: Setting sigaction handler, was 0
May 21 15:02:17 srv-test amavis[89917]: (89917-01) timer set to 320 s (was 480 s)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) do_ascii: Decoding part p001 (0 items), uulib V0.5pl20
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer do_ascii: timer set to 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) decompose_part: p001 - atomic
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer parts_decode: remaining time = 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) check_header: 0, OK
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Checking for banned types and filenames
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="DEFAULT"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup , 1 matches for "admin@domain.tld", results: "(constant:DEFAULT)"=>"DEFAULT"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) collect banned table[0]: admin@domain.tld, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x96fb740)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) starting banned checks - traversing message structure tree
May 21 15:02:17 srv-test amavis[89917]: (89917-01) check_for_banned (p001) text/plain,.asc
May 21 15:02:17 srv-test amavis[89917]: (89917-01) doing banned check for admin@domain.tld on text/plain,.asc
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_re(["text/plain",".asc"]), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, ["text/plain",".asc"] does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "P=p001\tL=1\tM=text/plain\tT=asc" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) p.path admin@domain.tld: "P=p001,L=1,M=text/plain,T=asc"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) banned check: any=0, all=N (1)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_re("MAIL") matches key "(?-xism:^MAIL$)", result="1"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => true,  "MAIL" matches, result="1", matching_key="(?-xism:^MAIL$)"
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Issued a new file name: p002
May 21 15:02:17 srv-test amavis[89917]: (89917-01) presenting full original message to scanners as /var/amavis/tmp/amavis-20090521T150216-89917/parts/p002
May 21 15:02:17 srv-test amavis[89917]: (89917-01) Calling virus scanners, 2 files to scan in /var/amavis/tmp/amavis-20090521T150216-89917/parts
May 21 15:02:17 srv-test amavis[89917]: (89917-01) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer run_av: timer set to 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer run_av: timer set to 384 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ask_av Using (ClamAV-clamd): CONTSCAN /var/amavis/tmp/amavis-20090521T150216-89917/parts
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ask_daemon_internal: timer set to 10 s (was 384 s)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ClamAV-clamd: Connecting to socket  /var/run/clamav/clamd
May 21 15:02:17 srv-test amavis[89917]: (89917-01) creating socket by IO::Socket::UNIX to /var/run/clamav/clamd
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ClamAV-clamd: Sending CONTSCAN /var/amavis/tmp/amavis-20090521T150216-89917/parts to UNIX socket /var/run/clamav/clamd
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer ask_daemon_internal: timer set to 307 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer ask_daemon_internal: timer set to 384 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) prolong_timer ask_av: timer set to 480 s
May 21 15:02:17 srv-test amavis[89917]: (89917-01) ask_av (ClamAV-clamd) result: /var/amavis/tmp/amavis-20090521T150216-89917/parts: OK
May 21 15:02:17 srv-test amavis[89917]: (89917-01) run_av (ClamAV-clamd): CLEAN
May 21 15:02:17 srv-test amavis[89917]: (89917-01) run_av (ClamAV-clamd) result: clean
May 21 15:02:17 srv-test amavis[89917]: (89917-01) wbl: checking sender
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .tld, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld) matches keys: "."=>ARRAY(0x96fbb48)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup , 1 matches for "admin@domain.tld", results: "."=>[Amavis::Lookup::RE=ARRAY(0x96fb938),HASH(0x96fb9a4)]
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_re("admin@domain.tld"), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) query_keys: admin@domain.tld, skeletor@, domain.tld, .domain.tld, .com.ua, .ua, .
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup_hash(admin@domain.tld), no matches
May 21 15:02:17 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:17 srv-test amavis[89917]: (89917-01) SpamControl: calling spam scanner SpamAssassin
May 21 15:02:17 srv-test amavis[89917]: (89917-01) timer set to 320 s for SA (was 480 s)
May 21 15:02:17 srv-test amavis[89917]: (89917-01) calling SA parse, SA version 3.2.5, 3.002005, data as GLOB
May 21 15:02:17 srv-test amavis[89917]: (89917-01) CALLING SA check
May 21 15:02:19 srv-test amavis[89917]: (89917-01) prolong_timer spam_scan_sa_finish: timer set to 478 s
May 21 15:02:19 srv-test amavis[89917]: (89917-01) spam_scan: score=3.858 autolearn=no tests=[ALL_TRUSTED=-1.44,AWL=-2.226,DNS_FROM_RFC_BOGUSMX=2.125,RAZOR2_CF_RANGE_51_100=0.5,RAZOR2_CF_RANGE_E4_51_100=1.5,RAZOR2_CHECK=0.5,TVD_SPACE_RATIO=2.899]
May 21 15:02:19 srv-test amavis[89917]: (89917-01) prolong_timer spam_scan: remaining time = 478 s
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="2"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="2", matching_key="(constant:2)"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="4.2"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="4.2", matching_key="(constant:4.2)"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="6.5"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="6.5", matching_key="(constant:6.5)"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) final_destiny (ccat=0) is PASS, recip admin@domain.tld
May 21 15:02:19 srv-test amavis[89917]: (89917-01) final_destiny PASS, recip admin@domain.tld
May 21 15:02:19 srv-test amavis[89917]: (89917-01) do_notify_and_quar: ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="2"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="2", matching_key="(constant:2)"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="4.2"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="4.2", matching_key="(constant:4.2)"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="1"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="1", matching_key="(constant:1)"
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld" does not match
May 21 15:02:19 srv-test amavis[89917]: (89917-01) headers CLUSTERING: NEW CLUSTER : score=3.858, tag=1, tag2=0, local=1, bl=, s=, mangle=
May 21 15:02:19 srv-test amavis[89917]: (89917-01) header: X-Virus-Scanned: amavisd-new at domain.tld
May 21 15:02:19 srv-test amavis[89917]: (89917-01) header: X-Spam-Flag: NO
May 21 15:02:19 srv-test amavis[89917]: (89917-01) header: X-Spam-Score: 3.858
May 21 15:02:19 srv-test amavis[89917]: (89917-01) header: X-Spam-Level: ***
May 21 15:02:19 srv-test amavis[89917]: (89917-01) header: X-Spam-Status: No,
score=3.858 tagged_above=2 required=4.2 \ttests=[ALL_TRUSTED=-1.44, AWL=-2.226, DNS_FROM_RFC_BOGUSMX=2.125, \tRAZOR2_CF_RANGE_51_100=0.5, RAZOR2_CF_RANGE_E4_51_100=1.5, \tRAZOR2_CHECK=0.5, TVD_SPACE_RATIO=2.899] autolearn=no
May 21 15:02:19 srv-test amavis[89917]: (89917-01) header: Received: from srv-test.domain.tld ([127.0.0.1]) \tby localhost (srv-test.domain.tld [127.0.0.1]) (amavisd-new, port 10024) \twith ESMTP id I9A+8btgq79D for ; \tThu, 21 May 2009 15:02:16 +0300 (EEST)
May 21 15:02:19 srv-test amavis[89917]: (89917-01) headers CLUSTERING: done all 1 recips in one go
May 21 15:02:19 srv-test amavis[89917]: (89917-01) SPAM-TAG, -> , No, score=3.858 tagged_above=2 required=4.2 tests=[ALL_TRUSTED=-1.44, AWL=-2.226, DNS_FROM_RFC_BOGUSMX=2.125, RAZOR2_CF_RANGE_51_100=0.5, RAZOR2_CF_RANGE_E4_51_100=1.5, RAZOR2_CHECK=0.5, TVD_SPACE_RATIO=2.899] autolearn=no
May 21 15:02:19 srv-test amavis[89917]: (89917-01) dkim: candidate originators: 2822.From:, 2821.mail_from:
May 21 15:02:19 srv-test amavis[89917]: (89917-01) lookup => undef, "admin@domain.tld", no lookup tables
May 21 15:02:19 srv-test amavis[89917]: (89917-01) dkim: not signing, no applicable private key for domains domain.tld, s=, From:
May 21 15:02:19 srv-test amavis[89917]: (89917-01) (about to connect to [127.0.0.1]:10025) FWD via SMTP: ->
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp session: setting up a new session
May 21 15:02:19 srv-test amavis[89917]: (89917-01) establish_or_refresh, state: down
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp creating socket by IO::Socket::INET to [127.0.0.1]:10025
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
May 21 15:02:19 srv-test postfix/smtpd[89924]: connect from localhost[127.0.0.1]
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: receiving
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop read 39 chars< 220 srv-test.domain.tld ESMTP Postfix
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp resp to greeting: 220 srv-test.domain.tld ESMTP Postfix
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp cmd> EHLO localhost
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: sending
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop sent 16> EHLO localhost
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: receiving
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop read 186 chars< 250-srv-test.domain.tld 250-PIPELINING 250-SIZE 10240000 250-VRFY 250-ETRN 250-STARTTLS 250-AUTH PLAIN LOGIN 250-AUTH=PLAIN LOGIN 250-ENHANCEDSTATUSCODES 250-8BITMIME 250 DSN
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp resp to EHLO: 250 srv-test.domain.tld PIPELINING SIZE 10240000 VRFY ETRN STARTTLS AUTH PLAIN LOGIN AUTH=PLAIN LOGIN ENHANCEDSTATUSCODES 8BITMIME DSN
May 21 15:02:19 srv-test amavis[89917]: (89917-01) Remote host presents itself as: srv-test.domain.tld, handles DSN, handles PIPELINING
May 21 15:02:19 srv-test amavis[89917]: (89917-01) AUTH not needed, user='', MTA offers 'PLAIN LOGIN'
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp cmd> MAIL FROM: BODY=7BIT
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp cmd> RCPT TO: ORCPT=rfc822;admin@domain.tld
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp cmd> DATA
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
May 21 15:02:19 srv-test postfix/smtpd[89924]: EE433170D7: client=localhost[127.0.0.1]
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: sending
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop sent 113> MAIL FROM: BODY=7BIT RCPT TO: ORCPT=rfc822;admin@domain.tld DATA
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: receiving
May 21 15:02:19 srv-test postfix/cleanup[89921]: EE433170D7: message-id=<4A154296.6080800@domain.tld>
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop read 65 chars< 250 2.1.0 Ok 250 2.1.5 Ok 354 End data with .
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp resp to RCPT (pip) (): 250 2.1.5 Ok
May 21 15:02:19 srv-test postfix/qmgr[76330]: EE433170D7: from=, size=1356, nrcpt=1 (queue active)
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp resp to DATA: 354 End data with .
May 21 15:02:19 srv-test amavis[89917]: (89917-01) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0xbdc58c8)
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: needline=1, flush=0, wr=1, timeout=478
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: sending
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop sent 1181> X-Virus-Scanned: amavisd-new at domain.tld X-Spam-Flag: NOX-Spam-Score: 3.858 X-Spam-Level: *** X-Spam-Status: No, score=3.858 tagged_above=2 required=4.2 \ttests=[ALL_TRUSTED=-1.44, AWL=-2.226,  [...]
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: needline=1, flush=0, wr=0, timeout=478
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop: receiving
May 21 15:02:19 srv-test amavis[89917]: (89917-01) rw_loop read 36 chars< 250 2.0.0 Ok: queued as EE433170D7
May 21 15:02:19 srv-test amavis[89917]: (89917-01) smtp resp to data-dot (): 250 2.0.0 Ok: queued as EE433170D7
May 21 15:02:19 srv-test amavis[89917]: (89917-01) Amavis::Out::SMTP::Session close, keeping connection
May 21 15:02:19 srv-test amavis[89917]: (89917-01) prolong_timer fwd-end-chkpnt: timer set to 478 s
May 21 15:02:20 srv-test amavis[89917]: (89917-01) FWD via SMTP: -> ,BODY=7BIT 250 2.0.0 Ok, id=89917-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as EE433170D7
May 21 15:02:20 srv-test amavis[89917]: (89917-01) prolong_timer forwarding: remaining time = 478 s
May 21 15:02:20 srv-test amavis[89917]: (89917-01) DSN: sender is credible (orig), SA: 3.858,
May 21 15:02:20 srv-test amavis[89917]: (89917-01) lookup: (scalar) matches, result="18"
May 21 15:02:20 srv-test amavis[89917]: (89917-01) lookup => true,  "admin@domain.tld" matches, result="18", matching_key="(constant:18)"
May 21 15:02:20 srv-test amavis[89917]: (89917-01) dsn: from MTA 250 NonBlocking:CleanTag -> : on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, mta_resp: "250 2.0.0 Ok, id=89917-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as EE433170D7"
May 21 15:02:20 srv-test amavis[89917]: (89917-01) DSN: SUCC from MTA 250 NonBlocking:CleanTag, no DSN requested: ->
May 21 15:02:20 srv-test amavis[89917]: (89917-01) one_response_for_all : success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 Ok, id=89917-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as EE433170D7'
May 21 15:02:20 srv-test amavis[89917]: (89917-01) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 Ok, id=89917-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as EE433170D7
May 21 15:02:20 srv-test amavis[89917]: (89917-01) prolong_timer delivery-notification: remaining time = 478 s
May 21 15:02:20 srv-test amavis[89917]: (89917-01) fish_out_ip_from_received: 10.10.10.111
May 21 15:02:20 srv-test amavis[89917]: (89917-01) lookup_ip_acl (publicnetworks): key="10.10.10.111" matches "!10.0.0.0/8", result=0
May 21 15:02:20 srv-test amavis[89917]: (89917-01) parse_ip_address_from_received: 10.10.10.111
May 21 15:02:20 srv-test amavis[89917]: (89917-01) Passed CLEAN, MYNETS LOCAL [10.10.10.111] [10.10.10.111] -> , Message-ID: <4A154296.6080800@domain.tld>, mail_id: I9A+8btgq79D, Hits: 3.858, size: 610, queued_as: EE433170D7, 3149 ms
May 21 15:02:20 srv-test amavis[89917]: (89917-01) prolong_timer main_log_entry: remaining time = 478 s
May 21 15:02:20 srv-test amavis[89917]: (89917-01) Syslog warnings: 7 x No buffer space available
May 21 15:02:20 srv-test amavis[89917]: (89917-01) updating snmp variables
May 21 15:02:20 srv-test amavis[89917]: (89917-01) prolong_timer check done: remaining time = 478 s
May 21 15:02:20 srv-test amavis[89917]: (89917-01) sending SMTP response: "250 2.0.0 Ok, id=89917-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as EE433170D7"
May 21 15:02:20 srv-test amavis[89917]: (89917-01) ESMTP> 250 2.0.0 Ok, id=89917-01, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as EE433170D7
May 21 15:02:20 srv-test amavis[89917]: (89917-01) switch_to_client_time 480 s, smtp response sent
May 21 15:02:20 srv-test amavis[89917]: (89917-01) TempDir::strip: /var/amavis/tmp/amavis-20090521T150216-89917
May 21 15:02:20 srv-test amavis[89917]: (89917-01) rmdir_recursively: /var/amavis/tmp/amavis-20090521T150216-89917/parts, excl=1
May 21 15:02:20 srv-test amavis[89917]: (89917-01) TIMING - SMTP greeting: 29 (1%)1, SMTP EHLO: 7 (0%)1, SMTP pre-MAIL: 7 (0%)1, mkdir tempdir: 2 (0%)1, create email.txt: 3 (0%)2, SMTP pre-DATA-flush: 28 (1%)2, SMTP DATA: 65 (2%)4, check_init: 2 (0%)5, digest_hdr: 8 (0%)5, digest_body_dkim: 4 (0%)5, gen_mail_id: 5 (0%)5, mkdir parts: 13 (0%)5, mime_decode: 40 (1%)7, get-file-type1: 51 (2%)8, decompose_part: 7 (0%)9, parts_decode: 0 (0%)9, check_header: 7 (0%)9, AV-scan-1: 43 (1%)10, spam-wb-list: 12 (0%)11, SA parse: 21 (1%)11, SA check: 2553 (81%)92, update_cache: 41 (1%)93, decide_mail_destiny: 7 (0%)93, fwd-connect: 77 (2%)96, fwd-mail-pip: 20 (1%)96, fwd-rcpt-pip: 1 (0%)96, fwd-data-chkpnt: 1 (0%)96, write-header: 3 (0%)97, fwd-data-contents: 0 (0%)97, fwd-end-chkpnt: 15 (0%)97, prepare-dsn: 5 (0%)97, main_log_entry: 76 (2%)100, update_snmp: 5 (0%)100, SMTP pre-response: 2 (0%)100, SMTP response: 2 (0%)100, unlink-2-files: 2 (0%)100, rundown: 2 (0%)100
May 21 15:02:20 srv-test amavis[89917]: (89917-01) idle_proc, 6: was busy, 3096.9 ms, total idle 0.003 s, busy 3.165 s
May 21 15:02:20 srv-test amavis[89917]: (89917-01) idle_proc, 5: was idle, 0.5 ms, total idle 0.004 s, busy 3.165 s
May 21 15:02:20 srv-test amavis[89917]: (89917-01) ESMTP< QUIT
May 21 15:02:20 srv-test amavis[89917]: (89917-01) switch_to_my_time     480 s, SMTP QUIT received
May 21 15:02:20 srv-test amavis[89917]: (89917-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmiss

Добавить комментарий

Ваш адрес email не будет опубликован.