Aug 5, 2024: iRedMail-1.7.1 has been released.

**k-hussein** · 2018-05-02 21:37:43

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Topic: SPAM in subject

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.4
- Linux/BSD distribution name and version: Ubuntu 14.04 LTS
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): LDAP
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? yes
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

Hello.

Yesterday I needed to add 4 domains to my mail server, however all the added domains when I try to send e-mails from it te subject get changed and SPAM is being added to it.
tried to check the SPF records and DKIM also added DMARC record but still the problem persist any ideas.

be noted that the main domain is working fine.

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

**k-hussein** · 2018-05-02 23:03:33

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

When I test the dkim key I get:
TESTING#2: dkim._domainkey.****.com => pass

but with analyzing header, dkim is none:
spf=pass (sender IP is ) smtp.mailfrom=*****.com; ****.com; dkim=none (message not signed) header.d=none;*****.com; dmarc=pass action=none header.from=****.com;

**ZhangHuangbin** · 2018-05-03 22:54:20

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

*) Did you see DKIM header in the mail source?
*) Do you have AMavisd settings to sign DKIM key for these new domains?

**k-hussein** · 2018-05-04 03:14:35

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

*) Did you see DKIM header in the mail source?
No, thing related to dkim in the header
*) Do you have AMavisd settings to sign DKIM key for these new domains?
yes all set in 50-user for amavis

**k-hussein** · 2018-05-04 05:20:56

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

Update:
in 50-user I updated: $sa_spam_subject_tag= [SPAM] to $sa_spam_subject_tag= undef
and now SPAM got removed from the subject however it is still not DKIM signed, your help appreciated.

**ZhangHuangbin** · 2018-05-04 22:31:01

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

Try this: Use one DKIM key for all mail domains.
https://docs.iredmail.org/sign.dkim.sig … il-domains

**k-hussein** · 2018-05-05 03:43:43

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

tried that, still only the first domain get signed. all the new domains not signed.

**ZhangHuangbin** · 2018-05-05 15:04:11

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

Show us your Amavisd DKIM settings.

**k-hussein** · 2018-05-06 17:30:41

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

I have dkim signing setting per policy bank as below:

$policy_bank{'ORIGINATING'} = {  # mail supposedly originating from our users
    originating => 1,  # declare that mail was submitted by our smtp client
    allow_disclaimers => 1,  # enables disclaimer insertion if available
    enable_dkim_signing => 1,

    # notify administrator of locally originating malware
    virus_admin_maps => ["root\@$mydomain"],
    spam_admin_maps  => [],
    bad_header_admin_maps => [],
    banned_admin_maps => ["root\@$mydomain"],
    warnbadhsender   => 1,
    warnbannedsender => 1,

    # force MTA conversion to 7-bit (e.g. before DKIM signing)
    #smtpd_discard_ehlo_keywords => ['8BITMIME'],

    # don't remove NOTIFY=SUCCESS option
    terminate_dsn_on_notify_success => 0,

    # don't perform spam/virus/header check.
    #bypass_spam_checks_maps => [1],    # ORIGINATING spam
    #bypass_header_checks_maps => [1],  # ORIGINATING bad-header
    #bypass_virus_checks_maps => [1],   # ORIGINATING virus
    #bypass_banned_checks_maps => [1],  # ORIGINATING banned file types

    #forward to a smtpd service providing DKIM signing service
    #forward_method => 'smtp:[amavis]:10027',
    #force MTA conversion to 7-bit (e.g. before DKIM signing)
    #smtpd_discard_ehlo_keywords => ['8BITMIME'],
    #bypass_banned_checks_maps => [1],  # allow sending any file names and types
    #terminate_dsn_on_notify_success => 0,  # don't remove NOTIFY=SUCCESS option
};

and

$policy_bank{'MYNETS'} = {   # mail originating from @mynetworks
  originating => 1,  # is true in MYNETS by default, but let's make it explicit
  os_fingerprint_method => undef,  # don't query p0f for internal clients
  allow_disclaimers => 1,  # enables disclaimer insertion if available
  enable_dkim_signing => 1,

and this is the domains settings:

dkim_key("maindomain.com", "dkim", "/var/lib/dkim/maindomain.net02.pem");
dkim_key("domain1.com", "dkim", "/var/lib/dkim/domain1.com.pem");
dkim_key("domain2.com", "dkim", "/var/lib/dkim/domain2.com.pem");
dkim_key("domain3", "dkim", "/var/lib/dkim/domain3.pem");
dkim_key("domain4.com", "dkim", "/var/lib/dkim/domain4.pem");
dkim_key("domain5.com", "dkim", "/var/lib/dkim/domain5.com.pem");

    "maindomain.com"  => { d => "maindomain.com", a => 'rsa-sha256', ttl => 10*24*3600 },    
    "domain1.com"  => { d => "domain1.com", a => 'rsa-sha256', ttl => 10*24*3600 },
    "domain2.com"  => { d => "domain2.com", a => 'rsa-sha256', ttl => 10*24*3600 },
    "domain3.com"  => { d => "domain3.com", a => 'rsa-sha256', ttl => 10*24*3600 },
    "domain4.com"  => { d => "domain4.com", a => 'rsa-sha256', ttl => 10*24*3600 },
    "domain5.com"  => { d => "domain5.com", a => 'rsa-sha256', ttl => 10*24*3600 },

the only working dkim signing is for maindomain.

**ZhangHuangbin** · 2018-05-08 10:50:46

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

k-hussein wrote:

dkim_key("maindomain.com", "dkim", "/var/lib/dkim/maindomain.net02.pem");
dkim_key("domain1.com", "dkim", "/var/lib/dkim/domain1.com.pem");
dkim_key("domain2.com", "dkim", "/var/lib/dkim/domain2.com.pem");
dkim_key("domain3", "dkim", "/var/lib/dkim/domain3.pem");
dkim_key("domain4.com", "dkim", "/var/lib/dkim/domain4.pem");
dkim_key("domain5.com", "dkim", "/var/lib/dkim/domain5.com.pem");

Do you have all dkim key files under /var/lib/dkim/?

Any error in Amavisd log file?

**k-hussein** · 2018-05-08 21:38:22

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

Do you have all dkim key files under /var/lib/dkim/? Yes

this is the amavis debugging for 1 external mail:

May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-02) Net::Server: 2018/05/07-15:49:00 CONNECT TCP Peer: "[127.0.0.1]:47289" Local: "[127.0.0.1]:10026"
May  7 15:49:00 Exchange-P01 amavis[14573]: () idle_proc, hi : was idle, 2023.3 ms, total idle 8.017 s, busy 0.315 s
May  7 15:49:00 Exchange-P01 amavis[14573]: () loaded base policy bank
May  7 15:49:00 Exchange-P01 amavis[14573]: () loaded policy bank "ORIGINATING"
May  7 15:49:00 Exchange-P01 amavis[14573]: () lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
May  7 15:49:00 Exchange-P01 amavis[14573]: () process_request: fileno sock=14, STDIN=0, STDOUT=1
May  7 15:49:00 Exchange-P01 amavis[14573]: () get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: () prolong_timer switch_to_my_time(new request): timer 336, was 0, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: () process_request: suggested_protocol="" on a TCP socket
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 4: was busy, 3.4 ms, total idle 8.017 s, busy 0.318 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp readline: read 23 bytes into buffer, new size: 23
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 5: was idle, 0.3 ms, total idle 8.018 s, busy 0.318 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) SMTP< EHLO Exchange-P01.com\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx SMTP EHLO) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx SMTP EHLO): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250-[127.0.0.1]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250-VRFY
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250-PIPELINING
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250-SIZE
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250-ENHANCEDSTATUSCODES
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250-8BITMIME
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250-DSN
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250 XFORWARD NAME ADDR PORT PROTO HELO IDENT SOURCE
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 6: was busy, 1.8 ms, total idle 8.018 s, busy 0.320 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp readline: read 237 bytes into buffer, new size: 237
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 5: was idle, 0.3 ms, total idle 8.018 s, busy 0.320 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP< XFORWARD NAME=localhost ADDR=127.0.0.1 PORT=42738\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250 2.5.0 Ok XFORWARD
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 6: was busy, 1.0 ms, total idle 8.018 s, busy 0.321 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 5: was idle, 0.1 ms, total idle 8.018 s, busy 0.321 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP< XFORWARD PROTO=ESMTP HELO=_ IDENT=BB38B5CC5262 SOURCE=LOCAL\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx SMTP XFORWARD) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx SMTP XFORWARD): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250 2.5.0 Ok XFORWARD
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 6: was busy, 0.9 ms, total idle 8.018 s, busy 0.322 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 5: was idle, 0.1 ms, total idle 8.018 s, busy 0.322 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP< MAIL FROM:<efax@domain1> SIZE=1030\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx SMTP MAIL) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx SMTP MAIL): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) check_mail_begin_task: task_count=3
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_ip_acl arr.obj: key="127.0.0.1" matches "127.0.0.0/8", result=1
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) loaded policy bank "MYNETS" over "ORIGINATING"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [debug_sender] => undef, "efax@domain1" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250 2.1.0 Sender <efax@domain1> OK
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 6: was busy, 2.2 ms, total idle 8.018 s, busy 0.324 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 5: was idle, 0.1 ms, total idle 8.019 s, busy 0.324 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP< RCPT TO:<user.user.1@externaldomain.com> ORCPT=rfc822;user.user.1@externaldomain.com\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup => undef, "user.user.1@externaldomain.com", no lookup tables
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="1"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [local_domains] => true,  "user.user.1@externaldomain.com" matches, result="1", matching_key="(constant:1)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) query_keys: user.user.1@externaldomain.com, user.user.1, @externaldomain.com, @.externaldomain.com, @.com, @.
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql sel_policy "user.user.1@externaldomain.com", query args: [user.user.1@externaldomain.com,-3], [user.user.1,-3], [@externaldomain.com,-3], [@.externaldomain.com,-3], [@.com,-3], [@.,-3]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql select: SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql begin, nontransaction
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: SELECT users.*, policy.*, users.id FROM users LEFT JOIN policy ON users.policy_id=policy.id WHERE users.email IN (?,?,?,?,?,?) ORDER BY users.priority DESC
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql: "user.user.1@externaldomain.com" matches catchall, local=>undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql(user.user.1@externaldomain.com) matches, result=(id=>"2", priority=>"0", policy_id=>"2", email=>"@.", fullname=>-, id=>"2", policy_name=>"@.", virus_lover=>-, spam_lover=>"N", unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>"virus-quarantine", spam_quarantine_to=>"spam-quarantine", banned_quarantine_to=>-, unchecked_quarantine_to=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, addr_extension_virus=>-, addr_extension_spam=>-, addr_extension_banned=>-, addr_extension_bad_header=>-, warnvirusrecip=>-, warnbannedrecip=>-, warnbadhrecip=>-, newvirus_admin=>-, virus_admin=>-, banned_admin=>-, bad_header_admin=>-, spam_admin=>-, spam_subject_tag=>-, ...
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ...spam_subject_tag2=>-, spam_subject_tag3=>-, message_size_limit=>"20971520", banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"2", local=>-)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(message_size_limit) rec=0, "user.user.1@externaldomain.com" result: "20971520"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [message_size_limit] => true,  "user.user.1@externaldomain.com" matches, result="20971520", matching_key="id=>"2", priority=>"0", policy_id=>"2", email=>"@.", fullname=>-, id=>"2", policy_name=>"@.", virus_lover=>-, spam_lover=>"N", unchecked_lover=>-, banned_files_lover=>-, bad_header_lover=>-, bypass_virus_checks=>-, bypass_spam_checks=>-, bypass_banned_checks=>-, bypass_header_checks=>-, virus_quarantine_to=>"virus-quarantine", spam_quarantine_to=>"spam-quarantine", banned_quarantine_to=>-, unchecked_quarantine_to=>-, bad_header_quarantine_to=>-, clean_quarantine_to=>-, archive_quarantine_to=>-, spam_tag_level=>-, spam_tag2_level=>-, spam_tag3_level=>-, spam_kill_level=>-, spam_dsn_cutoff_level=>-, spam_quarantine_cutoff_level=>-, addr_extension_virus=>-, addr_extension_spam=>-, addr_extension_banned=>-, addr_extension_bad_header=>-, warnvirusrecip=>-, warnbannedrecip=>-, warnbadhrecip=>-, newvirus_admin=>-, virus_admin=>-, banned_admin=>-, bad_...
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ...header_admin=>-, spam_admin=>-, spam_subject_tag=>-, spam_subject_tag2=>-, spam_subject_tag3=>-, message_size_limit=>"20971520", banned_rulenames=>-, disclaimer_options=>-, forward_method=>-, sa_userconf=>-, sa_username=>-, id=>"2", local=>-"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250 2.1.5 Recipient <user.user.1@externaldomain.com> OK
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 6: was busy, 4.5 ms, total idle 8.019 s, busy 0.329 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 5: was idle, 0.2 ms, total idle 8.019 s, busy 0.329 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP< DATA\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx SMTP DATA) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx SMTP DATA): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP::10026 /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw: <efax@domain1> -> <user.user.1@externaldomain.com> SIZE=1030 Received: from Exchange-P01.com ([127.0.0.1]) by localhost (Exchange-P01.com [127.0.0.1]) (amavisd-new, port 10026) with ESMTP for <user.user.1@externaldomain.com>; Mon,  7 May 2018 15:49:00 -0400 (EDT)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 354 End data with <CR><LF>.<CR><LF>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, receiving data
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) enforcing size limit 20971520 during DATA
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp copy: read 1039 bytes into buffer, new size: 1039
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp copy: 6 bytes still buffered at end
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx data-end) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx data-end): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP< .<CR><LF>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp connection cache, dt: 2.0, state: 0
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp connection cache, dt: 2.0 -> enabling
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline get_body_digest - deadline in 480.0 s, set to 30.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline digest_pre - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer digest_pre: timer 336, was 336, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_body_digest: reading header section
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline digest_hdr - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer digest_hdr: timer 336, was 336, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_body_digest: reading mail body
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline digest_body - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer digest_body: timer 336, was 336, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) body type (ESMTP BODY): unlabeled, good (h=0, b=0)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) body hash: 1c32ccb2614549974f8d732d3be5bfc8
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Original mail size: 1030; quota set to: 515000 bytes
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql begin, nontransaction
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: SELECT id FROM maddr WHERE partition_tag=? AND email=?
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) save_info_preliminary JdtXFswh4ins, sender id: 269442, efax@domain1, exists
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql begin, nontransaction
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: SELECT id FROM maddr WHERE partition_tag=? AND email=?
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) save_info_preliminary JdtXFswh4ins, recip id: 268968, user.user.1@externaldomain.com, exists
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql begin transaction
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: INSERT INTO msgs (partition_tag, mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?,?)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql commit
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Checking: JdtXFswh4ins ORIGINATING/MYNETS [127.0.0.1] <efax@domain1> -> <user.user.1@externaldomain.com>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) 2822.From: <efax@domain1>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(local) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="1"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [local_domains] => true,  "user.user.1@externaldomain.com" matches, result="1", matching_key="(constant:1)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(bypass_virus_checks) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [bypass_virus_checks] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(bypass_banned_checks) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [bypass_banned_checks] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(bypass_spam_checks) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [bypass_spam_checks] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(id) rec=0, "user.user.1@externaldomain.com" result: "2"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [users.id], 1 matches for "user.user.1@externaldomain.com", results: "/cached/"=>"2"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(policy_id) rec=0, "user.user.1@externaldomain.com" result: "2"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [users.policy_id] => true,  "user.user.1@externaldomain.com" matches, result="2", matching_key="/cached/"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Extracting mime components
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Issued a new file name: p001
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Issued a new file name: p002
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Issued a new pseudo part: p003
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) p003 1 Content-Type: multipart/alternative
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Charging 8 bytes to remaining quota 515000 (out of 515000, (0%)) - by mime_decode
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) p001 1/1 Content-Type: text/plain, size: 8 B, name: 
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) reparenting p001 from p000 to p003
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Charging 204 bytes to remaining quota 514992 (out of 515000, (0%)) - by mime_decode
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) p002 1/2 Content-Type: text/html, size: 204 B, name: 
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) reparenting p002 from p000 to p003
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline mime_decode - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer mime_decode: timer 336, was 336, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline mime_decode-1 - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer mime_decode-1: timer 336, was 336, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) decode_parts: level=1, #parts=3 : p001, p002, p003
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) running file(1) on 2 files, arglist size 23
May  7 15:49:00 Exchange-P01 postfix/smtpd[14278]: disconnect from localhost[127.0.0.1]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) run_command: [14746] /usr/bin/file p001 p002 </dev/null 2>&1
May  7 15:49:00 Exchange-P01 amavis[14746]: (14573-03) open_on_specific_fd: target fd0 closing, to become < /dev/null
May  7 15:49:00 Exchange-P01 amavis[14746]: (14573-03) open_on_specific_fd: target fd1 closing, to become > &=18
May  7 15:49:00 Exchange-P01 amavis[14746]: (14573-03) open_on_specific_fd: target fd1 dup2 from fd18 > &=18
May  7 15:49:00 Exchange-P01 amavis[14746]: (14573-03) open_on_specific_fd: source fd18 closed
May  7 15:49:00 Exchange-P01 amavis[14746]: (14573-03) open_on_specific_fd: target fd2 closing, to become > &1
May  7 15:49:00 Exchange-P01 amavis[14746]: (14573-03) open_on_specific_fd: target fd2 dup2 from fd1 > &1
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) result line from file(1): p001: ASCII text\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_re("ASCII text") matches key "(?^i:^(ASCII|text)\b)", result="asc"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [map_full_type_to_short_type] => true,  "ASCII text" matches, result="asc", matching_key="(?^i:^(ASCII|text)\\b)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) File-type of p001: ASCII text; (asc)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) result line from file(1): p002: HTML document, ASCII text\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_re("HTML document, ASCII text") matches key "(?^i:\btext\b)", result="asc"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [map_full_type_to_short_type] => true,  "HTML document, ASCII text" matches, result="asc", matching_key="(?^i:\\btext\\b)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) File-type of p002: HTML document, ASCII text; (asc)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) decompose_part: p001 - atomic
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) decompose_part: p002 - atomic
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline parts_decode - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer parts_decode: timer 336, was 336, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(bypass_header_checks) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [bypass_header_checks] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) check_header: 0, OK
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(bypass_header_checks) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [bypass_header_checks] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Checking for banned types and filenames
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(banned_rulenames) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="DEFAULT"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [banned_filename], 1 matches for "user.user.1@externaldomain.com", results: "(constant:DEFAULT)"=>"DEFAULT"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) collect banned table[0]: user.user.1@externaldomain.com, tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x3830550)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) starting banned checks - traversing message structure tree
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) check_for_banned (p003,p001) multipart/alternative | text/plain,.asc
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) doing banned check for user.user.1@externaldomain.com on multipart/alternative | text/plain,.asc
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_re(["multipart/alternative","text/plain",".asc"]), no matches
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [check_bann:user.user.1@externaldomain.com] => undef, ["multipart/alternative","text/plain",".asc"] does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/alternative\nP=p001\tL=1/1\tM=text/plain\tT=asc" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) p.path user.user.1@externaldomain.com: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1,M=text/plain,T=asc"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) check_for_banned (p003,p002) multipart/alternative | text/html,.asc
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) doing banned check for user.user.1@externaldomain.com on multipart/alternative | text/html,.asc
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_re(["multipart/alternative","text/html",".asc"]), no matches
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [check_bann:user.user.1@externaldomain.com] => undef, ["multipart/alternative","text/html",".asc"] does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [banned_namepath_re] => undef, "P=p003\tL=1\tM=multipart/alternative\nP=p002\tL=1/2\tM=text/html\tT=asc" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) p.path user.user.1@externaldomain.com: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2,M=text/html,T=asc"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) banned check: any=0, all=N (1)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_re("MAIL"), no matches
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [keep_decoded_original] => undef, "MAIL" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) invoking av-scanner ClamAV-clamd
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /tmp/clamd.socket
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline run_av_pre - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer run_av_pre: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline run_av_scan - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer run_av_scan: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline ask_daemon_internal_connect_pre - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline ask_daemon_internal_connect - deadline in 479.9 s, set to 10.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer ask_daemon_internal_connect: timer 10, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ClamAV-clamd: Connecting to socket  /tmp/clamd.socket
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) new socket by IO::Socket::UNIX to /tmp/clamd.socket, timeout 10
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) connected to /tmp/clamd.socket successfully
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts\n to socket /tmp/clamd.socket
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=0, flush=1, wr=1, timeout=10
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: sending
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline ask_daemon_internal_scan - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer ask_daemon_internal_scan: timer 336, was 10, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=0, flush=0, wr=0, timeout=335.999
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts: OK\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=0, flush=0, wr=0, timeout=335.999
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read: got eof
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer ask_daemon_internal: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline run_av_3 - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer run_av_3: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts: OK\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) run_av (ClamAV-clamd): CLEAN
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) run_av (ClamAV-clamd) result: clean
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) wbl: checking sender <efax@domain1>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) wbl: (SQL) recip <user.user.1@externaldomain.com>, 1 matches
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="1"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [local_domains] => true,  "efax@domain1" matches, result="1", matching_key="(constant:1)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) query_keys: efax@domain1, efax, @domain1, @.domain1, @.com, @.
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql sel_wblist "efax@domain1", query args: "2", [efax@domain1,-3], [efax,-3], [@domain1,-3], [@.domain1,-3], [@.com,-3], [@.,-3]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql select: SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql begin, nontransaction
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: SELECT wb FROM wblist JOIN mailaddr ON wblist.sid=mailaddr.id WHERE wblist.rid=? AND mailaddr.email IN (?,?,?,?,?,?) ORDER BY mailaddr.priority DESC
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql(efax@domain1) matches, result=(wb=>"B")
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(wb) rec=0, "efax@domain1" result: "B"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup => true,  "efax@domain1" matches, result="B", matching_key="wb=>"B""
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) wbl: (SQL) recip <user.user.1@externaldomain.com>, rid=2, got: "B"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) wbl: (SQL) recip <user.user.1@externaldomain.com> blacklisted sender <efax@domain1>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) query_keys: user.user.1@externaldomain.com, user.user.1@, externaldomain.com, .externaldomain.com, .com, .
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_hash(user.user.1@externaldomain.com) matches keys: "."=>ARRAY(0x3c4a338)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [score_recip<user.user.1@externaldomain.com>,score_sender], 1 matches for "user.user.1@externaldomain.com", results: "."=>[Amavis::Lookup::RE=ARRAY(0x3c4a4a0),{}]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_re("efax@domain1"), no matches
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [score_sender<efax@domain1>] => undef, "efax@domain1" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) wbl: blacklisted sender <efax@domain1>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sender white/blacklisted, skipping spam_scan
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_tag_level) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="2"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_tag_level] => true,  "user.user.1@externaldomain.com" matches, result="2", matching_key="(constant:2)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_tag2_level) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="6.31"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_tag2_level] => true,  "user.user.1@externaldomain.com" matches, result="6.31", matching_key="(constant:6.31)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_tag3_level) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_tag3_level] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_kill_level) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="6.31"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_kill_level] => true,  "user.user.1@externaldomain.com" matches, result="6.31", matching_key="(constant:6.31)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(message_size_limit) rec=0, "user.user.1@externaldomain.com" result: "20971520"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [message_size_limit] => true,  "user.user.1@externaldomain.com" matches, result="20971520", matching_key="/cached/"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) final_destiny (ccat=6) is PASS, recip user.user.1@externaldomain.com
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) final_destiny (ccat=5) is PASS, recip user.user.1@externaldomain.com
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) final_destiny (ccat=0) is PASS, recip user.user.1@externaldomain.com
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) final_destiny PASS, recip user.user.1@externaldomain.com
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) do_notify_and_quar: ccat=Spam (6,0) ("6":Spam, "5,1":Spammy3, "5":Spammy, "1,1":CleanTag, "1":Clean, "0":CatchAll) ccat_block=(), qar_mth=
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) do_notify_and_quarantine: not quarantining, q_method off
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup => undef, "user.user.1@externaldomain.com", no lookup tables
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_quarantine_bysender_to] => undef, "efax@domain1" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) skip admin notification, no administrators
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) do_notify_and_quarantine - done
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(forward_method) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [forward_method] => true,  "user.user.1@externaldomain.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) delivery method is smtp:[127.0.0.1]:10025, recips: user.user.1@externaldomain.com
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_tag_level) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="2"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_tag_level] => true,  "user.user.1@externaldomain.com" matches, result="2", matching_key="(constant:2)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_tag2_level) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup: (scalar) matches, result="6.31"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_tag2_level] => true,  "user.user.1@externaldomain.com" matches, result="6.31", matching_key="(constant:6.31)"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_subject_tag3) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_subject_tag3] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_subject_tag2) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_subject_tag2] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_sql_field(spam_subject_tag) rec=0, "user.user.1@externaldomain.com" result: undef
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_subject_tag] => undef, "user.user.1@externaldomain.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) headers CLUSTERING: NEW CLUSTER <user.user.1@externaldomain.com>: score=x, tag=1, tag2=1, local=1, bl=1, s=, mangle=
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: X-Virus-Scanned: Debian amavisd-new at Exchange-P01.com\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: X-Spam-Flag: YES\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: X-Spam-Score: 64\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: X-Spam-Level: ****************************************************************\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: X-Spam-Status: Yes, score=x tagged_above=2 required=6.31 BLACKLISTED tests=[]\n\tautolearn=unavailable\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: Received: from Exchange-P01.com ([127.0.0.1])\n\tby localhost (Exchange-P01.com [127.0.0.1]) (amavisd-new, port 10026)\n\twith ESMTP id JdtXFswh4ins for <user.user.1@externaldomain.com>;\n\tMon,  7 May 2018 15:49:00 -0400 (EDT)\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) headers CLUSTERING: done all 1 recips in one go
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) spam-tag, <efax@domain1> -> <user.user.1@externaldomain.com>, Yes, score=x tagged_above=2 required=6.31 BLACKLISTED tests=[] autolearn=unavailable
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) dkim: not signing spam (from inside), From: <efax@domain1>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) about to connect to smtp:[127.0.0.1]:10025, FWD from <efax@domain1> -> <user.user.1@externaldomain.com>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline fwd_init - deadline in 479.9 s, set to 480.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp session: setting up a new session
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) establish_or_refresh, state: down
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) new socket by IO::Socket::INET to [127.0.0.1]:10025, timeout 35, blocking
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) connected to [127.0.0.1]:10025 successfully
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=35
May  7 15:49:00 Exchange-P01 postfix/smtpd[12556]: connect from localhost[127.0.0.1]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read 45 chars< 220 Exchange-P01.com ESMTP Postfix (Ubuntu)\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp greeting: 220 Exchange-P01.com ESMTP Postfix (Ubuntu)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> EHLO localhost
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=0, flush=1, wr=1, timeout=300
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: sending
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop sent 16> EHLO localhost\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=300
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read 116 chars< 250-Exchange-P01.com\r\n250-PIPELINING\r\n250-SIZE 104857600\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to EHLO: 250 Exchange-P01.com\nPIPELINING\nSIZE 104857600\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) tls active=0, capable=, sec_level=0
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Remote host presents itself as: Exchange-P01.com, handles DSN, handles PIPELINING
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) AUTH not needed, user='', MTA offers ''
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> MAIL FROM:<efax@domain1> BODY=7BIT
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> RCPT TO:<user.user.1@externaldomain.com> ORCPT=rfc822;user.user.1@externaldomain.com
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> DATA
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=0, flush=1, wr=1, timeout=120
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: sending
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop sent 125> MAIL FROM:<efax@domain1> BODY=7BIT\r\nRCPT TO:<user.user.1@externaldomain.com> ORCPT=rfc822;user.user.1@externaldomain.com\r\nDATA\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=300
May  7 15:49:00 Exchange-P01 postfix/smtpd[12556]: E5B5B5CC5286: client=localhost[127.0.0.1]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) 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
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to MAIL (pip): 250 2.1.0 Ok
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to RCPT (pip) (<user.user.1@externaldomain.com>): 250 2.1.5 Ok
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x8206b40)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=1, timeout=479.986
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: sending
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop sent 1532> X-Virus-Scanned: Debian amavisd-new at Exchange-P01.com\r\nX-Spam-Flag: YES\r\nX-Spam-Score: 64\r\nX-Spam-Level: ****************************************************************\r\nX-Spam-Status: Yes, score=x [...]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=479.986
May  7 15:49:00 Exchange-P01 postfix/cleanup[13960]: E5B5B5CC5286: message-id=<6d7a736ab1320863e4609e1f7586eddc@domain1>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 postfix/qmgr[32988]: E5B5B5CC5286: from=<efax@domain1>, size=1713, nrcpt=1 (queue active)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read 38 chars< 250 2.0.0 Ok: queued as E5B5B5CC5286\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to data-dot (<user.user.1@externaldomain.com>): 250 2.0.0 Ok: queued as E5B5B5CC5286
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Amavis::Out::SMTP::Session close, keeping connection
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline fwd-end-chkpnt - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer fwd-end-chkpnt: timer 336, was 0, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) FWD from <efax@domain1> -> <user.user.1@externaldomain.com>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline forwarding - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer forwarding: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) DSN: sender is credible (orig), SA: 0.000, <efax@domain1>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "efax@domain1" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) dsn: from MTA 250 NonBlocking:Spam <efax@domain1> -> <user.user.1@externaldomain.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) DSN: SUCC from MTA 250 NonBlocking:Spam, no DSN requested: <efax@domain1> -> <user.user.1@externaldomain.com>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) one_response_for_all <efax@domain1>: 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 E5B5B5CC5286'
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) 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 E5B5B5CC5286
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) status counters: InMsgsStatus{Relayed,RelayedTagged,RelayedTaggedInternal,RelayedTaggedOriginating}
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline delivery-notification - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer delivery-notification: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) fish_out_ip_from_received: 127.0.0.1
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_ip_acl (publicnetworks) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) parse_ip_address_from_received: 127.0.0.1
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Passed SPAM {RelayedTaggedInternal}, ORIGINATING/MYNETS LOCAL [127.0.0.1]:42738 [127.0.0.1] <efax@domain1> -> <user.user.1@externaldomain.com>, Queue-ID: BB38B5CC5262, Message-ID: <6d7a736ab1320863e4609e1f7586eddc@domain1>, mail_id: JdtXFswh4ins, Hits: -, size: 1030, queued_as: E5B5B5CC5286, 145 ms
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline main_log_entry - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer main_log_entry: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql begin transaction
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) save_info_final JdtXFswh4ins, orig=Y, chks=VHB, cont.ty=S, q.type= , q.to=, dsn=N, score=0, Message-ID: <6d7a736ab1320863e4609e1f7586eddc@domain1>, From: 'efax@domain1', Subject: 'test'
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE partition_tag=? AND mail_id=?
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql commit
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) updating snmp variables
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline check done - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer check done: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286
May  7 15:49:00 Exchange-P01 postfix/smtp[14252]: BB38B5CC5262: to=<user.user.1@externaldomain.com>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.23, delays=0.07/0/0.01/0.15, 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 E5B5B5CC5286)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) TempDir::strip: /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rmdir_recursively: /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts, excl=1
May  7 15:49:00 Exchange-P01 postfix/qmgr[32988]: BB38B5CC5262: removed

**ZhangHuangbin** · 2018-05-10 08:07:27

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

Only one line found:

May 7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) dkim: not signing spam (from inside), From: <efax@domain1>

**k-hussein** · 2018-05-11 01:09:05

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

here is the rest of the log:

May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) about to connect to smtp:[127.0.0.1]:10025, FWD from <efax@domain1.com> -> <testuser@externaldomain.com>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline fwd_init - deadline in 479.9 s, set to 480.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp session: setting up a new session
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) establish_or_refresh, state: down
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) new socket by IO::Socket::INET to [127.0.0.1]:10025, timeout 35, blocking
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) connected to [127.0.0.1]:10025 successfully
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=35
May  7 15:49:00 Exchange-P01 postfix/smtpd[12556]: connect from localhost[127.0.0.1]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read 45 chars< 220 Exchange-P01.com ESMTP Postfix (Ubuntu)\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp greeting: 220 Exchange-P01.com ESMTP Postfix (Ubuntu)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> EHLO localhost
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=0, flush=1, wr=1, timeout=300
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: sending
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop sent 16> EHLO localhost\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=300
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read 116 chars< 250-Exchange-P01.com\r\n250-PIPELINING\r\n250-SIZE 104857600\r\n250-ETRN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250 DSN\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to EHLO: 250 Exchange-P01.com\nPIPELINING\nSIZE 104857600\nETRN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) tls active=0, capable=, sec_level=0
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Remote host presents itself as: Exchange-P01.com, handles DSN, handles PIPELINING
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) AUTH not needed, user='', MTA offers ''
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> MAIL FROM:<efax@domain1.com> BODY=7BIT
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> RCPT TO:<testuser@externaldomain.com> ORCPT=rfc822;testuser@externaldomain.com
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp cmd> DATA
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=0, flush=1, wr=1, timeout=120
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: sending
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop sent 125> MAIL FROM:<efax@domain1.com> BODY=7BIT\r\nRCPT TO:<testuser@externaldomain.com> ORCPT=rfc822;testuser@externaldomain.com\r\nDATA\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=300
May  7 15:49:00 Exchange-P01 postfix/smtpd[12556]: E5B5B5CC5286: client=localhost[127.0.0.1]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) 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
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to MAIL (pip): 250 2.1.0 Ok
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to RCPT (pip) (<testuser@externaldomain.com>): 250 2.1.5 Ok
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) write_header: 0, Amavis::Out::SMTP::Protocol=HASH(0x8206b40)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=1, timeout=479.986
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: sending
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop sent 1532> X-Virus-Scanned: Debian amavisd-new at Exchange-P01.com\r\nX-Spam-Flag: YES\r\nX-Spam-Score: 64\r\nX-Spam-Level: ****************************************************************\r\nX-Spam-Status: Yes, score=x [...]
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: needline=1, flush=0, wr=0, timeout=479.986
May  7 15:49:00 Exchange-P01 postfix/cleanup[13960]: E5B5B5CC5286: message-id=<6d7a736ab1320863e4609e1f7586eddc@domain1.com>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop: receiving
May  7 15:49:00 Exchange-P01 postfix/qmgr[32988]: E5B5B5CC5286: from=<efax@domain1.com>, size=1713, nrcpt=1 (queue active)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rw_loop read 38 chars< 250 2.0.0 Ok: queued as E5B5B5CC5286\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) smtp resp to data-dot (<testuser@externaldomain.com>): 250 2.0.0 Ok: queued as E5B5B5CC5286
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Amavis::Out::SMTP::Session close, keeping connection
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline fwd-end-chkpnt - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer fwd-end-chkpnt: timer 336, was 0, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) FWD from <efax@domain1.com> -> <testuser@externaldomain.com>,BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline forwarding - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer forwarding: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) DSN: sender is credible (orig), SA: 0.000, <efax@domain1.com>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "efax@domain1.com" does not match
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) dsn: from MTA 250 NonBlocking:Spam <efax@domain1.com> -> <testuser@externaldomain.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) DSN: SUCC from MTA 250 NonBlocking:Spam, no DSN requested: <efax@domain1.com> -> <testuser@externaldomain.com>
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) one_response_for_all <efax@domain1.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286'
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) 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 E5B5B5CC5286
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) status counters: InMsgsStatus{Relayed,RelayedTagged,RelayedTaggedInternal,RelayedTaggedOriginating}
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline delivery-notification - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer delivery-notification: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) fish_out_ip_from_received: 127.0.0.1
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) lookup_ip_acl (publicnetworks) arr.obj: key="127.0.0.1" matches "!127.0.0.0/8", result=0
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) parse_ip_address_from_received: 127.0.0.1
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) Passed SPAM {RelayedTaggedInternal}, ORIGINATING/MYNETS LOCAL [127.0.0.1]:42738 [127.0.0.1] <efax@domain1.com> -> <testuser@externaldomain.com>, Queue-ID: BB38B5CC5262, Message-ID: <6d7a736ab1320863e4609e1f7586eddc@domain1.com>, mail_id: JdtXFswh4ins, Hits: -, size: 1030, queued_as: E5B5B5CC5286, 145 ms
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline main_log_entry - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer main_log_entry: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql begin transaction
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) save_info_final JdtXFswh4ins, orig=Y, chks=VHB, cont.ty=S, q.type= , q.to=, dsn=N, score=0, Message-ID: <6d7a736ab1320863e4609e1f7586eddc@domain1.com>, From: 'efax@domain1.com', Subject: 'test'
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql: executing clause: UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE partition_tag=? AND mail_id=?
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sql commit
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) updating snmp variables
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline check done - deadline in 479.9 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer check done: timer 336, was 336, deadline in 479.9 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286"
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as E5B5B5CC5286
May  7 15:49:00 Exchange-P01 postfix/smtp[14252]: BB38B5CC5262: to=<testuser@externaldomain.com>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.23, delays=0.07/0/0.01/0.15, 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 E5B5B5CC5286)
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) TempDir::strip: /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) rmdir_recursively: /var/lib/amavis/tmp/amavis-20180507T154852-14573-TRQffDaw/parts, excl=1
May  7 15:49:00 Exchange-P01 postfix/qmgr[32988]: BB38B5CC5262: removed
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) size: 1030, TIMING [total 156 ms] - SMTP greeting: 3 (2%)2, SMTP EHLO: 2 (1%)3, SMTP pre-MAIL: 3 (2%)5, lookup_sql: 5 (3%)9, SMTP pre-DATA-flush: 3 (2%)10, SMTP DATA: 28 (18%)28, check_init: 1 (0%)29, digest_hdr: 1 (1%)30, digest_body_dkim: 1 (1%)30, gen_mail_id: 6 (4%)34, mime_decode: 13 (8%)43, get-file-type2: 22 (14%)57, parts_decode: 0 (0%)57, check_header: 2 (1%)59, AV-scan-1: 14 (9%)68, lookup_sql: 2 (1%)69, spam-wb-list: 1 (1%)70, decide_mail_destiny: 2 (1%)71, notif-quar: 1 (0%)71, fwd-connect: 7 (4%)75, fwd-mail-pip: 10 (6%)82, fwd-rcpt-pip: 0 (0%)82, fwd-data-chkpnt: 0 (0%)82, write-header: 1 (0%)82, fwd-data-contents: 0 (0%)82, fwd-end-chkpnt: 4 (3%)85, prepare-dsn: 2 (1%)87, main_log_entry: 11 (7%)94, sql-update: 3 (2%)96, update_snmp: 3 (2%)98, SMTP pre-response: 1 (0%)98, SMTP response: 1 (0%)99, unlink-2-files: 0 (0%)99, rundown: 2 (1%)100
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 6: was busy, 141.4 ms, total idle 8.019 s, busy 0.470 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, 5: was idle, 0.2 ms, total idle 8.019 s, busy 0.470 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP< QUIT\r\n
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 336.000 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 336, was 480, deadline in 480.0 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) switch_to_client_time 480 s, smtp response sent
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) SMTP session over, timer stopped
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) exiting process_request
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) idle_proc, bye: was busy, 1.8 ms, total idle 8.019 s, busy 0.472 s
May  7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) load: 6 %, total idle 8.019 s, busy 0.472 s

**ZhangHuangbin** · 2018-05-13 11:51:52

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

Check my previous reply:

May 7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) dkim: not signing spam (from inside), From: <efax@domain1>

The email is considered as spam, and Amavisd doesn't sign it.

**k-hussein** · 2018-05-14 21:34:39

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

any ideas where to look why it consider this mails as a spam ?

**k-hussein** · 2018-05-15 00:38:50

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

update:
I have enabled those 2 lines in Originating policy bank:
bypass_spam_checks_maps => [1],
bypass_virus_checks_maps => [1],

and now it is working, thanks Zhang

**ZhangHuangbin** · 2018-05-18 09:58:43

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

k-hussein wrote:

I have enabled those 2 lines in Originating policy bank:
bypass_spam_checks_maps => [1],
bypass_virus_checks_maps => [1],

With these 2 lines, Amavisd will bypass spam AND VIRUS checking for this policy bank, are you sure this is what you really want?

**k-hussein** · 2018-05-21 21:09:46

k-hussein
Member
Offline

Registered: 2014-12-11
Posts: 106

Re: SPAM in subject

am out of ideas why it keep considering the other domains mails as spam =/

**ZhangHuangbin** · 2018-05-22 10:17:44

ZhangHuangbin
iRedMail Developers
Offline

Registered: 2009-05-06
Posts: 31,094

Re: SPAM in subject

k-hussein wrote:

am out of ideas why it keep considering the other domains mails as spam =/

You need to check Amavisd log, it's mentioned:

May 7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: X-Spam-Score: 64\n
...
May 7 15:49:00 Exchange-P01 amavis[14573]: (14573-03) header: X-Spam-Status: Yes, score=x tagged_above=2 required=6.31 BLACKLISTED tests=[]\n\tautolearn=unavailable\n

Aug 5, 2024: iRedMail-1.7.1 has been released.

SPAM in subject

Posts: 19

1 Topic by k-hussein 2018-05-02 21:37:43

Topic: SPAM in subject

2 Reply by k-hussein 2018-05-02 23:03:33

Re: SPAM in subject

3 Reply by ZhangHuangbin 2018-05-03 22:54:20

Re: SPAM in subject

4 Reply by k-hussein 2018-05-04 03:14:35

Re: SPAM in subject

5 Reply by k-hussein 2018-05-04 05:20:56

Re: SPAM in subject

6 Reply by ZhangHuangbin 2018-05-04 22:31:01

Re: SPAM in subject

7 Reply by k-hussein 2018-05-05 03:43:43

Re: SPAM in subject

8 Reply by ZhangHuangbin 2018-05-05 15:04:11

Re: SPAM in subject

9 Reply by k-hussein 2018-05-06 17:30:41 (edited by k-hussein 2018-05-07 23:33:43)

Re: SPAM in subject

10 Reply by ZhangHuangbin 2018-05-08 10:50:46

Re: SPAM in subject

11 Reply by k-hussein 2018-05-08 21:38:22

Re: SPAM in subject

12 Reply by ZhangHuangbin 2018-05-10 08:07:27

Re: SPAM in subject

13 Reply by k-hussein 2018-05-11 01:09:05

Re: SPAM in subject

14 Reply by ZhangHuangbin 2018-05-13 11:51:52

Re: SPAM in subject

15 Reply by k-hussein 2018-05-14 21:34:39

Re: SPAM in subject

16 Reply by k-hussein 2018-05-15 00:38:50

Re: SPAM in subject

17 Reply by ZhangHuangbin 2018-05-18 09:58:43

Re: SPAM in subject

18 Reply by k-hussein 2018-05-21 21:09:46

Re: SPAM in subject

19 Reply by ZhangHuangbin 2018-05-22 10:17:44

Re: SPAM in subject

Posts: 19