First incoming email often refused

Discussion in 'Server Operation' started by MP Loots, May 3, 2021.

  1. MP Loots

    MP Loots New Member

    Hi. One particular user complains about missing emails. I had a look into it and found a specific line in the logs:

    ... postfix/cleanup[14324]: D4F5433CD61: discard: header ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; ...

    If the sender retries, it mostly does not appear in that second delivery attempt; instead, it flows through amavis, dovecot and gets delivered.

    Most email is delivered without issue, but this happens a view times on a weekly basis - roughly with about 5% of the specific sender's emails gets lost first time. It does not feel trustworthy, that's the biggest issue.

    Anyone that knows how i can relax postfix or make sure this sender's domain is treated as trusted source? (it's an office365 customer with own domain, so this probably comes up more often than I know of at the moment)

    Thanks,
    Martijn
     
  2. Jesse Norell

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    That is not normal behavior, what customizations have you made? Post your main.cf (in code tags)
     
  3. Jesse Norell

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    Also, can you post the full set of logs from one such delivery attempt?
     
  4. MP Loots

    MP Loots New Member

    Hi Jesse. Appreciate your response very much.
    I need to anonimize the log example, I'll post it later.
    Here the main.cf:
    Code:
    # See /usr/share/postfix/main.cf.dist for a commented, more complete version
    
    
    # Debian specific:  Specifying a file name will cause the first
    # line of that file to be used as the name.  The Debian default
    # is /etc/mailname.
    #myorigin = /etc/mailname
    
    smtpd_banner = $myhostname ESMTP $mail_name (Ubuntu)
    biff = no
    
    # appending .domain is the MUA's job.
    append_dot_mydomain = no
    
    # Uncomment the next line to generate "delayed mail" warnings
    #delay_warning_time = 4h
    
    readme_directory = /usr/share/doc/postfix
    
    # See http://www.postfix.org/COMPATIBILITY_README.html -- default to 2 on
    # fresh installs.
    compatibility_level = 2
    
    # TLS parameters
    smtpd_tls_cert_file = /etc/postfix/smtpd.cert
    smtpd_tls_key_file = /etc/postfix/smtpd.key
    smtpd_use_tls = yes
    smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
    smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
    
    # See /usr/share/doc/postfix/TLS_README.gz in the postfix-doc package for
    # information on enabling SSL in the smtp client.
    
    smtpd_relay_restrictions = permit_mynetworks permit_sasl_authenticated defer_unauth_destination
    myhostname = not.therealname.com
    alias_maps = hash:/etc/aliases, hash:/var/lib/mailman/data/aliases
    alias_database = hash:/etc/aliases, hash:/var/lib/mailman/data/aliases
    myorigin = /etc/mailname
    mydestination = not.therealname.com, localhost, localhost.localdomain
    relayhost =
    #mynetworks = 127.0.0.0/8 [::1]/128
    mynetworks = 127.0.0.0/8
    mailbox_size_limit = 0
    recipient_delimiter = +
    inet_interfaces = all
    inet_protocols = ipv4
    html_directory = /usr/share/doc/postfix/html
    virtual_alias_domains =
    virtual_alias_maps = hash:/var/lib/mailman/data/virtual-mailman, proxy:mysql:/etc/postfix/mysql-virtual_forwardings.cf, proxy:mysql:/etc/postfix/mysql-virtual_email2email.cf
    virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql-virtual_domains.cf
    virtual_mailbox_maps = proxy:mysql:/etc/postfix/mysql-virtual_mailboxes.cf
    virtual_mailbox_base = /var/vmail
    virtual_uid_maps = mysql:/etc/postfix/mysql-virtual_uids.cf
    virtual_gid_maps = mysql:/etc/postfix/mysql-virtual_gids.cf
    sender_bcc_maps = proxy:mysql:/etc/postfix/mysql-virtual_outgoing_bcc.cf
    smtpd_sasl_auth_enable = yes
    broken_sasl_auth_clients = yes
    smtpd_sasl_authenticated_header = yes
    smtpd_restriction_classes = greylisting
    greylisting = check_policy_service inet:127.0.0.1:10023
    smtpd_recipient_restrictions = permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination, reject_invalid_hostname, reject_non_fqdn_hostname, reject_unknown_recipient_domain, reject_non_fqdn_recipient, reject_non_fqdn_sender, reject_unknown_sender_domain, reject_unknown_recipient_domain, reject_rbl_client zen.spamhaus.org, reject_rbl_client bl.spamcop.net, check_recipient_access mysql:/etc/postfix/mysql-virtual_recipient.cf, check_recipient_access mysql:/etc/postfix/mysql-virtual_policy_greylist.cf
    smtpd_tls_security_level = may
    transport_maps = hash:/var/lib/mailman/data/transport-mailman, proxy:mysql:/etc/postfix/mysql-virtual_transports.cf
    relay_domains = mysql:/etc/postfix/mysql-virtual_relaydomains.cf
    relay_recipient_maps = mysql:/etc/postfix/mysql-virtual_relayrecipientmaps.cf
    smtpd_sender_login_maps = proxy:mysql:/etc/postfix/mysql-virtual_sender_login_maps.cf
    proxy_read_maps = $local_recipient_maps $mydestination $virtual_alias_maps $virtual_alias_domains $sender_bcc_maps $virtual_mailbox_maps $virtual_mailbox_domains $relay_recipient_maps $relay_domains $canonical_maps $sender_canonical_maps $recipient_canonical_maps $relocated_maps $transport_maps $mynetworks $smtpd_sender_login_maps
    smtpd_helo_required = yes
    smtpd_helo_restrictions = permit_sasl_authenticated, permit_mynetworks, check_helo_access regexp:/etc/postfix/helo_access, reject_invalid_hostname, reject_non_fqdn_hostname, reject_invalid_helo_hostname, reject_unknown_helo_hostname, check_helo_access regexp:/etc/postfix/blacklist_helo
    smtpd_sender_restrictions = check_sender_access mysql:/etc/postfix/mysql-virtual_sender.cf regexp:/etc/postfix/tag_as_originating.re, permit_mynetworks, permit_sasl_authenticated, check_sender_access regexp:/etc/postfix/tag_as_foreign.re
    smtpd_client_restrictions = check_client_access mysql:/etc/postfix/mysql-virtual_client.cf
    smtpd_client_message_rate_limit = 100
    maildrop_destination_concurrency_limit = 1
    maildrop_destination_recipient_limit = 1
    virtual_transport = dovecot
    header_checks = regexp:/etc/postfix/header_checks
    mime_header_checks = regexp:/etc/postfix/mime_header_checks
    nested_header_checks = regexp:/etc/postfix/nested_header_checks
    body_checks = regexp:/etc/postfix/body_checks
    owner_request_special = no
    smtp_tls_security_level = may
    smtpd_tls_mandatory_protocols = !SSLv2, !SSLv3
    smtpd_tls_protocols = !SSLv2,!SSLv3
    smtp_tls_protocols = !SSLv2,!SSLv3
    smtpd_tls_exclude_ciphers = RC4, aNULL
    smtp_tls_exclude_ciphers = RC4, aNULL
    dovecot_destination_recipient_limit = 1
    smtpd_sasl_type = dovecot
    smtpd_sasl_path = private/auth
    content_filter = amavis:[127.0.0.1]:10024
    receive_override_options = no_address_mappings
    message_size_limit = 0
    
     
  5. MP Loots

    MP Loots New Member

    Anonimized example first try:
    Code:
    May  3 13:44:54 anonhost postfix/smtpd[12481]: connect from mail-eopbgr20040.outbound.protection.outlook.com[40.107.2.40]
    May  3 13:44:54 anonhost postfix/smtpd[12481]: NOQUEUE: filter: RCPT from mail-eopbgr20040.outbound.protection.outlook.com[40.107.2.40]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10026; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<EUR02-VE1-obe.outbound.protection.outlook.com>
    May  3 13:44:54 anonhost postfix/smtpd[12481]: NOQUEUE: filter: RCPT from mail-eopbgr20040.outbound.protection.outlook.com[40.107.2.40]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10024; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<EUR02-VE1-obe.outbound.protection.outlook.com>
    May  3 13:44:54 anonhost postfix/smtpd[12481]: D4F5433CD61: client=mail-eopbgr20040.outbound.protection.outlook.com[40.107.2.40]
    May  3 13:44:54 anonhost postfix/cleanup[14324]: D4F5433CD61: discard: header ARC-Seal: i=1; a=rsa-sha256; s=arcselector9901; d=microsoft.com; cv=none;? b=Nk6q2Krwjvc+6N9knViZmITQeSuR4KgXb9N2qQlNnIHxA0ePg5gvTt4o9v0PAIYTaJ6IlmBej34UZAYn287rF2ubrqRzyJ211p+v9OpLuyv7017gYC5PZIO9uei from mail-eopbgr20040.outbound.protection.outlook.com[40.107.2.40]; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<EUR02-VE1-obe.outbound.protection.outlook.com>
    May  3 13:44:55 anonhost postfix/smtpd[12481]: disconnect from mail-eopbgr20040.outbound.protection.outlook.com[40.107.2.40] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
    
     
  6. MP Loots

    MP Loots New Member

    Anonimized example second try + delivery to 2nd recipient (sender tries to make sure it gets delivered...). I could not send the full log, beacsue of all debug statements - too large for the forum:
    Code:
    May  3 14:33:33 anonhost postfix/smtpd[17674]: connect from mail-eopbgr30071.outbound.protection.outlook.com[40.107.3.71]
    May  3 14:33:33 anonhost postfix/smtpd[17674]: NOQUEUE: filter: RCPT from mail-eopbgr30071.outbound.protection.outlook.com[40.107.3.71]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10026; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<EUR03-AM5-obe.outbound.protection.outlook.com>
    May  3 14:33:33 anonhost postfix/smtpd[17674]: NOQUEUE: filter: RCPT from mail-eopbgr30071.outbound.protection.outlook.com[40.107.3.71]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10024; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<EUR03-AM5-obe.outbound.protection.outlook.com>
    May  3 14:33:33 anonhost postfix/smtpd[17674]: C04D8604320: client=mail-eopbgr30071.outbound.protection.outlook.com[40.107.3.71]
    May  3 14:33:33 anonhost postfix/smtpd[17674]: C04D8604320: filter: RCPT from mail-eopbgr30071.outbound.protection.outlook.com[40.107.3.71]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10026; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<EUR03-AM5-obe.outbound.protection.outlook.com>
    May  3 14:33:33 anonhost postfix/smtpd[17674]: C04D8604320: filter: RCPT from mail-eopbgr30071.outbound.protection.outlook.com[40.107.3.71]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10024; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<EUR03-AM5-obe.outbound.protection.outlook.com>
    May  3 14:33:33 anonhost postfix/cleanup[17647]: C04D8604320: message-id=<AM0PR06MB65612AB3A4339109547624F0F55B9@AM0PR06MB6561.eurprd06.prod.outlook.com>
    May  3 14:33:33 anonhost postfix/qmgr[818]: C04D8604320: from=<[email protected]>, size=132559, nrcpt=2 (queue active)
    May  3 14:33:33 anonhost amavis[17716]: Net::Server: 2021/05/03-14:33:33 CONNECT TCP Peer: "[127.0.0.1]:40720" Local: "[127.0.0.1]:10024"
    May  3 14:33:33 anonhost amavis[17716]: loaded base policy bank
    May  3 14:33:33 anonhost amavis[17716]: lookup_ip_acl (inet_acl) arr.obj: key="127.0.0.1" matches "127.0.0.1", result=1
    May  3 14:33:33 anonhost amavis[17716]: process_request: fileno sock=15, STDIN=0, STDOUT=1
    May  3 14:33:33 anonhost amavis[17716]: get_deadline switch_to_my_time(new request) - deadline in 480.0 s, set to 288.000 s
    May  3 14:33:33 anonhost amavis[17716]: prolong_timer switch_to_my_time(new request): timer 288, was 0, deadline in 480.0 s
    May  3 14:33:33 anonhost amavis[17716]: process_request: suggested_protocol="" on a TCP socket
    May  3 14:33:33 anonhost postfix/smtpd[17674]: disconnect from mail-eopbgr30071.outbound.protection.outlook.com[40.107.3.71] ehlo=2 starttls=1 mail=1 rcpt=2 data=1 quit=1 commands=8
    May  3 14:33:36 anonhost postfix/smtpd[17771]: connect from localhost[127.0.0.1]
    May  3 14:33:36 anonhost postfix/smtpd[17771]: 77E47604481: client=localhost[127.0.0.1]
    May  3 14:33:36 anonhost postfix/cleanup[17384]: 77E47604481: message-id=<AM0PR06MB65612AB3A4339109547624F0F55B9@AM0PR06MB6561.eurprd06.prod.outlook.com>
    May  3 14:33:36 anonhost postfix/qmgr[818]: 77E47604481: from=<[email protected]>, size=133058, nrcpt=2 (queue active)
    May  3 14:33:36 anonhost postfix/smtp[17710]: C04D8604320: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.8, delays=0.14/0/0.01/2.7, 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 77E47604481)
    May  3 14:33:36 anonhost postfix/smtp[17710]: C04D8604320: to=<[email protected]>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.8, delays=0.14/0/0.01/2.7, 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 77E47604481)
    May  3 14:33:36 anonhost postfix/qmgr[818]: C04D8604320: removed
    May  3 14:33:36 anonhost dovecot: lda([email protected]): sieve: msgid=? <AM0PR06MB65612AB3A4339109547624F0F55B9@AM0PR06MB6561.eurprd06.prod.outlook.com>: stored mail into mailbox 'INBOX'
    May  3 14:33:36 anonhost postfix/pipe[17775]: 77E47604481: to=<[email protected]>, relay=dovecot, delay=0.07, delays=0.02/0.01/0/0.04, dsn=2.0.0, status=sent (delivered via dovecot service (doveconf: Warning: /etc/dovecot/dovecot.conf line 71: Global setting mail_plugins won't change the s))
    May  3 14:33:36 anonhost dovecot: lda([email protected]): sieve: msgid=? <AM0PR06MB65612AB3A4339109547624F0F55B9@AM0PR06MB6561.eurprd06.prod.outlook.com>: stored mail into mailbox 'INBOX'
    May  3 14:33:36 anonhost postfix/pipe[17776]: 77E47604481: to=<[email protected]>, relay=dovecot, delay=0.07, delays=0.02/0.01/0/0.04, dsn=2.0.0, status=sent (delivered via dovecot service (doveconf: Warning: /etc/dovecot/dovecot.conf line 71: Global setting mail_plugins won't change the s))
    May  3 14:33:36 anonhost postfix/qmgr[818]: 77E47604481: removed
    May  3 16:33:37 anonhost amavis[17716]: (17716-18) ip_from_received: no IP address in:  from DB9PR02CA0017.eurprd02.prod.outlook.com (2603:10a6:10:1d9::22)\n by VE1P192MB0720.EURP192.PROD.OUTLOOK.COM (2603:10a6:800:14b::7) with\n Microsoft SMTP Server (version=TLS1_2,\n cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.4087.35; Mon, 3 May\n 2021 14:33:34 +0000\n
    May  3 16:33:37 anonhost amavis[17716]: (17716-18) ip_from_received: no IP address in:  from DB5EUR01FT032.eop-EUR01.prod.protection.outlook.com\n (2603:10a6:10:1d9:cafe::9f) by DB9PR02CA0017.outlook.office365.com\n (2603:10a6:10:1d9::22) with Microsoft SMTP Server (version=TLS1_2,\n cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id 15.20.4087.27 via Frontend\n Transport; Mon, 3 May 2021 14:33:34 +0000\n
    
     
  7. Steini86

    Steini86 Active Member

    If your client is using his own domain, has he correctly configured SPF? https://o365info.com/how-to-manage-spf-record-in-an-office-365-based-environment/

    Discard is bad, because it silently drops the mail. As I understand the log file, its discarded because of a header check. What is the content of the files:
    /etc/postfix/header_checks
    /etc/postfix/mime_header_checks
    /etc/postfix/nested_header_checks

    By the way: Your main.cf looks like a mess. How do you maintain that? Might be a good time to use the new ISPC way of overwriting the postfix config: https://www.howtoforge.com/communit...-for-custom-postfix-and-dovecot-config.86559/
    Then you can go through every line of your config and see if you still need it (do you need IPv4 only? Do you really need TLS1.0/TLS1.1? Do you really want not.therealname.com in mydestination? etc pp ...)
     
  8. MP Loots

    MP Loots New Member

    Hiya Stein. Thanks for the reply. As for the ISPC postfig config tool, I first need to upgrade ISPconfig I think and I'm a bit hesitant to do that on a production system... I'm on 3.1.15p3 at the moment.

    The main.conf is controlled by ISPconfig; I don't touch it myself. By the way "not.therealname.com" is, as the term says, in actuality the FQDN of my server... :)

    Below the header_checks file, the others were empty:
    Code:
    /^From: .*Mortgage|Concealed|Affiliate|Bathroom|Ukrain|Russia|TopRated|KN95/  DISCARD
    /^From: .*Be Sure|Dating|Hemp Oil|Debt|Associate|Shooting|Credit Score/  DISCARD
    /^From: .* Associate|Buy |Benefits|Settlement|Singles|HVAC|Overstock/  DISCARD
    /^From: .*Body Shape| Bill | Savings| Pain | Miracle | Health |Medicare/  DISCARD
    /^From: .*Thermo|Fever|Pressure|Cool Air|Lingo|Fast |Explore|[Bb]oost/  DISCARD
    /^From: .*Doorbell|Smartwatch|CoolAir|Drone|Ultra Wifi|BodyTone|Breathe/  DISCARD
    /^From: .*Asian|RentTo|Torch|Tactical|Diabet|DIY|Before/  DISCARD
    /^From: .* Fat |Killer|Gizmos|[Ss]hed |Warby|[Ww]ood|Remed/  DISCARD
    /^From: .*UltraWifi|Canvas|Prices|[Mm]odeling|Pest |Snoring|Remover|Fungus/  DISCARD
    
    I added these to ISPconfig because I had lots of spam issues.. Still have btw, need to find better ways.
     
  9. Steini86

    Steini86 Active Member

    Use rspamd agains spam: https://www.howtoforge.com/replacing-amavisd-with-rspamd-in-ispconfig/
    (Attention, can lead to some (new) false positives in the beginning, especially if your users get (valid) newsletters)

    From what I see, one of your header checks is responsible for the discarding of the message. But I don't know, why it works if the message is sent a second time :confused: Since you anonymized the FROM part, it is hard to tell which rule might have been applied.
    You could add an additional message for your log files, for example to see which line is responsible:
    See: http://www.postfix.org/header_checks.5.html
    For testing, you could use HOLD instead of DISCARD. So you will see the messages and have the option to delete or release it. Or you can use REJECT instead of DISCARD, so the sender will get a notification and you additional information for the logs.

    If you have a message that gets reproducibly discarded, you can also use one of the common debugging techniques:
    http://www.postfix.org/DEBUG_README.html
     
    Jesse Norell likes this.
  10. Jesse Norell

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    Your earlier logs show this was the rejected header:
    So if your header_checks only matches From: headers..... something doesn't add up. In any case, rejecting mail based on very short sequences of characters like that is quite prone to false positives (hence your issue here) and not recommended for most cases. Train your spam scanner and it'll catch a lot more of those; if you need to write custom rules, it would be better to write them in the language/config of your spam scanner than blocking in postfix.
     

Share This Page