Hello Henrique,
thank you for the response and guide to modify amavisd-new, I have done that
and restarted amavis with
"/etc/init.d/amavis debug".
The results are in the attachment, hope it will help.
About the DB schema, someone asked before, I'm using ISPConfig 3.1, so the
whole amavis configuration is done by that.
Best regards
Jakub Novak
______________________________________________________________
> Od: Henrique de Moraes Holschuh <h...@debian.org>
> Komu: 847...@bugs.debian.org
> Datum: 12.02.2017 17:26
> Předmět: Re: Bug#847311: amavisd-new: After the last Debian update Amavis
>
On Sun, 12 Feb 2017, Brian May wrote:
> >> https://github.com/perl5-dbi/DBD-mysql/issues/78
<https://github.com/perl5-dbi/DBD-mysql/issues/78>
>
> Please read the latest message on the above report...
Jakub,
This issue is a nasty problem between amavisd-new and DBD-mysql. It is
yet not clear which program is at fault, or if it is an ABI break gone
bad, etc.
The upstream bug report is at:
https://github.com/perl5-dbi/DBD-mysql/issues/78
<https://github.com/perl5-dbi/DBD-mysql/issues/78>
The amavisd-new Debian maintainers and DBD upstream are having trouble
to reproduce the issue, although we do have breakage reports also from
in Fedora, Gentoo and FreeBSD. There is cleary some factor we're
missing.
Upstream DBD asks (in the issue linked above):
"So I see only option now, enabling DBI tracing in that problematic
amavis code and sending stderr trace output for later inspection.
Tracing can be enabled by DBI->trace(2); and disabled by DBI->trace(0);"
Would you be willing to reproduce the issue you reported with the
changes requested by upstream?
AFAIK, you just need to add:
$conn_h->trace(2);
around line 20211 in /usr/sbin/amavisd-new (I think right after
or right before the
$conn_h->begin_work_nontransaction; # (re)connect if not connected
line would work best.
It is probably best to disable the tracing at the end of the function, by
adding:
$conn_h->trace(0);
right before the line reading "section_time('lookup_sql');" around line
number 20262.
If that doesn't work, try using DBI->trace(2); and DBI->trace(0);
instead.
Since the trace information goes to stderr, it would probably be best to
debug amavis by running it in "foreground" mode, and diverting stderr
to a file...
Thanks!
--
Henrique Holschuh
Feb 12 20:28:14.535 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
Net::Server: 2017/02/12-20:28:14 CONNECT TCP Peer: "[127.0.0.1]:37442" Local:
"[127.0.0.1]:10024"
Feb 12 20:28:14.536 mailserver.domain2.com /usr/sbin/amavisd-new[6693]: loaded
base policy bank
Feb 12 20:28:14.538 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Feb 12 20:28:14.538 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
process_request: fileno sock=15, STDIN=0, STDOUT=1
Feb 12 20:28:14.538 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to
288.000 s
Feb 12 20:28:14.538 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in
480.0 s
Feb 12 20:28:14.539 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
process_request: suggested_protocol="" on a TCP socket
Feb 12 20:28:14.540 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Feb 12 20:28:14.540 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:14.540 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 4: was busy, 5.3 ms, total idle 0.000 s, busy 0.005 s
Feb 12 20:28:14.540 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp readline: read 20 bytes, new size: 20
Feb 12 20:28:14.540 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.000 s, busy 0.005 s
Feb 12 20:28:14.541 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SMTP< EHLO mailserver.domain2.com\r\n
Feb 12 20:28:14.541 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s,
set to 288.000 s
Feb 12 20:28:14.541 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 288, was 480,
deadline in 480.0 s
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-[127.0.0.1]
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-VRFY
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-PIPELINING
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-SIZE
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-ENHANCEDSTATUSCODES
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-8BITMIME
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-SMTPUTF8
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250-DSN
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:14.542 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 6: was busy, 2.0 ms, total idle 0.000 s, busy 0.007 s
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp readline: read 244 bytes, new size: 244
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.000 s, busy 0.007 s
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP< XFORWARD NAME=mailserver.domain.com ADDR=86.49.134.180
PORT=59182\r\n
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0
s, set to 288.000 s
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was
480, deadline in 480.0 s
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 6: was busy, 0.5 ms, total idle 0.000 s, busy 0.008 s
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.008 s
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP< XFORWARD PROTO=ESMTP HELO=mailserver.domain.com
IDENT=81467120639 SOURCE=REMOTE\r\n
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0
s, set to 288.000 s
Feb 12 20:28:14.543 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 288, was
480, deadline in 480.0 s
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 6: was busy, 0.4 ms, total idle 0.001 s, busy 0.008 s
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.008 s
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP< MAIL FROM:<sen...@domain.com> SIZE=2287 BODY=7BIT\r\n
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s,
set to 288.000 s
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 288, was 480,
deadline in 480.0 s
Feb 12 20:28:14.544 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) check_mail_begin_task: task_count=1
Feb 12 20:28:14.545 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) TempDir::prepare_dir: created directory
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH
Feb 12 20:28:14.545 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) TempDir::prepare_file: creating file
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/email.txt
Feb 12 20:28:14.545 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) TempDir::prepare_file: layers: unix,perlio
Feb 12 20:28:14.545 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_ip_acl (client_ipaddr_policy) arr.obj: key="86.49.134.180",
no match
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [debug_sender] => undef, "sen...@domain.com" does not match
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) mesage size set to a declared size 2287
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250 2.1.0 Sender <sen...@domain.com> OK
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 6: was busy, 2.4 ms, total idle 0.001 s, busy 0.011 s
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.011 s
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP< RCPT TO:<recei...@domain2.com>
ORCPT=rfc822;recei...@domain2.com\r\n
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s,
set to 288.000 s
Feb 12 20:28:14.546 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 288, was 480,
deadline in 480.0 s
Feb 12 20:28:14.547 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup => undef, "recei...@domain2.com", no lookup tables
Feb 12 20:28:14.547 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_acl(recei...@domain2.com), no match
Feb 12 20:28:14.547 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [local_domains] => undef, "recei...@domain2.com" does not
match
Feb 12 20:28:14.547 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) query_keys: recei...@domain2.com, @domain2.com, @.domain2.com,
@.com, @.
Feb 12 20:28:14.547 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql sel_policy "recei...@domain2.com", query args:
[recei...@domain2.com,12], [@domain2.com,12], [@.domain2.com,12], [@.com,12],
[@.,12]
Feb 12 20:28:14.547 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql select: SELECT *,spamfilter_users.id FROM
spamfilter_users LEFT JOIN spamfilter_policy ON
spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email IN
(?,?,?,?,?) ORDER BY spamfilter_users.priority DESC
DBI 1.636-ithread default trace level set to 0x0/2 (pid 6693 pi
559a5c331010) at (eval 112) line 292 via (eval 112) line 49
Feb 12 20:28:14.548 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) sql begin, nontransaction
Feb 12 20:28:14.548 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Connecting to SQL database server
Feb 12 20:28:14.548 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) connect_to_sql: trying
'DBI:mysql:database=dbispconfig;host=127.0.0.1;port=3306'
-> DBI->connect(DBI:mysql:database=dbispconfig;host=127.0.0.1;port=3306,
ispconfig, ****, HASH(0x559a6172f8d0))
-> DBI->install_driver(mysql) for linux perl=5.024001 pid=6693 ruid=115
euid=115
install_driver: DBD::mysql version 4.041 loaded from
/usr/lib/x86_64-linux-gnu/perl5/5.24/DBD/mysql.pm
<- install_driver= DBI::dr=HASH(0x559a61734a70)
!! The warn '0' was CLEARED by call to connect method
-> connect for DBD::mysql::dr (DBI::dr=HASH(0x559a61734a70)~0x559a61734398
'database=dbispconfig;host=127.0.0.1;port=3306' 'ispconfig' ****
HASH(0x559a5ef7b6a0)) thr#559a5c331010
imp_dbh->connect: dsn = database=dbispconfig;host=127.0.0.1;port=3306, uid =
ispconfig, pwd = dfg8979087jkJKGHjhfghp98y89rfgwPPs
imp_dbh->my_login : dbname = dbispconfig, uid = ispconfig, pwd =
dfg8979087jkJKGHjhfghp98y89rfgwPPs,host = 127.0.0.1, port = 3306
imp_dbh->mysql_dr_connect: host = |127.0.0.1|, port = 3306, uid = ispconfig,
pwd = dfg8979087jkJKGHjhfghp98y89rfgwPPs
imp_dbh->bind_type_guessing: 0
imp_dbh->use_server_side_prepare: 0
imp_dbh->disable_fallback_for_server_prepare: 0
imp_dbh->mysql_dr_connect: client_flags = 2
imp_dbh->mysql_dr_connect: <- <- connect= ( DBI::db=HASH(0x559a61860a50) )
[1 items] at DBI.pm line 684
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER
'RaiseError' 0) thr#559a5c331010
<- STORE= ( 1 ) [1 items] at DBI.pm line 736
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER
'PrintError' 0) thr#559a5c331010
<- STORE= ( 1 ) [1 items] at DBI.pm line 736
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER
'AutoCommit' 1) thr#559a5c331010
<- STORE= ( 1 ) [1 items] at DBI.pm line 736
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER
'mysql_conn_attrs' HASH(0x559a63319220)) thr#559a5c331010
$h->{'mysql_conn_attrs'}=HASH(0x559a63319220) ignored for invalid
driver-specific attribute
<- STORE= ( '' ) [1 items] at DBI.pm line 739
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER 'Taint' 1)
thr#559a5c331010
T <- STORE= ( 1 ) [1 items] at DBI.pm line 739
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER 'Username'
'ispconfig') thr#559a5c331010
T <- STORE= ( 1 ) [1 items] at DBI.pm line 739
-> connected in DBD::_::db for DBD::mysql::db
(DBI::db=HASH(0x559a61860a50)~0x559a6330ef88
'DBI:mysql:database=dbispconfig;host=127.0.0.1;port=3306' 'ispconfig' ****
HASH(0x559a6172f8d0)) thr#559a5c331010
T <- connected= ( undef ) [1 items] at DBI.pm line 746
<- connect= DBI::db=HASH(0x559a61860a50)
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER
'dbi_connect_closure' CODE(0x559a617344b8)) thr#559a5c331010
T <- STORE= ( 1 ) [1 items] at DBI.pm line 755
Feb 12 20:28:14.551 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) connect_to_sql:
'DBI:mysql:database=dbispconfig;host=127.0.0.1;port=3306' succeeded
-> STORE for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER
'RaiseError' 1) thr#559a5c331010
T <- STORE= ( 1 ) [1 items] at (eval 110) line 253
-> do for DBD::mysql::db (DBI::db=HASH(0x559a61860a50)~0x559a6330ef88 'SET
NAMES 'utf8'') thr#559a5c331010
mysql.xs do() use_server_side_prepare 0, async 0
mysql_st_internal_execute MYSQL_VERSION_ID 100028
>parse_params statement SET NAMES 'utf8'
T <- do= ( '0E0' ) [1 items] at (eval 110) line 257
-> FETCH for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER 'Driver')
thr#559a5c331010
T <- FETCH= ( DBI::dr=HASH(0x559a61734a70) ) [1 items] at (eval 110) line 74
-> FETCH for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER 'Driver')
thr#559a5c331010
T <- FETCH= ( DBI::dr=HASH(0x559a61734a70) ) [1 items] at (eval 110) line 74
<> FETCH= ( 'mysql' ) [1 items] ('Name' from cache) at (eval 110) line 74
Feb 12 20:28:14.552 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) sql: preparing and executing (5 args): SELECT *,spamfilter_users.id
FROM spamfilter_users LEFT JOIN spamfilter_policy ON
spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email IN
(?,?,?,?,?) ORDER BY spamfilter_users.priority DESC
-> prepare for DBD::mysql::db (DBI::db=HASH(0x559a61860a50)~0x559a6330ef88
'SELECT *,spamfilter_users.id FROM spamfilter_users LEFT JOIN spamfilter_policy
ON spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email
IN (?,?,?,?,?) ORDER BY spamfilter_users.priority DESC') thr#559a5c331010
-> dbd_st_prepare MYSQL_VERSION_ID 100028, SQL statement: SELECT
*,spamfilter_users.id FROM spamfilter_users LEFT JOIN spamfilter_policy ON
spamfilter_users.policy_id=spamfilter_policy.id WHERE spamfilter_users.email IN
(?,?,?,?,?) ORDER BY spamfilter_users.priority DESC
>- dbd_st_free_result_sets
<- dbd_st_free_result_sets RC -1
<- dbd_st_free_result_sets
>count_params statement SELECT *,spamfilter_users.id FROM spamfilter_users LEFT
>JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id
>WHERE spamfilter_users.email IN (?,?,?,?,?) ORDER BY spamfilter_users.priority
>DESC
<- dbd_st_prepare
T <- prepare= ( DBI::st=HASH(0x559a6332c650) ) [1 items] at (eval 110) line
161
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90 1 'recei...@domain2.com' 12)
thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90 2 '@domain2.com' 12)
thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90 3 '@.domain2.com' 12)
thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90 4 '@.com' 12) thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90 5 '@.' 12) thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> execute for DBD::mysql::st (DBI::st=HASH(0x559a6332c650)~0x559a620afe90)
thr#559a5c331010
-> dbd_st_execute for 559a5f004e98
>- dbd_st_free_result_sets
<- dbd_st_free_result_sets RC -1
<- dbd_st_free_result_sets
mysql_st_internal_execute MYSQL_VERSION_ID 100028
>parse_params statement SELECT *,spamfilter_users.id FROM spamfilter_users LEFT
>JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id
>WHERE spamfilter_users.email IN (?,?,?,?,?) ORDER BY spamfilter_users.priority
>DESC
Binding parameters: SELECT *,spamfilter_users.id FROM spamfilter_users LEFT
JOIN spamfilter_policy ON spamfilter_users.policy_id=spamfilter_policy.id WHERE
spamfilter_users.email IN
('recei...@domain2.com','@domain2.com','@.domain2.com','@.com','@.') ORDER BY
spamfilter_users.priority DESC
<- dbd_st_execute returning imp_sth->row_num 1
T <- execute= ( 1 ) [1 items] at (eval 110) line 172
-> err in DBD::_::common for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90) thr#559a5c331010
T <- err= ( undef ) [1 items] at (eval 110) line 172
-> errstr in DBD::_::common for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90) thr#559a5c331010
T <- errstr= ( undef ) [1 items] at (eval 110) line 172
-> fetchrow_arrayref for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90) thr#559a5c331010
-> dbd_st_fetch
dbd_st_fetch for 559a5f004e98, chopblanks 0
dbd_st_fetch result set details
imp_sth->result=559a634ac138
mysql_num_fields=61
mysql_num_rows=1
mysql_affected_rows=1
dbd_st_fetch for 559a5f004e98, currow= 1
<- dbd_st_fetch, 61 cols
T <- fetchrow_arrayref= ( [ 4 1 1 'riud' 'riud' '' 1 5 1
'recei...@domain2.com' 'recei...@domain2.com' 'Y' 1 1 0 'riud' 'riud' 'r'
'Normalni' 'N' 'N' 'N' 'N' 'N' 'N' 'N' 'N' 'N' '' '' '' '' '' '' 0 0 0 0 0 ''
'' '' '' 'N' 'N' 'N' '' '' '' '' '' '' '' 0 '' -1 24 -1 24 'N' 4 ] ) [1 items]
row1 at (eval 110) line 140
-> FETCH for DBD::mysql::st (DBI::st=HASH(0x559a620afe90)~INNER 'NAME_lc')
thr#559a5c331010
-> dbd_st_FETCH_attrib for 559a5f004e98, key NAME_lc
-> dbd_st_FETCH_attrib for 559a5f004e98, key NAME
T <- FETCH= ( [ 'id' 'sys_userid' 'sys_groupid' 'sys_perm_user'
'sys_perm_group' 'sys_perm_other' 'server_id' 'priority' 'policy_id' 'email'
'fullname' 'local' 'id' 'sys_userid' 'sys_groupid' 'sys_perm_user'
'sys_perm_group' 'sys_perm_other' 'policy_name' 'virus_lover' 'spam_lover'
'banned_files_lover' 'bad_header_lover' 'bypass_virus_checks'
'bypass_spam_checks' 'bypass_banned_checks' 'bypass_header_checks'
'spam_modifies_subj' 'virus_quarantine_to' 'spam_quarantine_to'
'banned_quarantine_to' 'bad_header_quarantine_to' 'clean_quarantine_to'
'other_quarantine_to' 'spam_tag_level' 'spam_tag2_level' 'spam_kill_level'
'spam_dsn_cutoff_level' 'spam_quarantine_cutoff_level' 'addr_extension_virus'
'addr_extension_spam' 'addr_extension_banned' 'addr_extension_bad_header'
'warnvirusrecip' 'warnbannedrecip' 'warnbadhrecip' 'newvirus_admin'
'virus_admin' 'banned_admin' 'bad_header_admin' 'spam_admin' 'spam_subject_tag'
'spam_subject_tag2' 'message_size_limit' 'banned_rulenames' 'policyd_quota_in'
'policyd_quota_in_period' 'policyd_quota_out' 'policyd_quota_out_period'
'policyd_greylist' 'id' ] ) [1 items] at (eval 112) line 308
-> fetchrow_arrayref for DBD::mysql::st
(DBI::st=HASH(0x559a6332c650)~0x559a620afe90) thr#559a5c331010
-> dbd_st_fetch
dbd_st_fetch for 559a5f004e98, chopblanks 0
dbd_st_fetch result set details
imp_sth->result=559a634ac138
mysql_num_fields=61
mysql_num_rows=1
mysql_affected_rows=1
dbd_st_fetch for 559a5f004e98, currow= 2
dbd_st_fetch, no more rows to fetch
--> dbd_st_finish
>- dbd_st_free_result_sets
<- dbd_st_free_result_sets RC -1
<- dbd_st_free_result_sets
<-- dbd_st_finish
T <- fetchrow_arrayref= ( undef ) [1 items] row1 at (eval 110) line 140
Feb 12 20:28:14.554 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql(recei...@domain2.com) matches, result=(id=>"4",
sys_userid=>"1", sys_groupid=>"0", sys_perm_user=>"riud",
sys_perm_group=>"riud", sys_perm_other=>"r", server_id=>"1", priority=>"5",
policy_id=>"1", email=>"recei...@domain2.com",
fullname=>"recei...@domain2.com", local=>"Y", id=>"4", sys_userid=>"1",
sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud",
sys_perm_other=>"r", policy_name=>"Normalni", virus_lover=>"N",
spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N",
bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N",
bypass_header_checks=>"N", spam_modifies_subj=>"N", virus_quarantine_to=>"",
spam_quarantine_to=>"", banned_quarantine_to=>"", bad_header_quarantine_to=>"",
clean_quarantine_to=>"", other_quarantine_to=>"", spam_tag_level=>"0",
spam_tag2_level=>"0", spam_kill_level=>"0", spam_dsn_cutoff_level=>"0",
spam_quarantine_cutoff_level=>"0", addr_extension_virus=>"",
addr_extension_spam=>"", addr_extension_banned=>"",
addr_extension_bad_header=>"", warnvirusrecip=>"N", warnbannedrecip=>"N",
warnbadhrecip=>"N", newvirus_admin=>"", virus_admin=>"", banned_admin=>"",
bad_header_admin=>"", spam_admin=>"", spam_subject_tag=>"",
spam_subject_tag2=>"", message_size_limit=>"0", banned_rulenames=>"",
policyd_quota_in=>"-1", policyd_quota_in_period=>"24", policyd_quota_out=>"-1",
policyd_quota_out_period=>"24", policyd_greylist=>"N", id=>"4")
Feb 12 20:28:14.554 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(message_size_limit) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [message_size_limit] => false, "recei...@domain2.com"
matches, result="0", matching_key="id=>"4", sys_userid=>"1", sys_groupid=>"0",
sys_perm_user=>"riud", sys_perm_group=>"riud", sys_perm_other=>"r",
server_id=>"1", priority=>"5", policy_id=>"1", email=>"recei...@domain2.com",
fullname=>"recei...@domain2.com", local=>"Y", id=>"4", sys_userid=>"1",
sys_groupid=>"0", sys_perm_user=>"riud", sys_perm_group=>"riud",
sys_perm_other=>"r", policy_name=>"Normalni", virus_lover=>"N",
spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"N",
bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N",
bypass_header_checks=>"N", spam_modifies_subj=>"N", virus_quarantine_to=>"",
spam_quarantine_to=>"", banned_quarantine_to=>"", bad_header_quarantine_to=>"",
clean_quarantine_to=>"", other_quarantine_to=>"", spam_tag_level=>"0",
spam_tag2_level=>"0", spam_kill_level=>"0", spam_dsn_cutoff_level=>"0",
spam_quarantine_cutoff_level=>"0", addr_extension_virus=>"",
addr_extension_spam=>"", addr_extension_banned=>"",
addr_extension_bad_header=>"", warnvirusrecip=>"N", warnbannedrecip=>"N",
warnbadhrecip=>"N", newvirus_admin=>"", virus_admin=>"", banned_admin=>"",
bad_header_admin=>"", spam_admin=>"", spam_subject_tag=>"",
spam_subject_tag2=>"", message_size_limit=>"0", banned_rulenames=>"",
policyd_quota_in=>"-1", policyd_quota_in_period=>"24", policyd_quota_out=>"-1",
policyd_quota_out_period=>"24", policyd_greylist=>"N", id=>"4""
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250 2.1.5 Recipient <recei...@domain2.com> OK
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 6: was busy, 8.7 ms, total idle 0.001 s, busy 0.019 s
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 5: was idle, 0.1 ms, total idle 0.001 s, busy 0.019 s
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP< DATA\r\n
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s,
set to 288.000 s
Feb 12 20:28:14.555 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx SMTP DATA): timer 288, was 480,
deadline in 480.0 s
Feb 12 20:28:14.556 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP [127.0.0.1]:10024
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH: <sen...@domain.com>
-> <recei...@domain2.com> SIZE=2287 BODY=7BIT Received: from
mailserver.domain2.com ([127.0.0.1]) by localhost (mailserver.domain2.com
[127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <recei...@domain2.com>;
Sun, 12 Feb 2017 20:28:14 +0100 (CET)
Feb 12 20:28:14.556 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Feb 12 20:28:14.556 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:14.556 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, receiving data
Feb 12 20:28:14.581 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp copy: read 2296 bytes into buffer, new size: 2296
Feb 12 20:28:14.581 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp copy: 6 bytes still buffered at end
Feb 12 20:28:14.581 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s,
set to 288.000 s
Feb 12 20:28:14.582 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx data-end): timer 288, was 480,
deadline in 480.0 s
Feb 12 20:28:14.582 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP< .<CR><LF>
Feb 12 20:28:14.583 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
Feb 12 20:28:14.583 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline digest_pre - deadline in 480.0 s, set to 288.000 s
Feb 12 20:28:14.583 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer digest_pre: timer 288, was 288, deadline in 480.0 s
Feb 12 20:28:14.584 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) DNS resolver created, UDP payload size 1220, NS: 8.8.8.8, 8.8.4.4
Feb 12 20:28:14.584 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_body_digest: reading header section from memory
Feb 12 20:28:14.585 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_body_digest: feeding header section to DKIM verifier
Feb 12 20:28:14.586 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_body_digest: sending h/b separator to DKIM
Feb 12 20:28:14.586 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline digest_hdr - deadline in 480.0 s, set to 288.000 s
Feb 12 20:28:14.586 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer digest_hdr: timer 288, was 288, deadline in 480.0 s
Feb 12 20:28:14.587 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_body_digest: reading mail body from memory, 1 DKIM signatures
Feb 12 20:28:14.642 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline digest_body - deadline in 479.9 s, set to 288.000 s
Feb 12 20:28:14.642 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer digest_body: timer 288, was 288, deadline in 479.9 s
Feb 12 20:28:14.642 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_body_digest: message size 2287, header+sep 1772, body 515
Feb 12 20:28:14.642 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) body type (8bit-MIMEtransport): labeled 7BIT, good (h=0, b=0)
Feb 12 20:28:14.643 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) body hash: 9b3e6731e91233893a4248fee75d0f70
Feb 12 20:28:14.644 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ip_from_received: 86.49.134.180
Feb 12 20:28:14.645 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ip_from_received: 127.0.0.1
Feb 12 20:28:14.645 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ip_from_received: 127.0.0.1
Feb 12 20:28:14.645 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ip_from_received: 46.135.5.19
Feb 12 20:28:14.645 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches
"!127.0.0.0/8", result=0
Feb 12 20:28:14.646 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_ip_acl (public_nets) arr.obj: key="86.49.134.180" matches
"::ffff:0:0/96", result=1
Feb 12 20:28:14.646 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches
"!127.0.0.0/8", result=0
Feb 12 20:28:14.646 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_ip_acl (public_nets) arr.obj: key="127.0.0.1" matches
"!127.0.0.0/8", result=0
Feb 12 20:28:14.646 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_ip_acl (public_nets) arr.obj: key="46.135.5.19" matches
"::ffff:0:0/96", result=1
Feb 12 20:28:14.646 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) trace: ESMTP://[127.0.0.1]:37442 < ESMTPS://[86.49.134.180]:59182 <
ESMTP://127.0.0.1 < ESMTP://127.0.0.1 < ESMTPSA://46.135.5.19
Feb 12 20:28:14.646 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) dkim: public key s=dkim d=domain.com v=DKIM1, 1024-bit key
Feb 12 20:28:14.647 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) dkim: VALID, IN_FUTURE:(0 0:00:07) Author+Sender+MailFrom signature
by d=domain.com, From: <sen...@domain.com>, a=rsa-sha256, c=relaxed/simple,
s=dkim, i=@domain.com
Feb 12 20:28:14.647 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Original mail size: 2287; quota set to: 1143500 bytes (fmin=5,
fmax=500, qmin=102400, qmax=314572800)
Feb 12 20:28:14.647 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Checking: IMQpZ1XJLZ-N [86.49.134.180] <sen...@domain.com> ->
<recei...@domain2.com>
Feb 12 20:28:14.647 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) 2822.From: <sen...@domain.com>
Feb 12 20:28:14.647 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(local) rec=0, "recei...@domain2.com" result: "Y"
Feb 12 20:28:14.647 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [local_domains] => true, "recei...@domain2.com" matches,
result="Y", matching_key="/cached/"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(bypass_virus_checks) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [bypass_virus_checks] => false, "recei...@domain2.com"
matches, result="0", matching_key="/cached/"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(bypass_banned_checks) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [bypass_banned_checks] => false, "recei...@domain2.com"
matches, result="0", matching_key="/cached/"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(bypass_spam_checks) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [bypass_spam_checks] => false, "recei...@domain2.com"
matches, result="0", matching_key="/cached/"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(id) rec=0, "recei...@domain2.com" result: "4"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [users.id], 1 matches for "recei...@domain2.com", results:
"/cached/"=>"4"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(policy_id) rec=0, "recei...@domain2.com" result: "1"
Feb 12 20:28:14.648 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [users.policy_id] => true, "recei...@domain2.com" matches,
result="1", matching_key="/cached/"
Feb 12 20:28:14.649 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Extracting mime components from a string
Feb 12 20:28:14.652 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Issued a new file name: p001
Feb 12 20:28:14.653 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Issued a new file name: p002
Feb 12 20:28:14.654 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Issued a new pseudo part: p003
Feb 12 20:28:14.654 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) p003 1 Content-Type: multipart/alternative
Feb 12 20:28:14.654 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) mime_decode_epilogue: 1 lines
Feb 12 20:28:14.654 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Charging 4 bytes to remaining quota 1143500 (out of 1143500, (0%)) -
by mime_decode
Feb 12 20:28:14.654 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) p001 1/1 Content-Type: text/plain, size: 4 B, name:
Feb 12 20:28:14.654 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) reparenting p001 from p000 to p003
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Charging 153 bytes to remaining quota 1143496 (out of 1143500, (0%))
- by mime_decode
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) p002 1/2 Content-Type: text/html, size: 153 B, name:
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) reparenting p002 from p000 to p003
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline mime_decode - deadline in 479.9 s, set to 288.000 s
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer mime_decode: timer 288, was 288, deadline in 479.9 s
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline mime_decode-1 - deadline in 479.9 s, set to 288.000 s
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer mime_decode-1: timer 288, was 288, deadline in 479.9 s
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) decode_parts: level=1, #parts=3 : p001, p002, p003
Feb 12 20:28:14.655 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) running file(1) on 2 files, arglist size 23
Feb 12 20:28:14.658 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) run_command: [6713] /usr/bin/file p001 p002 </dev/null 2>&1
Feb 12 20:28:14.665 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) result line from file(1): p001: ASCII text, with no line
terminators\n
Feb 12 20:28:14.666 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_re("ASCII text, with no line terminators") matches key
"(?^i:^(ASCII|text)\\b)", result="asc"
Feb 12 20:28:14.666 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [map_full_type_to_short_type] => true, "ASCII text, with no
line terminators" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Feb 12 20:28:14.666 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) File-type of p001: ASCII text, with no line terminators; (asc)
Feb 12 20:28:14.666 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) result line from file(1): p002: XML 1.0 document, ASCII text\n
Feb 12 20:28:14.666 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_re("XML 1.0 document, ASCII text") matches key
"(?^i:\\btext\\b)", result="asc"
Feb 12 20:28:14.666 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [map_full_type_to_short_type] => true, "XML 1.0 document,
ASCII text" matches, result="asc", matching_key="(?^i:\\btext\\b)"
Feb 12 20:28:14.666 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) File-type of p002: XML 1.0 document, ASCII text; (asc)
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) decompose_part: p001 - atomic
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) decompose_part: p002 - atomic
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline parts_decode - deadline in 479.9 s, set to 288.000 s
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer parts_decode: timer 288, was 288, deadline in 479.9 s
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(bypass_header_checks) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [bypass_header_checks] => false, "recei...@domain2.com"
matches, result="0", matching_key="/cached/"
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) check_header: 0, OK
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(bypass_header_checks) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [bypass_header_checks] => false, "recei...@domain2.com"
matches, result="0", matching_key="/cached/"
Feb 12 20:28:14.667 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Checking for banned types and filenames
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(banned_rulenames) rec=0, "recei...@domain2.com"
result: ""
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup: (scalar) matches, result="DEFAULT"
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [banned_filename], 2 matches for "recei...@domain2.com",
results: "/cached/"=>"", "(constant:DEFAULT)"=>"DEFAULT"
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) collect banned table[0]: recei...@domain2.com, tables:
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) collect banned table[1]: recei...@domain2.com, tables:
DEFAULT=>Amavis::Lookup::RE=ARRAY(0x559a5d703a40)
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) starting banned checks - traversing message structure tree
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) doing banned check for recei...@domain2.com on multipart/alternative
| text/plain,.asc
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [check_bann:recei...@domain2.com] => undef,
["multipart/alternative","text/plain",".asc"] does not match
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [banned_namepath_re] => undef,
"P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc" does
not match
Feb 12 20:28:14.668 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) p.path recei...@domain2.com: "P=p003,L=1,M=multipart/alternative |
P=p001,L=1/1,M=text/plain,T=asc"
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) check_for_banned (p003,p002) multipart/alternative | text/html,.asc
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) doing banned check for recei...@domain2.com on multipart/alternative
| text/html,.asc
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_re(["multipart/alternative","text/html",".asc"]), no matches
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [check_bann:recei...@domain2.com] => undef,
["multipart/alternative","text/html",".asc"] does not match
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [banned_namepath_re] => undef,
"P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc" does
not match
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) p.path recei...@domain2.com: "P=p003,L=1,M=multipart/alternative |
P=p002,L=1/2,M=text/html,T=asc"
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) banned check: any=0, all=N (1)
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_re("MAIL"), no matches
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [keep_decoded_original] => undef, "MAIL" does not match
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Calling virus scanners, 2 files to scan in
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) invoking av-scanner ClamAV-clamd
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd)
/var/run/clamav/clamd.ctl
Feb 12 20:28:14.669 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.9 s
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) run_av Using (ClamAV-clamd): (code) CONTSCAN
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts\n
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline ask_daemon_internal_connect_pre - deadline in 479.9 s,
set to 288.000 s
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline ask_daemon_internal_connect - deadline in 479.9 s, set
to 10.000 s
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer ask_daemon_internal_connect: timer 10, was 288,
deadline in 479.9 s
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.ctl
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout
set to 10
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) connected to /var/run/clamav/clamd.ctl successfully
Feb 12 20:28:14.670 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ClamAV-clamd: Sending CONTSCAN
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts\n to socket
/var/run/clamav/clamd.ctl
Feb 12 20:28:14.671 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=0, flush=1, wr=1, timeout=10
Feb 12 20:28:14.671 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: sending 73 chars
Feb 12 20:28:14.671 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop sent 73> CONTSCAN
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts\n
Feb 12 20:28:14.671 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline ask_daemon_internal_scan - deadline in 479.9 s, set to
288.000 s
Feb 12 20:28:14.671 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline
in 479.9 s
Feb 12 20:28:14.671 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
Feb 12 20:28:14.673 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: receiving
Feb 12 20:28:14.673 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop read 68 chars<
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts: OK\n
Feb 12 20:28:14.673 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=0, flush=0, wr=0, timeout=287.999
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: receiving
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop read: got eof
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline ask_daemon_internal - deadline in 479.9 s, set to
288.000 s
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in
479.9 s
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline run_av_3 - deadline in 479.9 s, set to 288.000 s
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer run_av_3: timer 288, was 288, deadline in 479.9 s
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) run_av (ClamAV-clamd) result:
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts: OK\n
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) run_av (ClamAV-clamd): CLEAN
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) run_av (ClamAV-clamd) result: clean
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) wbl: checking sender <sen...@domain.com>
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) wbl: (SQL) recip <recei...@domain2.com>, 1 matches
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_acl(sen...@domain.com), no match
Feb 12 20:28:14.674 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [local_domains] => undef, "sen...@domain.com" does not match
Feb 12 20:28:14.675 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) query_keys: sen...@domain.com, @domain.com, @.domain.com, @.com, @.
Feb 12 20:28:14.675 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql sel_wblist "sen...@domain.com", query args: "4",
[sen...@domain.com,12], [@domain.com,12], [@.domain.com,12], [@.com,12], [@.,12]
Feb 12 20:28:14.675 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql select: SELECT wb FROM spamfilter_wblist WHERE
(spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) AND
(spamfilter_wblist.active="y") ORDER BY spamfilter_wblist.priority DESC
DBI 1.636-ithread default trace level set to 0x0/2 (pid 6693 pi
559a5c331010) at (eval 112) line 292 via (eval 112) line 49
Feb 12 20:28:14.675 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) sql begin, nontransaction
-> FETCH for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER 'Driver')
thr#559a5c331010
T <- FETCH= ( DBI::dr=HASH(0x559a61734a70) ) [1 items] at (eval 110) line 74
-> FETCH for DBD::mysql::db (DBI::db=HASH(0x559a6330ef88)~INNER 'Driver')
thr#559a5c331010
T <- FETCH= ( DBI::dr=HASH(0x559a61734a70) ) [1 items] at (eval 110) line 74
<> FETCH= ( 'mysql' ) [1 items] ('Name' from cache) at (eval 110) line 74
Feb 12 20:28:14.675 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) sql: preparing and executing (6 args): SELECT wb FROM
spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND (spamfilter_wblist.email
IN (?,?,?,?,?)) AND (spamfilter_wblist.active="y") ORDER BY
spamfilter_wblist.priority DESC
-> prepare for DBD::mysql::db (DBI::db=HASH(0x559a61860a50)~0x559a6330ef88
'SELECT wb FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND
(spamfilter_wblist.email IN (?,?,?,?,?)) AND (spamfilter_wblist.active="y")
ORDER BY spamfilter_wblist.priority DESC') thr#559a5c331010
-> dbd_st_prepare MYSQL_VERSION_ID 100028, SQL statement: SELECT wb
FROM spamfilter_wblist WHERE (spamfilter_wblist.rid=?) AND
(spamfilter_wblist.email IN (?,?,?,?,?)) AND (spamfilter_wblist.active="y")
ORDER BY spamfilter_wblist.priority DESC
>- dbd_st_free_result_sets
<- dbd_st_free_result_sets RC -1
<- dbd_st_free_result_sets
>count_params statement SELECT wb FROM spamfilter_wblist WHERE
>(spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) AND
>(spamfilter_wblist.active="y") ORDER BY spamfilter_wblist.priority DESC
<- dbd_st_prepare
T <- prepare= ( DBI::st=HASH(0x559a620a3ef8) ) [1 items] at (eval 110) line
161
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010 1 '4') thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010 2 'sen...@domain.com' 12)
thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010 3 '@domain.com' 12)
thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010 4 '@.domain.com' 12)
thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010 5 '@.com' 12) thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> bind_param for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010 6 '@.' 12) thr#559a5c331010
Called: dbd_bind_ph
T <- bind_param= ( 1 ) [1 items] at (eval 110) line 168
-> execute for DBD::mysql::st (DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010)
thr#559a5c331010
-> dbd_st_execute for 559a6332c7e8
>- dbd_st_free_result_sets
<- dbd_st_free_result_sets RC -1
<- dbd_st_free_result_sets
mysql_st_internal_execute MYSQL_VERSION_ID 100028
>parse_params statement SELECT wb FROM spamfilter_wblist WHERE
>(spamfilter_wblist.rid=?) AND (spamfilter_wblist.email IN (?,?,?,?,?)) AND
>(spamfilter_wblist.active="y") ORDER BY spamfilter_wblist.priority DESC
Binding parameters: SELECT wb FROM spamfilter_wblist WHERE
(spamfilter_wblist.rid='4') AND (spamfilter_wblist.email IN
('sen...@domain.com','@domain.com','@.domain.com','@.com','@.')) AND
(spamfilter_wblist.active="y") ORDER BY spamfilter_wblist.priority DESC
<- dbd_st_execute returning imp_sth->row_num 0
T <- execute= ( '0E0' ) [1 items] at (eval 110) line 172
-> err in DBD::_::common for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010) thr#559a5c331010
T <- err= ( undef ) [1 items] at (eval 110) line 172
-> errstr in DBD::_::common for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010) thr#559a5c331010
T <- errstr= ( undef ) [1 items] at (eval 110) line 172
-> fetchrow_arrayref for DBD::mysql::st
(DBI::st=HASH(0x559a620a3ef8)~0x559a6209b010) thr#559a5c331010
-> dbd_st_fetch
dbd_st_fetch for 559a6332c7e8, chopblanks 0
dbd_st_fetch result set details
imp_sth->result=559a636e2908
mysql_num_fields=1
mysql_num_rows=0
mysql_affected_rows=0
dbd_st_fetch for 559a6332c7e8, currow= 1
dbd_st_fetch, no more rows to fetch
--> dbd_st_finish
>- dbd_st_free_result_sets
<- dbd_st_free_result_sets RC -1
<- dbd_st_free_result_sets
<-- dbd_st_finish
T <- fetchrow_arrayref= ( undef ) [1 items] at (eval 110) line 140
Feb 12 20:28:14.676 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql, "sen...@domain.com" no match
Feb 12 20:28:14.676 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(wb), "sen...@domain.com" no matching records
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup => undef, "sen...@domain.com" does not match
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) wbl: (SQL) recip <recei...@domain2.com>, rid=4, got: ""
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [blacklist_recip<recei...@domain2.com>] => undef,
"recei...@domain2.com" does not match
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [blacklist_sender<sen...@domain.com>,blacklist_sender] =>
undef, "sen...@domain.com" does not match
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [whitelist_recip<recei...@domain2.com>] => undef,
"recei...@domain2.com" does not match
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [whitelist_sender<sen...@domain.com>,whitelist_sender] =>
undef, "sen...@domain.com" does not match
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) query_keys: recei...@domain2.com, richard@, domain2.com,
.domain2.com, .com, .
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_hash(recei...@domain2.com) matches keys:
"."=>ARRAY(0x559a5d792138)
Feb 12 20:28:14.677 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [score_recip<recei...@domain2.com>,score_sender], 1 matches
for "recei...@domain2.com", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x559a5d779c38),{}]
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_re("sen...@domain.com"), no matches
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [score_sender<sen...@domain.com>] => undef,
"sen...@domain.com" does not match
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SpamControl: calling spam scanner SpamAssassin
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline spam_scan_sa_pre - deadline in 479.9 s, set to 476.000 s
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer spam_scan_sa_pre: timer 476, was 288, deadline in
479.9 s
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(sa_userconf) rec=0, "recei...@domain2.com" result:
undef
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field, no such fields: sa_userconf
Feb 12 20:28:14.678 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [sa_userconf] => undef, "recei...@domain2.com" does not match
Feb 12 20:28:14.679 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(sa_username) rec=0, "recei...@domain2.com" result:
undef
Feb 12 20:28:14.679 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field, no such fields: sa_username
Feb 12 20:28:14.679 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [sa_username] => undef, "recei...@domain2.com" does not match
Feb 12 20:28:14.679 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SA user config: "", username: "amavis", 0, (0)recei...@domain2.com
Feb 12 20:28:14.679 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) calling SA parse (0), SA vers 3.4.1, 3.004001, data as STRING_REF,
recips_ind [0], user: "amavis"
Feb 12 20:28:14.679 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline SA check - deadline in 479.9 s, set to 475.000 s
Feb 12 20:28:14.681 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) CALLING SA check (0)
Feb 12 20:28:19.061 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) DONE SA check (0)
Feb 12 20:28:19.063 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline spam_scan_sa - deadline in 475.5 s, set to 286.000 s
Feb 12 20:28:19.063 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer spam_scan_sa: timer 286, was 472, deadline in 475.5 s
Feb 12 20:28:19.063 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) spam_scan: score=-2.01 autolearn=ham autolearn_force=no
tests=[BAYES_00=-1.9,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,HTML_MESSAGE=0.001,SPF_PASS=-0.001,T_RP_MATCHES_RCVD=-0.01]
recips=0
Feb 12 20:28:19.064 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline spam_scan - deadline in 475.5 s, set to 286.000 s
Feb 12 20:28:19.064 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer spam_scan: timer 286, was 286, deadline in 475.5 s
Feb 12 20:28:19.064 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup => undef, "@domain.com", no lookup tables
Feb 12 20:28:19.064 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(spam_tag_level) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:19.064 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [spam_tag_level] => false, "recei...@domain2.com" matches,
result="0", matching_key="/cached/"
Feb 12 20:28:19.064 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(spam_tag2_level) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [spam_tag2_level] => false, "recei...@domain2.com" matches,
result="0", matching_key="/cached/"
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(spam_tag3_level) rec=0, "recei...@domain2.com"
result: undef
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field, no such fields: spam_tag3_level
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [spam_tag3_level] => undef, "recei...@domain2.com" does not
match
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(spam_kill_level) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [spam_kill_level] => false, "recei...@domain2.com" matches,
result="0", matching_key="/cached/"
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(message_size_limit) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [message_size_limit] => false, "recei...@domain2.com"
matches, result="0", matching_key="/cached/"
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) final_destiny (ccat=0) is PASS, recip recei...@domain2.com
Feb 12 20:28:19.065 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) final_destiny PASS, recip recei...@domain2.com
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll)
ccat_block=(), qar_mth=
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) do_notify_and_quarantine: not quarantining, q_method off
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) skip admin notification, no administrators
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) do_notify_and_quarantine - done
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(forward_method) rec=0, "recei...@domain2.com"
result: undef
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field, no such fields: forward_method
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup: (opaque) matches, result="smtp:127.0.0.1:*"
Feb 12 20:28:19.066 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [forward_method] => true, "recei...@domain2.com" matches,
result="smtp:127.0.0.1:*", matching_key="(opaque:smtp:127.0.0.1:*)"
Feb 12 20:28:19.067 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) delivery method is 1, recips: recei...@domain2.com
Feb 12 20:28:19.067 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(spam_tag_level) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:19.067 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [spam_tag_level] => false, "recei...@domain2.com" matches,
result="0", matching_key="/cached/"
Feb 12 20:28:19.067 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup_sql_field(spam_tag2_level) rec=0, "recei...@domain2.com"
result: "0"
Feb 12 20:28:19.067 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [spam_tag2_level] => false, "recei...@domain2.com" matches,
result="0", matching_key="/cached/"
Feb 12 20:28:19.067 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) headers CLUSTERING: NEW CLUSTER <recei...@domain2.com>: score=-2.01,
tag=0, tag2=0, local=1, bl=, s=, mangle=
Feb 12 20:28:19.068 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) header encoded (all-ASCII): X-Virus-Scanned: Debian amavisd-new at
mailserver.domain2.com
Feb 12 20:28:19.068 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) header: X-Virus-Scanned: Debian amavisd-new at
mailserver.domain2.com\n
Feb 12 20:28:19.068 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) fwd: scanner provided a header field X-Spam-Checker-Version,
inhibited by %allowed_added_header_fields
Feb 12 20:28:19.068 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) fwd: scanner provided a header field X-Spam-Level, but we preferred
our own
Feb 12 20:28:19.068 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) fwd: scanner provided a header field X-Spam-Status, but we preferred
our own
Feb 12 20:28:19.068 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) header encoded (all-ASCII): Authentication-Results:
mailserver.domain2.com (amavisd-new);\n dkim=pass (1024-bit key)\n
header.d=domain.com
Feb 12 20:28:19.068 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) header: Authentication-Results: mailserver.domain2.com
(amavisd-new); dkim=pass (1024-bit key)\n\theader.d=domain.com\n
Feb 12 20:28:19.069 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) header encoded (all-ASCII): Received: from mailserver.domain2.com
([127.0.0.1])\n by localhost (mailserver.domain2.com [127.0.0.1]) (amavisd-new,
port 10024)\n with ESMTP\n id IMQpZ1XJLZ-N\n for <recei...@domain2.com>;\n Sun,
12 Feb 2017 20:28:14 +0100 (CET)
Feb 12 20:28:19.069 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) header: Received: from mailserver.domain2.com ([127.0.0.1])\n\tby
localhost (mailserver.domain2.com [127.0.0.1]) (amavisd-new, port
10024)\n\twith ESMTP id IMQpZ1XJLZ-N for <recei...@domain2.com>;\n\tSun, 12 Feb
2017 20:28:14 +0100 (CET)\n
Feb 12 20:28:19.069 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) headers CLUSTERING: done all 1 recips in one go
Feb 12 20:28:19.069 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) dkim: not signing mail which is not originating from our site
Feb 12 20:28:19.069 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) about to connect to smtp:127.0.0.1:*, IMQpZ1XJLZ-N FWD from
<sen...@domain.com> -> <recei...@domain2.com>
Feb 12 20:28:19.070 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline fwd_init - deadline in 475.5 s, set to 476.000 s
Feb 12 20:28:19.070 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp session: setting up a new session
Feb 12 20:28:19.070 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) establish_or_refresh, state: down
Feb 12 20:28:19.070 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Feb 12 20:28:19.071 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) connected to [127.0.0.1]:10025 successfully
Feb 12 20:28:19.071 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=1, flush=0, wr=0, timeout=35
Feb 12 20:28:19.081 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: receiving
Feb 12 20:28:19.081 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop read 46 chars< 220 mailserver.domain2.com ESMTP Postfix
(Debian/GNU)\r\n
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp greeting: 220 mailserver.domain2.com ESMTP Postfix
(Debian/GNU), dt: 11.5 ms
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp cmd> EHLO localhost
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=0, flush=1, wr=1, timeout=300
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: sending 16 chars
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop sent 16> EHLO localhost\r\n
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: receiving
Feb 12 20:28:19.082 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop read 171 chars<
250-mailserver.domain2.com\r\n250-PIPELINING\r\n250-SIZE\r\n250-VRFY\r\n250-ETRN\r\n250-STARTTLS\r\n250-AUTH
PLAIN LOGIN\r\n250-AUTH=PLAIN
LOGIN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp resp to EHLO: 250
mailserver.domain2.com\nPIPELINING\nSIZE\nVRFY\nETRN\nSTARTTLS\nAUTH PLAIN
LOGIN\nAUTH=PLAIN LOGIN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) tls active=0, capable=1, sec_level=0
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Remote host presents itself as: mailserver.domain2.com, handles DSN,
PIPELINING, 8BITMIME
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) AUTH not needed, user='', MTA offers 'PLAIN LOGIN'
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp cmd> MAIL FROM:<sen...@domain.com> BODY=7BIT
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) orcpt_encode rfc822, recei...@domain2.com, encode_for_smtp
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp cmd> RCPT TO:<recei...@domain2.com>
ORCPT=rfc822;recei...@domain2.com
Feb 12 20:28:19.083 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp cmd> DATA
Feb 12 20:28:19.084 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=0, flush=1, wr=1, timeout=120
Feb 12 20:28:19.084 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: sending 106 chars
Feb 12 20:28:19.084 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop sent 106> MAIL FROM:<sen...@domain.com> BODY=7BIT\r\nRCPT
TO:<recei...@domain2.com> ORCPT=rfc822;recei...@domain2.com\r\nDATA\r\n
Feb 12 20:28:19.084 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=1, flush=0, wr=0, timeout=300
Feb 12 20:28:19.088 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: receiving
Feb 12 20:28:19.088 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data
with <CR><LF>.<CR><LF>\r\n
Feb 12 20:28:19.089 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp resp to MAIL (pip): 250 2.1.0 Ok
Feb 12 20:28:19.089 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp resp to RCPT (pip) (<recei...@domain2.com>): 250 2.1.5 Ok
Feb 12 20:28:19.090 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
Feb 12 20:28:19.090 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x559a6375b308)
Feb 12 20:28:19.091 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=1, flush=0, wr=1, timeout=475.979
Feb 12 20:28:19.091 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: sending 2647 chars
Feb 12 20:28:19.091 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop sent 2647> X-Virus-Scanned: Debian amavisd-new at
mailserver.domain2.com\r\nAuthentication-Results: mailserver.domain2.com
(amavisd-new); dkim=pass (1024-bit key)\r\n\theader.d=domain.com\r\nReceived:
from mailserver.domain2.com ([127.0.0.1])\r\n\tby l [...]
Feb 12 20:28:19.091 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: needline=1, flush=0, wr=0, timeout=475.979
Feb 12 20:28:19.094 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop: receiving
Feb 12 20:28:19.094 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rw_loop read 37 chars< 250 2.0.0 Ok: queued as 1562312063B\r\n
Feb 12 20:28:19.094 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) smtp resp to data-dot (<recei...@domain2.com>): 250 2.0.0 Ok: queued
as 1562312063B, dt: 2.5 ms
Feb 12 20:28:19.095 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Amavis::Out::SMTP::Session close, keeping connection
Feb 12 20:28:19.095 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline fwd-end-chkpnt - deadline in 475.5 s, set to 286.000 s
Feb 12 20:28:19.095 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer fwd-end-chkpnt: timer 286, was 0, deadline in 475.5 s
Feb 12 20:28:19.095 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) IMQpZ1XJLZ-N FWD from <sen...@domain.com> -> <recei...@domain2.com>,
BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as
1562312063B
Feb 12 20:28:19.095 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline forwarding - deadline in 475.5 s, set to 286.000 s
Feb 12 20:28:19.096 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer forwarding: timer 286, was 286, deadline in 475.5 s
Feb 12 20:28:19.096 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) DSN: sender is credible (dkim), SA: -2.010, <sen...@domain.com>
Feb 12 20:28:19.096 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef,
"sen...@domain.com" does not match
Feb 12 20:28:19.096 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) dsn: from MTA 250 NonBlocking:Clean <sen...@domain.com> ->
<recei...@domain2.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=,
DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1562312063B"
Feb 12 20:28:19.096 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested:
<sen...@domain.com> -> <recei...@domain2.com>
Feb 12 20:28:19.096 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) delivery_status_notification: notif 0 bytes, suppressed: no
Feb 12 20:28:19.096 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) one_response_for_all, per_recip_capable: N, suppressed: N
Feb 12 20:28:19.097 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) one_response_for_all <sen...@domain.com>: success, r=0,b=0,d=0,
ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued
as 1562312063B'
Feb 12 20:28:19.097 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1562312063B
Feb 12 20:28:19.097 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline delivery-notification - deadline in 475.5 s, set to
286.000 s
Feb 12 20:28:19.097 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer delivery-notification: timer 286, was 286, deadline in
475.5 s
Feb 12 20:28:19.097 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) status counters:
InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound}
Feb 12 20:28:19.097 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline snmp-counters - deadline in 475.5 s, set to 286.000 s
Feb 12 20:28:19.097 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer snmp-counters: timer 286, was 286, deadline in 475.5 s
Feb 12 20:28:19.098 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) orcpt_encode rfc822, recei...@domain2.com, smtputf8
Feb 12 20:28:19.100 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) oldest_public_ip_addr_from_received: 46.135.5.19
Feb 12 20:28:19.102 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Passed CLEAN {RelayedInbound}, [86.49.134.180]:59182 [46.135.5.19]
<sen...@domain.com> -> <recei...@domain2.com>, Queue-ID: 81467120639,
Message-ID: <emfb17d6bd-7aeb-4b96-b9ac-40b9e7bf021b@matrix>, mail_id:
IMQpZ1XJLZ-N, Hits: -2.01, size: 2287, queued_as: 1562312063B,
dkim_sd=dkim:domain.com, 4567 ms
Feb 12 20:28:19.102 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline main_log_entry - deadline in 475.5 s, set to 286.000 s
Feb 12 20:28:19.102 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer main_log_entry: timer 286, was 286, deadline in 475.5 s
Feb 12 20:28:19.102 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) TIMING-SA total 4383 ms - parse: 1.22 (0.0%),
extract_message_metadata: 7 (0.2%), get_uri_detail_list: 0.15 (0.0%),
tests_pri_-1000: 2.1 (0.0%), tests_pri_-950: 0.71 (0.0%), tests_pri_-900: 0.68
(0.0%), tests_pri_-400: 9 (0.2%), check_bayes: 8 (0.2%), b_tokenize: 3.0
(0.1%), b_tok_get_all: 1.39 (0.0%), b_comp_prob: 1.46 (0.0%), b_tok_touch_all:
0.12 (0.0%), b_finish: 0.47 (0.0%), tests_pri_0: 276 (6.3%), check_spf: 248
(5.7%), poll_dns_idle: 4238 (96.7%), check_pyzor: 0.12 (0.0%), tests_pri_500:
4011 (91.5%), learn: 62 (1.4%), b_learn: 60 (1.4%), b_count_change: 3.8 (0.1%),
get_report: 0.29 (0.0%)
Feb 12 20:28:19.102 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) updating snmp variables in BDB
Feb 12 20:28:19.103 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline check done - deadline in 475.5 s, set to 286.000 s
Feb 12 20:28:19.103 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer check done: timer 286, was 286, deadline in 475.5 s
Feb 12 20:28:19.103 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025):
250 2.0.0 Ok: queued as 1562312063B"
Feb 12 20:28:19.103 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok:
queued as 1562312063B
Feb 12 20:28:19.109 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:19.109 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) TempDir::strip:
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH
Feb 12 20:28:19.109 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rmdir_recursively:
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts, excl=1
Feb 12 20:28:19.110 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) size: 2287, TIMING [total 4575 ms] - sql-prepare: 3.6 (0%)0, SMTP
greeting: 1.7 (0%)0, SMTP EHLO: 2.2 (0%)0, SMTP pre-MAIL: 1.5 (0%)0, mkdir
tempdir: 0.8 (0%)0, create email.txt: 0.3 (0%)0, sql-connect: 7 (0%)0,
lookup_sql: 2.7 (0%)0, SMTP pre-DATA-flush: 1.3 (0%)0, SMTP DATA: 26 (1%)1,
check_init: 0.7 (0%)1, digest_hdr: 3.8 (0%)1, digest_body_dkim: 56 (1%)2,
collect_info: 4.1 (0%)2, mkdir parts: 1.8 (0%)2, mime_decode: 6 (0%)3,
get-file-type2: 12 (0%)3, parts_decode: 0.2 (0%)3, check_header: 0.7 (0%)3,
AV-scan-1: 6 (0%)3, lookup_sql: 2.5 (0%)3, spam-wb-list: 1.3 (0%)3, SA msg
read: 0.5 (0%)3, SA parse: 2.5 (0%)3, SA check: 4380 (96%)99,
decide_mail_destiny: 4.4 (0%)99, notif-quar: 0.4 (0%)99, fwd-connect: 17
(0%)99, fwd-mail-pip: 6 (0%)100, fwd-rcpt-pip: 0.8 (0%)100, fwd-data-chkpnt:
0.1 (0%)100, write-header: 0.7 (0%)100, fwd-data-contents: 0.7 (0%)100,
fwd-end-chkpnt: 4.2 (0%)100, prepare-dsn: 1.6 (0%)100, report: 2.1 (0%)100,
main_log_entry: 3.2 (0%)100, update_snmp: 0.9 (0%)100, SMTP pre-response: 0.3
(0%)100, SMTP response: 6 (0%)100, unlink-2-files: 0.4 (0%)100, rundown: 0.8
(0%)100
Feb 12 20:28:19.111 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 6: was busy, 4555.6 ms, total idle 0.001 s, busy 4.575 s
Feb 12 20:28:19.111 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, 5: was idle, 0.2 ms, total idle 0.001 s, busy 4.575 s
Feb 12 20:28:19.111 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP< QUIT\r\n
Feb 12 20:28:19.111 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s,
set to 288.000 s
Feb 12 20:28:19.111 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480,
deadline in 480.0 s
Feb 12 20:28:19.111 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Feb 12 20:28:19.112 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) switch_to_client_time 480 s, smtp response sent
Feb 12 20:28:19.112 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SMTP session over, timer stopped
Feb 12 20:28:19.113 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) exiting process_request
Feb 12 20:28:19.113 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) idle_proc, bye: was busy, 2.7 ms, total idle 0.001 s, busy 4.578 s
Feb 12 20:28:19.114 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) load: 100 %, total idle 0.001 s, busy 4.578 s
^CFeb 12 20:28:19.771 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
child_goes_idle (child finishing)
Feb 12 20:28:19.771 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) child_goes_idle (child finishing)
Feb 12 20:28:19.771 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) disconnecting from SQL
Feb 12 20:28:19.771 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
child_goes_idle: disconnected none (child finishing)
Feb 12 20:28:19.771 mailserver.domain2.com /usr/sbin/amavisd-new[6694]: SA
rundown_child (0)
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) child_goes_idle: disconnected SQL-lookup (child finishing)
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
SpamControl: rundown_child on SpamAssassin done
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
child_finish_hook: invoking DESTROY methods
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SA rundown_child (0)
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
Amavis::Lookup::SQL DESTROY called
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
Amavis::Lookup::SQL DESTROY called
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
Amavis::Out::SQL::Connection DESTROY called
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SpamControl: rundown_child on SpamAssassin done
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) child_finish_hook: invoking DESTROY methods
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) TempDir::DESTROY called
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
Amavis::DB::SNMP DESTROY called
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) TempDir removal: empty tempdir is being removed:
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rmdir_recursively:
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH, excl=
Feb 12 20:28:19.772 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) rmdir_recursively:
/var/lib/amavis/tmp/amavis-20170212T202814-06693-fE9YrXCH/parts, excl=
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6678]:
Net::Server: 2017/02/12-20:28:19 Server closing!
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6678]:
Net::Server: Kill TERM pid 6694
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Amavis::Lookup::SQL DESTROY called
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6678]:
Net::Server: Kill TERM pid 6693
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) child_goes_idle (child finishing)
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) child_goes_idle: disconnected none (child finishing)
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SA rundown_child (0)
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) SpamControl: rundown_child on SpamAssassin done
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) child_finish_hook: invoking DESTROY methods
Feb 12 20:28:19.773 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Amavis::DB::SNMP DESTROY called
Feb 12 20:28:19.777 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
child_goes_idle (child finishing)
Feb 12 20:28:19.777 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
child_goes_idle: disconnected none (child finishing)
Feb 12 20:28:19.777 mailserver.domain2.com /usr/sbin/amavisd-new[6694]: SA
rundown_child (0)
Feb 12 20:28:19.777 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
SpamControl: rundown_child on SpamAssassin done
Feb 12 20:28:19.777 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
child_finish_hook: invoking DESTROY methods
Feb 12 20:28:19.778 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Amavis::Out::SQL::Connection DESTROY called
Feb 12 20:28:19.778 mailserver.domain2.com /usr/sbin/amavisd-new[6694]:
Amavis::DB::SNMP DESTROY called
Feb 12 20:28:19.779 mailserver.domain2.com /usr/sbin/amavisd-new[6693]:
(06693-01) Amavis::Lookup::SQL DESTROY called
