submission, not originating ... for roaming, authenticated users?
Django [BOfH]
django at nausch.org
Sun Nov 19 22:39:28 CET 2017
HI,
pardon for my little stupid question. But I'm on a point and have
absolutly no idea, why my new installed amavisd-new installation won't
accept my roaming-usermails.
O.K. in my master.cf of postfix I have:
submission inet n - n - - smtpd
-o syslog_name=postfix/submission
-o smtpd_tls_security_level=encrypt
-o smtpd_sasl_auth_enable=yes
-o smtpd_tls_ask_ccert=no
-o smtpd_reject_unlisted_recipient=no
-o smtpd_etrn_restrictions=reject
-o smtpd_recipient_restrictions=
-o smtpd_relay_restrictions=permit_sasl_authenticated,reject
-o milter_macro_daemon_name=ORIGINATING
-o content_filter=smtp:[127.0.0.1]:10024
-o disable_dns_lookups=yes
-o smtp_send_xforward_command=yes
-o mynetworks=127.0.0.0/8
-o smtp_data_done_timeout=1200
My amavisd.conf has the follwing definitions:
@listen_sockets = (
'127.0.0.1:10024',
'127.0.0.1:9998',
"$MYHOME/amavisd.sock"
);
$interface_policy{'10024'} = 'ORIGINATING';
@mynetworks = qw(
127.0.0.0/8
[::ffff:127.0.0.0]/104
[::1]/128
);
@local_domains_maps = (
[".$mydomain"],
read_hash("/etc/postfix/all_local_domains_map"),
);
$policy_bank{'ORIGINATING'} = {
inet_acl => [qw( 127.0.0.1 )],
originating => 1,
allow_disclaimers => 1,
virus_admin_maps => ["virusalert\@$mydomain"],
spam_admin_maps => ["virusalert\@$mydomain"],
warnbadhsender => 1,
smtpd_discard_ehlo_keywords => ['8BITMIME'],
bypass_spam_checks_maps => [0],
bypass_banned_checks_maps => [0],
bypass_virus_checks_maps => [0],
terminate_dsn_on_notify_success => 0,
notify_method => 'smtp:[127.0.0.1]:10025',
forward_method => 'smtp:[127.0.0.1]:10025',
final_virus_destiny => 'D_BOUNCE',
};
So far so good. No voodoo or similar else - a standard config like all
others, I made the last years.
If I send an testmail with swaks through Port 587 as an authenticated
roaming user, the message is accepted and sen to the final recipient.
BUT:
The mail isn't DKIM signed, so I tried to understand why. AMaViS thought
the mail was not from local:
Open relay? Nonlocal recips but not originating: django at nausch.org
The whole maillog is here:
Nov 19 21:33:08 mailslut postfix/submission/smtpd[26111]: connect from
mx1.nausch.org[217.92.13.131]
Nov 19 21:33:09 mailslut postfix/submission/smtpd[26111]: Anonymous TLS
connection established from mx1.nausch.org[217.92.13.131]: TLSv1.2 with
cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
Nov 19 21:33:09 mailslut postfix/submission/smtpd[26111]: 7D744600048:
client=mx1.nausch.org[217.92.13.131], sasl_method=LOGIN,
sasl_username=n3rd at omni128.de
Nov 19 21:33:09 mailslut postfix/cleanup[26120]: 7D744600048: message-id=<>
Nov 19 21:33:09 mailslut postfix/qmgr[26096]: 7D744600048:
from=<n3rd at omni128.de>, size=566, nrcpt=1 (queue active)
Nov 19 21:33:09 mailslut amavis[26104]: Net::Server: 2017/11/19-21:33:09
CONNECT TCP Peer: "[127.0.0.1]:48950" Local: "[127.0.0.1]:10024"
Nov 19 21:33:09 mailslut amavis[26104]: loaded base policy bank
Nov 19 21:33:09 mailslut amavis[26104]: loaded policy bank "ORIGINATING"
Nov 19 21:33:09 mailslut amavis[26104]: lookup_ip_acl (inet_acl)
arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
Nov 19 21:33:09 mailslut amavis[26104]: process_request: fileno sock=13,
STDIN=0, STDOUT=1
Nov 19 21:33:09 mailslut amavis[26104]: get_deadline
switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: prolong_timer
switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: process_request:
suggested_protocol="" on a TCP socket
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) SMTP> 220 [127.0.0.1]
ESMTP amavisd-new service ready
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, smtp response sent
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 4: was
busy, 3.6 ms, total idle 0.000 s, busy 0.004 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) smtp readline: read
34 bytes, new size: 34
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 5: was
idle, 0.2 ms, total idle 0.000 s, busy 0.004 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) SMTP< EHLO
mx.omni128.de\r\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
switch_to_my_time(rx SMTP EHLO): timer 288, was 480, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250-[127.0.0.1]
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250-VRFY
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250-PIPELINING
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250-SIZE
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP>
250-ENHANCEDSTATUSCODES
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250-DSN
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250 XFORWARD
NAME ADDR PORT PROTO HELO IDENT SOURCE
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, smtp response sent
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 6: was
busy, 0.5 ms, total idle 0.000 s, busy 0.004 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) smtp readline: read
110 bytes, new size: 110
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 5: was
idle, 0.1 ms, total idle 0.000 s, busy 0.004 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP< MAIL
FROM:<n3rd at omni128.de>\r\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
switch_to_my_time(rx SMTP MAIL): timer 288, was 480, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
check_mail_begin_task: task_count=1
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) TempDir::prepare_dir:
created directory
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
TempDir::prepare_file: creating file
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/email.txt
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
TempDir::prepare_file: layers: unix,perlio
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_ip_acl
(client_ipaddr_policy) arr.obj: key="0.0.0.0" matches "0.0.0.0/8", result=1
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) policy bank
"LOCALHOST" does not exist, ignored
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [debug_sender]
=> undef, "n3rd at omni128.de" does not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250 2.1.0
Sender <n3rd at omni128.de> OK
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, smtp response sent
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 6: was
busy, 2.0 ms, total idle 0.000 s, busy 0.006 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 5: was
idle, 0.0 ms, total idle 0.000 s, busy 0.006 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP< RCPT
TO:<django at nausch.org> ORCPT=rfc822;django at nausch.org\r\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
switch_to_my_time(rx SMTP RCPT): timer 288, was 480, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup => undef,
"django at nausch.org", no lookup tables
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250 2.1.5
Recipient <django at nausch.org> OK
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, smtp response sent
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 6: was
busy, 0.5 ms, total idle 0.000 s, busy 0.006 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) idle_proc, 5: was
idle, 0.0 ms, total idle 0.000 s, busy 0.006 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP< DATA\r\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
switch_to_my_time(rx SMTP DATA): timer 288, was 480, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP
[127.0.0.1]:10024
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86:
<n3rd at omni128.de> -> <django at nausch.org> Received: from mx.omni128.de
([127.0.0.1]) by asav.omni128.de (asav.omni128.de [127.0.0.1])
(amavisd-new, port 10024) with ESMTP for <django at nausch.org>; Sun, 19
Nov 2017 21:33:09 +0100 (CET)
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 354 End data
with <CR><LF>.<CR><LF>
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, smtp response sent
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, receiving data
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) smtp copy: read 575
bytes into buffer, new size: 575
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) smtp copy: 6 bytes
still buffered at end
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
switch_to_my_time(rx data-end): timer 288, was 480, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP< .<CR><LF>
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) message size set to 566
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
get_body_digest - deadline in 480.0 s, set to 30.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
digest_pre - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
digest_pre: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_body_digest:
reading header section from memory
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
digest_hdr - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
digest_hdr: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_body_digest:
reading mail body from memory, 0 DKIM signatures
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
digest_body - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
digest_body: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_body_digest:
message size 566, header+sep 540, body 26
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) body type
(8bit-MIMEtransport): unlabeled, good (h=0, b=0)
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) body hash:
5e4a6c05336dff65870f1c8870955b2a
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ip_from_received:
217.92.13.131
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_ip_acl
(public_nets) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_ip_acl
(public_nets) arr.obj: key="217.92.13.131" matches "::ffff:0:0/96", result=1
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) trace:
ESMTP://[127.0.0.1]:48950 < ESMTPSA://217.92.13.131
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) client IP address
unknown, fetched from Received: 127.0.0.1
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Original mail size:
566; quota set to: 283000 bytes (fmin=5, fmax=500, qmin=102400,
qmax=524288000)
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Checking:
1UkmOMluhonk ORIGINATING [127.0.0.1] <n3rd at omni128.de> ->
<django at nausch.org>
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) 2822.From:
<n3rd at omni128.de>
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
lookup_acl(django at nausch.org), no match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) query_keys:
django at nausch.org, django@, nausch.org, .nausch.org, .org, .
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
lookup_hash(django at nausch.org), no matches
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[local_domains] => undef, "django at nausch.org" does not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="0"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup => false,
"django at nausch.org" matches, result="0", matching_key="(constant:0)"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="0"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup => false,
"django at nausch.org" matches, result="0", matching_key="(constant:0)"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="0"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup => false,
"django at nausch.org" matches, result="0", matching_key="(constant:0)"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Open relay? Nonlocal
recips but not originating: django at nausch.org
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Extracting mime
components from a string
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Issued a new file
name: p001
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Charging 24 bytes to
remaining quota 283000 (out of 283000, (0%)) - by mime_decode
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) p001 1 Content-Type:
text/plain, 7bit, size: 24, SHA1 digest:
955a2b605a8ace72f2e722802fc64d14987379b7
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
mime_decode - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
mime_decode: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
mime_decode-1 - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
mime_decode-1: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) inspect_dsn: parts:
text/plain
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) inspect_dsn: not a bounce
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
dsn_parse - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
dsn_parse: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) decode_parts:
level=1, #parts=1 : p001
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) running file(1) on 1
files, arglist size 18
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) run_command: [26124]
/usr/bin/file p001 </dev/null 2>&1
Nov 19 21:33:09 mailslut amavis[26124]: (26104-01) open_on_specific_fd:
target fd0 closing, to become < /dev/null
Nov 19 21:33:09 mailslut amavis[26124]: (26104-01) open_on_specific_fd:
target fd1 closing, to become (65) &=16
Nov 19 21:33:09 mailslut amavis[26124]: (26104-01) open_on_specific_fd:
target fd1 dup2 from fd16 (65) &=16
Nov 19 21:33:09 mailslut amavis[26124]: (26104-01) open_on_specific_fd:
source fd16 closed
Nov 19 21:33:09 mailslut amavis[26124]: (26104-01) open_on_specific_fd:
target fd2 closing, to become (65) &1
Nov 19 21:33:09 mailslut amavis[26124]: (26104-01) open_on_specific_fd:
target fd2 dup2 from fd1 (65) &1
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) result line from
file(1): p001: ASCII text\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_re("ASCII
text") matches key "(?^i:^(ASCII|text)\\b)", result="asc"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[map_full_type_to_short_type] => true, "ASCII text" matches,
result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) File-type of p001:
ASCII text; (asc)
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) decompose_part: p001
- atomic
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
parts_decode - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
parts_decode: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[bypass_header_checks] => undef, "django at nausch.org" does not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) check_header: 0, OK
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[bypass_header_checks] => undef, "django at nausch.org" does not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Checking for banned
types and filenames
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="DEFAULT"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[banned_filename], 1 matches for "django at nausch.org", results:
"(constant:DEFAULT)"=>"DEFAULT"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) collect banned
table[0]: django at nausch.org, tables:
DEFAULT=>Amavis::Lookup::RE=ARRAY(0x2d75898)
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) starting banned
checks - traversing message structure tree
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) check_for_banned
(p001) text/plain,.asc
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) doing banned check
for django at nausch.org on text/plain,.asc
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
lookup_re(["text/plain",".asc"]), no matches
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[check_bann:django at nausch.org] => undef, ["text/plain",".asc"] does not
match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[banned_namepath_re] => undef, "P=p001\tL=1\tM=text/plain\tT=asc" does
not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) p.path
django at nausch.org: "P=p001,L=1,M=text/plain,T=asc"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) banned check: any=0,
all=N (1)
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_re("MAIL")
matches key "(?^:^MAIL$)", result="1"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[keep_decoded_original] => true, "MAIL" matches, result="1",
matching_key="(?^:^MAIL$)"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Issued a new file
name: p002
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) presenting full
original message to scanners as
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts/p002
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Calling virus
scanners, 2 files to scan in
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) invoking av-scanner
ClamAV-clamd
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ask_daemon:
proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamd.amavisd/clamd.sock
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) run_av
(ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
run_av_pre - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
run_av_pre: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
run_av_scan - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
run_av_scan: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) run_av Using
(ClamAV-clamd): (code) CONTSCAN
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
ask_daemon_internal_connect_pre - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
ask_daemon_internal_connect - deadline in 480.0 s, set to 10.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
ask_daemon_internal_connect: timer 10, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ClamAV-clamd:
Connecting to socket /var/run/clamd.amavisd/clamd.sock
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) new socket by
IO::Socket::UNIX to /var/run/clamd.amavisd/clamd.sock, timeout set to 10
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) connected to
/var/run/clamd.amavisd/clamd.sock successfully
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ClamAV-clamd: Sending
CONTSCAN
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts\n to
socket /var/run/clamd.amavisd/clamd.sock
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop: needline=0,
flush=1, wr=1, timeout=10
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop: sending 76 chars
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop sent 76>
CONTSCAN
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
ask_daemon_internal_scan - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
ask_daemon_internal_scan: timer 288, was 10, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop: needline=0,
flush=0, wr=0, timeout=287.999
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop: receiving
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop read 71
chars<
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts: OK\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop: needline=0,
flush=0, wr=0, timeout=287.999
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop: receiving
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) rw_loop read: got eof
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
ask_daemon_internal - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
ask_daemon_internal: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline run_av_3
- deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
run_av_3: timer 288, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) run_av (ClamAV-clamd)
result:
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts: OK\n
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) run_av
(ClamAV-clamd): CLEAN
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) run_av (ClamAV-clamd)
result: clean
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) wbl: checking sender
<n3rd at omni128.de>
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[blacklist_recip<django at nausch.org>] => undef, "django at nausch.org" does
not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[blacklist_sender<n3rd at omni128.de>,blacklist_sender] => undef,
"n3rd at omni128.de" does not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[whitelist_recip<django at nausch.org>] => undef, "django at nausch.org" does
not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[whitelist_sender<n3rd at omni128.de>,whitelist_sender] => undef,
"n3rd at omni128.de" does not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) query_keys: cached
django at nausch.org
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
lookup_hash(django at nausch.org) matches keys: "."=>ARRAY(0x39852e8)
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[score_recip<django at nausch.org>,score_sender], 1 matches for
"django at nausch.org", results:
"."=>[Amavis::Lookup::RE=ARRAY(0x3984ec8),{amavis-user-admin at lists.sourceforge.net=>"-3",owner-postfix-announce at postfix.org=>"-3",ntbugtraq at listserv.ntbugtraq.com=>"-3",donotreply at sendmail.org=>"-3",slashdot at slashdot.org=>"-3",clp-request at comp.nus.edu.sg=>"-3",nobody at cert.org=>"-3",security-alerts at linuxsecurity.com=>"-3",cvs-commits-list-admin at gnome.org=>"-3",amavis-user-bounces at lists.sourceforge.net=>"-3",notification-return at lists.sophos.com=>"-3",mailman-announce-admin at python.org=>"-3",emailnews at genomeweb.com=>"-5",owner-textbreakingnews at cnnimail12.cnn.com=>"-5",ca+envelope at sendmail.org=>"-3",cert-advisory at us-cert.gov=>"-3",returns.groups.yahoo.com=>"-3",owner-postfix-users at postfix.org=>"-3",.example.net=>"1",securityfocus.com=>"-3",yahoo-dev-null at yahoo-inc.com=>"-3",owner-alert at iss.net=>"-3",sendmail-announce-request at lists.sendmail.org=>"-3",surveys-err...
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
...ors at lists.nua.ie=>"-3",spamassassin.apache.org=>"-3",lvs-users-admin at linuxvirtualserver.org=>"-3",sender at example.net=>"3",owner-sendmail-announce at lists.sendmail.org=>"-3",noreply at freshmeat.net=>"-3",ietf-123-owner at loki.ietf.org=>"-3",clusternews at linuxnetworx.com=>"-3",owner-technews at postel.acm.org=>"-3",rt-users-admin at lists.fsck.com=>"-3"}]
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
lookup_re("n3rd at omni128.de"), no matches
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) query_keys:
n3rd at omni128.de, django@, omni128.de, .omni128.de, .de, .
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01)
lookup_hash(n3rd at omni128.de), no matches
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup
[score_sender<n3rd at omni128.de>] => undef, "n3rd at omni128.de" does not match
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) SpamControl: calling
spam scanner SpamAssassin
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline
spam_scan_sa_pre - deadline in 480.0 s, set to 476.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) prolong_timer
spam_scan_sa_pre: timer 476, was 288, deadline in 480.0 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) SA user config: "",
username: "amavis", 0, (0)django at nausch.org
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) calling SA parse (0),
SA vers 3.4.0, 3.004000, data as STRING_REF, recips_ind [0], user: "amavis"
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) get_deadline SA check
- deadline in 480.0 s, set to 475.000 s
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) mimepart digest:
955a2b605a8ace72f2e722802fc64d14987379b7:text/plain
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) CALLING SA check (0)
Nov 19 21:33:09 mailslut postfix/submission/smtpd[26111]: disconnect
from mx1.nausch.org[217.92.13.131]
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) DONE SA check (0)
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
spam_scan_sa - deadline in 479.7 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
spam_scan_sa: timer 288, was 476, deadline in 479.7 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) spam_scan:
score=-0.86 autolearn=no autolearn_force=no
tests=[ALL_TRUSTED=-1,MISSING_MID=0.14] recips=0
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
spam_scan - deadline in 479.7 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
spam_scan: timer 288, was 288, deadline in 479.7 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="-1000"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[spam_tag_level] => true, "django at nausch.org" matches, result="-1000",
matching_key="(constant:-1000)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="6.31"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[spam_tag2_level] => true, "django at nausch.org" matches, result="6.31",
matching_key="(constant:6.31)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[spam_tag3_level] => undef, "django at nausch.org" does not match
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="6.31"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[spam_kill_level] => true, "django at nausch.org" matches, result="6.31",
matching_key="(constant:6.31)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) final_destiny
(ccat=0) is PASS, recip django at nausch.org
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="disclaimer"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup [Mangling1] =>
true, "django at nausch.org" matches, result="disclaimer",
matching_key="(constant:disclaimer)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01)
lookup_acl(n3rd at omni128.de) matches key ".omni128.de", result=1
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[local_domains] => true, "n3rd at omni128.de" matches, result="1",
matching_key=".omni128.de"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) mangling YES:
disclaimer (was: disclaimer), discl_allowed=1, <n3rd at omni128.de> ->
<django at nausch.org>
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) final_destiny PASS,
recip django at nausch.org
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) do_notify_and_quar:
ccat=CleanTag (1,1) ("1,1":CleanTag, "1":Clean, "0":CatchAll)
ccat_block=(), qar_mth=
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01)
do_notify_and_quarantine: not quarantining, q_method off
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) skip admin
notification, no administrators
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01)
do_notify_and_quarantine - done
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (opaque)
matches, result="smtp:[127.0.0.1]:10025"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[forward_method] => true, "django at nausch.org" matches,
result="smtp:[127.0.0.1]:10025",
matching_key="(opaque:smtp:[127.0.0.1]:10025)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) delivery method is 1,
recips: django at nausch.org
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="-1000"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[spam_tag_level] => true, "django at nausch.org" matches, result="-1000",
matching_key="(constant:-1000)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="6.31"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[spam_tag2_level] => true, "django at nausch.org" matches, result="6.31",
matching_key="(constant:6.31)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) headers CLUSTERING:
NEW CLUSTER <django at nausch.org>: score=-0.86, tag=1, tag2=0, local=0,
bl=, s=, mangle=disclaimer
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) header encoded
(all-ASCII): X-Amavis-Modified: Mail body modified (using disclaimer) -
asav.omni128.de
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) header:
X-Amavis-Modified: Mail body modified (using disclaimer)
-\n\tasav.omni128.de\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) header encoded
(all-ASCII): X-Virus-Scanned: amavisd-new at omni128.de
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) header:
X-Virus-Scanned: amavisd-new at omni128.de\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) header encoded
(all-ASCII): Received: from mx.omni128.de ([127.0.0.1])\n by
asav.omni128.de (asav.omni128.de [127.0.0.1]) (amavisd-new, port
10024)\n with ESMTP\n id 1UkmOMluhonk\n for <django at nausch.org>;\n Sun,
19 Nov 2017 21:33:09 +0100 (CET)
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) header: Received:
from mx.omni128.de ([127.0.0.1])\n\tby asav.omni128.de (asav.omni128.de
[127.0.0.1]) (amavisd-new, port 10024)\n\twith ESMTP id 1UkmOMluhonk for
<django at nausch.org>;\n\tSun, 19 Nov 2017 21:33:09 +0100 (CET)\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) headers CLUSTERING:
done all 1 recips in one go
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) mangling by:
disclaimer, <django at nausch.org>
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) run_command: [26126]
/usr/bin/altermime
--input=/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/email-repl.txt
--verbose --disclaimer=/etc/mail/disclaimer.txt
--disclaimer-html=/etc/mail/altermime/disclaimer.html </dev/null 2>&1
Nov 19 21:33:10 mailslut amavis[26126]: (26104-01) open_on_specific_fd:
target fd0 closing, to become < /dev/null
Nov 19 21:33:10 mailslut amavis[26126]: (26104-01) open_on_specific_fd:
target fd1 closing, to become (65) &=16
Nov 19 21:33:10 mailslut amavis[26126]: (26104-01) open_on_specific_fd:
target fd1 dup2 from fd16 (65) &=16
Nov 19 21:33:10 mailslut amavis[26126]: (26104-01) open_on_specific_fd:
source fd16 closed
Nov 19 21:33:10 mailslut amavis[26126]: (26104-01) open_on_specific_fd:
target fd2 closing, to become (65) &1
Nov 19 21:33:10 mailslut amavis[26126]: (26104-01) open_on_specific_fd:
target fd2 dup2 from fd1 (65) &1
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) collect_results from
[26126] (/usr/bin/altermime), 272 bytes, (limit 16384)
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) (!!)collect_results
from [26126] (/usr/bin/altermime): DIED, signal 11 (000b)
mime_alter.c:1401:AM_disclaimer_load_text:ERROR: Cannot stat
'/etc/mail/disclaimer.txt' (No such file or
directory)\nmime_alter.c:1401:AM_disclaimer_load_text:ERROR: Cannot stat
'/etc/mail/altermime/disclaimer.html' (No such file or
directory)\nAttempting to add disclaimer\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) program
/usr/bin/altermime said:
mime_alter.c:1401:AM_disclaimer_load_text:ERROR: Cannot stat
'/etc/mail/disclaimer.txt' (No such file or
directory)\nmime_alter.c:1401:AM_disclaimer_load_text:ERROR: Cannot stat
'/etc/mail/altermime/disclaimer.html' (No such file or
directory)\nAttempting to add disclaimer\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) (!)mangling by
altermime failed: Program /usr/bin/altermime failed: 11,
mime_alter.c:1401:AM_disclaimer_load_text:ERROR: Cannot stat
'/etc/mail/disclaimer.txt' (No such file or
directory)\nmime_alter.c:1401:AM_disclaimer_load_text:ERROR: Cannot stat
'/etc/mail/altermime/disclaimer.html' (No such file or
directory)\nAttempting to add disclaimer, mail will pass unmodified
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) dkim: not signing
mail which is not originating from our site
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) about to connect to
smtp:[127.0.0.1]:10025, 1UkmOMluhonk FWD from <n3rd at omni128.de> ->
<django at nausch.org>
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline fwd_init
- deadline in 479.6 s, set to 480.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp session: setting
up a new session
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) establish_or_refresh,
state: down
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) new socket using
IO::Socket::IP to [127.0.0.1]:10025, timeout 35
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) connected to
[127.0.0.1]:10025 successfully
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=1,
flush=0, wr=0, timeout=35
Nov 19 21:33:10 mailslut postfix/smtpd[26127]: connect from
localhost[127.0.0.1]
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: receiving
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop read 47
chars< 220 mx.omni128.de ESMTP Postfix\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp greeting: 220
mx.omni128.de ESMTP Postfix, dt: 20.7 ms
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp cmd> EHLO
asav.omni128.de
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=0,
flush=1, wr=1, timeout=300
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: sending 36 chars
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop sent 36> EHLO
asav.omni128.de\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=1,
flush=0, wr=0, timeout=300
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: receiving
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop read 228
chars< 250-mx.omni128.de\r\n250-PIPELINING\r\n250-SIZE
52428800\r\n250-ETRN\r\n250-STARTTLS\r\n250-AUTH PLAIN
LOGIN\r\n250-AUTH=PLAIN LOGIN\r\n250-XFORWARD NAME ADDR PROTO HELO
SOURCE PORT IDENT\r\n250-ENHANCEDSTATUSCODES\r\n250 8BITMIME\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp resp to EHLO:
250 mx.omni128.de\nPIPELINING\nSIZE 52428800\nETRN\nSTARTTLS\nAUTH PLAIN
LOGIN\nAUTH=PLAIN LOGIN\nXFORWARD NAME ADDR PROTO HELO SOURCE PORT
IDENT\nENHANCEDSTATUSCODES\n8BITMIME
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) tls active=0,
capable=1, sec_level=0
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) Remote host presents
itself as: mx.omni128.de, handles PIPELINING, 8BITMIME
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp cmd> XFORWARD
ADDR=127.0.0.1
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=0,
flush=1, wr=1, timeout=300
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: sending 25 chars
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop sent 25>
XFORWARD ADDR=127.0.0.1\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=1,
flush=0, wr=0, timeout=300
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: receiving
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop read 14
chars< 250 2.0.0 Ok\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp resp to
XFORWARD: 250 2.0.0 Ok
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) AUTH not needed,
user='', MTA offers 'PLAIN LOGIN'
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp cmd> MAIL
FROM:<n3rd at omni128.de> BODY=7BIT
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp cmd> RCPT
TO:<django at nausch.org>
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp cmd> DATA
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=0,
flush=1, wr=1, timeout=120
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: sending 89 chars
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop sent 89> MAIL
FROM:<n3rd at omni128.de> BODY=7BIT\r\nRCPT TO:<django at nausch.org>\r\nDATA\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=1,
flush=0, wr=0, timeout=300
Nov 19 21:33:10 mailslut postfix/smtpd[26127]: 35A9D60004C:
client=localhost[127.0.0.1], orig_client=unknown[127.0.0.1]
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: receiving
Nov 19 21:33:10 mailslut amavis[26104]: (26104-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
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp resp to MAIL
(pip): 250 2.1.0 Ok
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp resp to RCPT
(pip) (<django at nausch.org>): 250 2.1.5 Ok
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp resp to DATA:
354 End data with <CR><LF>.<CR><LF>
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) write_header: 1,
Amavis::Out::SMTP::Protocol=HASH(0x5fd2b10)
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=1,
flush=0, wr=1, timeout=479.973
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: sending 975
chars
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop sent 975>
X-Amavis-Modified: Mail body modified (using disclaimer)
-\r\n\tasav.omni128\r\nX-Virus-Scanned: amavisd-new at
omni128.de\r\nReceived: from mx.omni128.de ([127.0. [...]
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: needline=1,
flush=0, wr=0, timeout=479.973
Nov 19 21:33:10 mailslut postfix/cleanup[26120]: 35A9D60004C:
message-id=<20171119203310.35A9D60004C at mx.omni128.de>
Nov 19 21:33:10 mailslut postfix/qmgr[26096]: 35A9D60004C:
from=<n3rd at omni128.de>, size=1246, nrcpt=1 (queue active)
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop: receiving
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rw_loop read 37
chars< 250 2.0.0 Ok: queued as 35A9D60004C\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp resp to data-dot
(<django at nausch.org>): 250 2.0.0 Ok: queued as 35A9D60004C, dt: 33.9 ms
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01)
Amavis::Out::SMTP::Session close, keeping connection
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
fwd-end-chkpnt - deadline in 479.6 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
fwd-end-chkpnt: timer 288, was 0, deadline in 479.6 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) 1UkmOMluhonk FWD from
<n3rd at omni128.de> -> <django at nausch.org>, BODY=7BIT 250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 35A9D60004C
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
forwarding - deadline in 479.6 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
forwarding: timer 288, was 288, deadline in 479.6 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) DSN: sender NOT
credible, SA: -0.860, <n3rd at omni128.de>
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup: (scalar)
matches, result="10"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup
[spam_dsn_cutoff_level_bysender] => true, "n3rd at omni128.de" matches,
result="10", matching_key="(constant:10)"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) dsn: from MTA 250
NonBlocking:CleanTag <n3rd at omni128.de> -> <django at nausch.org>:
on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=0,
destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250
2.0.0 Ok: queued as 35A9D60004C"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) DSN: SUCC from MTA
250 NonBlocking:CleanTag, no DSN requested: <n3rd at omni128.de> ->
<django at nausch.org>
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01)
delivery_status_notification: notif 0 bytes, suppressed: no
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) one_response_for_all,
per_recip_capable: N, suppressed: N
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) one_response_for_all
<n3rd at omni128.de>: 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 35A9D60004C'
Nov 19 21:33:10 mailslut amavis[26104]: (26104-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 35A9D60004C
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
delivery-notification - deadline in 479.6 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
delivery-notification: timer 288, was 288, deadline in 479.6 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) status counters:
InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedOpenRelay}
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
snmp-counters - deadline in 479.6 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
snmp-counters: timer 288, was 288, deadline in 479.6 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) orcpt_encode rfc822,
django at nausch.org, smtputf8
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01)
oldest_public_ip_addr_from_received: 217.92.13.131
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) Passed CLEAN
{RelayedOpenRelay}, ORIGINATING [127.0.0.1] [217.92.13.131]
<n3rd at omni128.de> -> <django at nausch.org>, mail_id: 1UkmOMluhonk, Hits:
-0.86, size: 566, queued_as: 35A9D60004C, 465 ms
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
main_log_entry - deadline in 479.6 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
main_log_entry: timer 288, was 288, deadline in 479.6 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) TIMING-SA total 325
ms - parse: 0.53 (0.2%), extract_message_metadata: 1.57 (0.5%),
get_uri_detail_list: 0.07 (0.0%), tests_pri_-1000: 1.64 (0.5%),
tests_pri_-950: 0.83 (0.3%), tests_pri_-900: 0.51 (0.2%),
tests_pri_-400: 0.34 (0.1%), tests_pri_0: 310 (95.3%),
check_dkim_signature: 0.43 (0.1%), check_dkim_adsp: 12 (3.6%),
check_spf: 0.16 (0.1%), check_razor2: 282 (86.8%), check_pyzor: 0.09
(0.0%), tests_pri_500: 1.65 (0.5%), get_report: 0.16 (0.0%)
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) updating snmp
variables in BDB
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline check
done - deadline in 479.6 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer check
done: timer 288, was 288, deadline in 479.6 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) sending SMTP
response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok:
queued as 35A9D60004C"
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) ESMTP> 250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 35A9D60004C
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, smtp response sent
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) TempDir::strip:
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) rmdir_recursively:
/var/spool/amavisd/tmp/amavis-20171119T213309-26104-JZzDvo86/parts, excl=1
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) size: 566, TIMING
[total 467 ms] - SMTP greeting: 3.6 (1%)1, SMTP EHLO: 0.6 (0%)1, SMTP
pre-MAIL: 0.2 (0%)1, mkdir tempdir: 0.7 (0%)1, create email.txt: 0.3
(0%)1, SMTP MAIL: 0.8 (0%)1, SMTP pre-DATA-flush: 1.2 (0%)2, SMTP DATA:
39 (8%)10, check_init: 0.3 (0%)10, digest_hdr: 0.3 (0%)10, digest_body:
0.2 (0%)10, collect_info: 1.1 (0%)10, mkdir parts: 1.1 (0%)11,
mime_decode: 3.6 (1%)11, get-file-type1: 8 (2%)13, parts_decode: 0.1
(0%)13, check_header: 0.3 (0%)13, AV-scan-1: 5 (1%)14, spam-wb-list: 0.8
(0%)14, SA msg read: 0.3 (0%)14, SA parse: 1.1 (0%)15, SA check: 324
(69%)84, decide_mail_destiny: 1.9 (0%)84, notif-quar: 0.2 (0%)84,
mangle-altermime: 6 (1%)86, fwd-connect: 22 (5%)91, fwd-xforward: 0.3
(0%)91, fwd-mail-pip: 4.3 (1%)92, fwd-rcpt-pip: 0.1 (0%)92,
fwd-data-chkpnt: 0.0 (0%)92, write-header: 0.2 (0%)92,
fwd-data-contents: 0.0 (0%)92, fwd-end-chkpnt: 34 (7%)99, prepare-dsn:
0.7 (0%)99, report: 0.9 (0%)99, main_log_entry: 2.1 (0%)100, update_s...
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) ...nmp: 0.7 (0%)100,
SMTP pre-response: 0.2 (0%)100, SMTP response: 0.1 (0%)100,
unlink-2-files: 0.1 (0%)100, rundown: 0.3 (0%)100
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) idle_proc, 6: was
busy, 460.5 ms, total idle 0.000 s, busy 0.467 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) idle_proc, 5: was
idle, 0.0 ms, total idle 0.000 s, busy 0.467 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) ESMTP< QUIT\r\n
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) get_deadline
switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) prolong_timer
switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) ESMTP> 221 2.0.0
[127.0.0.1] amavisd-new closing transmission channel
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) switch_to_client_time
480 s, smtp response sent
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) SMTP session over,
timer stopped
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) exiting process_request
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) idle_proc, bye: was
busy, 1.1 ms, total idle 0.000 s, busy 0.468 s
Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) load: 100 %, total
idle 0.000 s, busy 0.468 s
Nov 19 21:33:10 mailslut postfix/smtp[26123]: 7D744600048:
to=<django at nausch.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.8,
delays=0.32/0.01/0.01/0.46, dsn=2.0.0, status=sent (250 2.0.0 from
MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 35A9D60004C)
Nov 19 21:33:10 mailslut postfix/qmgr[26096]: 7D744600048: removed
I've absolutly no idea, why AMaViS won't accept mails from submission
port 587 as originating. :/
Any idea? Suggestions or hints?
ttyl
Django
More information about the amavis-users
mailing list