What's in your /etc/postfix/all_local_domains_map file? This line below says that amavis can't match that email address:
Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup => false, "[email protected]" matches, result="0", matching_key="(constant:0)" Is the nausch.org domain in that file? -----Original Message----- From: amavis-users [mailto:[email protected]] On Behalf Of Django [BOfH] Sent: Sunday, November 19, 2017 4:39 PM To: [email protected] Subject: submission, not originating ... for roaming, authenticated users? 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: [email protected] 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, [email protected] Nov 19 21:33:09 mailslut postfix/cleanup[26120]: 7D744600048: message-id=<> Nov 19 21:33:09 mailslut postfix/qmgr[26096]: 7D744600048: from=<[email protected]>, 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:<[email protected]>\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, "[email protected]" does not match Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250 2.1.0 Sender <[email protected]> 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:<[email protected]> ORCPT=rfc822;[email protected]\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, "[email protected]", no lookup tables Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) ESMTP> 250 2.1.5 Recipient <[email protected]> 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: <[email protected]> -> <[email protected]> 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 <[email protected]>; 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] <[email protected]> -> <[email protected]> Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) 2822.From: <[email protected]> Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_acl([email protected]), no match Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) query_keys: [email protected], django@, nausch.org, .nausch.org, .org, . Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_hash([email protected]), no matches Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [local_domains] => undef, "[email protected]" 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, "[email protected]" 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, "[email protected]" 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, "[email protected]" matches, result="0", matching_key="(constant:0)" Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) Open relay? Nonlocal recips but not originating: [email protected] 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, "[email protected]" 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, "[email protected]" 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 "[email protected]", results: "(constant:DEFAULT)"=>"DEFAULT" Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) collect banned table[0]: [email protected], 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 [email protected] 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:[email protected]] => 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 [email protected]: "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 <[email protected]> Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [blacklist_recip<[email protected]>] => undef, "[email protected]" does not match Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [blacklist_sender<[email protected]>,blacklist_sender] => undef, "[email protected]" does not match Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [whitelist_recip<[email protected]>] => undef, "[email protected]" does not match Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [whitelist_sender<[email protected]>,whitelist_sender] => undef, "[email protected]" does not match Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) query_keys: cached [email protected] Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_hash([email protected]) matches keys: "."=>ARRAY(0x39852e8) Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [score_recip<[email protected]>,score_sender], 1 matches for "[email protected]", results: "."=>[Amavis::Lookup::RE=ARRAY(0x3984ec8),{[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-5",[email protected]=>"-5",[email protected]=>"-3",[email protected]=>"-3",returns.groups.yahoo.com=>"-3",[email protected]=>"-3",.example.net=>"1",securityfocus.com=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",surveys-err... Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) [email protected]=>"-3",spamassassin.apache.org=>"-3",[email protected]=>"-3",[email protected]=>"3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3",[email protected]=>"-3"}] Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_re("[email protected]"), no matches Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) query_keys: [email protected], django@, omni128.de, .omni128.de, .de, . Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup_hash([email protected]), no matches Nov 19 21:33:09 mailslut amavis[26104]: (26104-01) lookup [score_sender<[email protected]>] => undef, "[email protected]" 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)[email protected] 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, "[email protected]" 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, "[email protected]" matches, result="6.31", matching_key="(constant:6.31)" Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup [spam_tag3_level] => undef, "[email protected]" 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, "[email protected]" 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 [email protected] 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, "[email protected]" matches, result="disclaimer", matching_key="(constant:disclaimer)" Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup_acl([email protected]) matches key ".omni128.de", result=1 Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) lookup [local_domains] => true, "[email protected]" 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, <[email protected]> -> <[email protected]> Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) final_destiny PASS, recip [email protected] 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, "[email protected]" 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: [email protected] 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, "[email protected]" 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, "[email protected]" matches, result="6.31", matching_key="(constant:6.31)" Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) headers CLUSTERING: NEW CLUSTER <[email protected]>: 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 <[email protected]>;\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 <[email protected]>;\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, <[email protected]> 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 <[email protected]> -> <[email protected]> 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:<[email protected]> BODY=7BIT Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) smtp cmd> RCPT TO:<[email protected]> 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:<[email protected]> BODY=7BIT\r\nRCPT TO:<[email protected]>\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) (<[email protected]>): 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=<[email protected]> Nov 19 21:33:10 mailslut postfix/qmgr[26096]: 35A9D60004C: from=<[email protected]>, 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 (<[email protected]>): 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 <[email protected]> -> <[email protected]>, 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, <[email protected]> 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, "[email protected]" matches, result="10", matching_key="(constant:10)" Nov 19 21:33:10 mailslut amavis[26104]: (26104-01) dsn: from MTA 250 NonBlocking:CleanTag <[email protected]> -> <[email protected]>: 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: <[email protected]> -> <[email protected]> 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 <[email protected]>: 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, [email protected], 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] <[email protected]> -> <[email protected]>, 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=<[email protected]>, 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
