1 Topic by chaz

  • chaz
  • Member
  • Offline
  • Registered: 2019-06-07
  • Posts: 37

Topic: Strange Greylisting Behaviour

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release):  0.9.9 OPENLDAP edition
- Deployed with iRedMail Easy or the downloadable installer? Installer
- Linux/BSD distribution name and version:  Debian 9.9
- Store mail accounts in which backend (LDAP/MySQL/PGSQL):  LDAP
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? No
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

I am experiencing a strange greylisting behaviour. The iredapd policy server result to greylist but the email still goes through without greylisting. See the iredapd log and postfix log entry below.

It seems to only happen with this client. This has happened several times.  Greylisting works on others.

Changes I've made:
1. Apply the fix for https://forum.iredmail.org/topic15836-p … sting.html
2. Turned off "throttle" plugin in /opt/iredapd/settings.py

postconf smtpd_recipient_restrictions
smtpd_recipient_restrictions = reject_non_fqdn_recipient reject_unlisted_recipient check_policy_service inet:127.0.0.1:7777 permit_mynetworks permit_sasl_authenticated reject_unauth_destination

iredapd log file

Jul 11 10:32:27 genesis iredapd DEBUG: [policy] request=smtpd_access_policy
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] protocol_state=RCPT
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] protocol_name=ESMTP
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] client_address=12.130.137.223
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] client_name=omp.bbbyemail.com
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] client_port=57472
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] reverse_client_name=omp.bbbyemail.com
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] helo_name=omp.bbbyemail.com
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] sender=BedBath&Beyond@emailbedbathandbeyond.com
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] recipient=dummy@mydomain.com
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] recipient_count=0
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] queue_id=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] instance=39fd.5d2772aa.d22d1.0
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] size=0
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] etrn_domain=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] stress=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] sasl_method=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] sasl_username=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] sasl_sender=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] ccert_subject=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] ccert_issuer=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] ccert_fingerprint=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] ccert_pubkey_fingerprint=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] encryption_protocol=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] encryption_cipher=
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] encryption_keysize=0
Jul 11 10:32:27 genesis iredapd DEBUG: [policy] policy_context=
Jul 11 10:32:27 genesis iredapd DEBUG: Sender domain is NOT hosted locally.
Jul 11 10:32:27 genesis iredapd DEBUG: Sender domain is not hosted locally, dunno.
Jul 11 10:32:27 genesis iredapd DEBUG: <-- Result: DUNNO
Jul 11 10:32:27 genesis iredapd DEBUG: --> Apply plugin: greylisting
Jul 11 10:32:27 genesis iredapd DEBUG: [SQL] Query greylisting whitelists from `greylisting_whitelist_domain_spf`: #012SELECT sender#012 FROM greylisting_whitelist_domain_spf#012 WHERE account IN ('dummy@mydomain.com', '@mydomain.com', '@.', '@.mydomain.com', '@.com')
Jul 11 10:32:27 genesis iredapd DEBUG: [SQL] Query greylisting whitelists from `greylisting_whitelists`: #012SELECT sender#012 FROM greylisting_whitelists#012 WHERE account IN ('dummy@mydomain.com', '@mydomain.com', '@.', '@.mydomain.com', '@.com')
Jul 11 10:32:27 genesis iredapd DEBUG: [12.130.137.223] Client is not explictly whitelisted.
Jul 11 10:32:27 genesis iredapd DEBUG: No whitelist found.
Jul 11 10:32:27 genesis iredapd DEBUG: [SQL] query greylisting settings: #012SELECT id, account, sender, sender_priority, active#012 FROM greylisting#012 WHERE account IN ('dummy@mydomain.com', '@mydomain.com', '@.', '@.mydomain.com', '@.com')#012 ORDER BY priority DESC, sender_priority DESC
Jul 11 10:32:27 genesis iredapd DEBUG: [SQL] query result: [(21L, '@.', '@.paypal.com', 50, 0), (27L, '@.', '@.groupon.com', 50, 0), (29L, '@.', '@.livingsocial.com', 50, 0), (11L, '@.', '@.', 0, 1)]
Jul 11 10:32:27 genesis iredapd DEBUG: Greylisting should be applied according to SQL record: (id=11, account='@.', sender='@.')
Jul 11 10:32:27 genesis iredapd DEBUG: [SQL] check whether client address (12.130.137.223) passed greylisting: #012SELECT id#012 FROM greylisting_tracking#012 WHERE client_address='12.130.137.223'#012 AND passed=1#012 LIMIT 1
Jul 11 10:32:27 genesis iredapd DEBUG: Client address (12.130.137.223) didn't pass greylisting.
Jul 11 10:32:27 genesis iredapd DEBUG: [SQL] query greylisting tracking: #012SELECT init_time, blocked_count, block_expired, record_expired#012               FROM greylisting_tracking#012 WHERE sender='bedbath&beyond@emailbedbathandbeyond.com'#012 AND recipient='dummy@mydomain.com'#012 AND client_address='12.130.137.223'#012 LIMIT 1
Jul 11 10:32:27 genesis iredapd INFO: [12.130.137.223] Client has not been seen before, greylisted.
Jul 11 10:32:27 genesis iredapd DEBUG: [SQL] New tracking: #012INSERT INTO greylisting_tracking (sender, sender_domain,#012                                                   recipient, rcpt_domain,#012 client_address,#012 init_time,#012 block_expired, record_expired,#012 blocked_count)#012 VALUES ('bedbath&beyond@emailbedbathandbeyond.com', 'emailbedbathandbeyond.com', 'dummy@mydomain.com', 'mydomain.com', '12.130.137.223', 1562866347, 1562866527, 1562952747, 1)
Jul 11 10:32:27 genesis iredapd DEBUG: <-- Result: 451 4.7.1 Resource temporarily unavailable, please try again later
Jul 11 10:32:27 genesis iredapd DEBUG: Session ended.
Jul 11 10:32:27 genesis iredapd INFO: [12.130.137.223] RCPT, bedbath&beyond@emailbedbathandbeyond.com -> dummy@mydomain.com, 451 4.7.1 Resource temporarily unavailable, please try again later  [sasl_username=, sender=bedbath&beyond@emailbedbathandbeyond.com, client_name=omp.bbbyemail.com, reverse_client_name=omp.bbbyemail.com, helo=omp.bbbyemail.com, encryption_protocol=, process_time=0.0264s]
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] request=smtpd_access_policy
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] protocol_state=END-OF-MESSAGE
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] protocol_name=ESMTP
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] client_address=12.130.137.223
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] client_name=omp.bbbyemail.com
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] client_port=57472
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] reverse_client_name=omp.bbbyemail.com
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] helo_name=omp.bbbyemail.com
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] sender=BedBath&Beyond@emailbedbathandbeyond.com
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] recipient=dummy@mydomain.com
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] recipient_count=1
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] queue_id=45l3630v77z5xWs
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] instance=39fd.5d2772aa.d22d1.0
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] size=114883
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] etrn_domain=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] stress=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] sasl_method=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] sasl_username=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] sasl_sender=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] ccert_subject=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] ccert_issuer=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] ccert_fingerprint=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] ccert_pubkey_fingerprint=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] encryption_protocol=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] encryption_cipher=
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] encryption_keysize=0
Jul 11 10:32:28 genesis iredapd DEBUG: [policy] policy_context=
Jul 11 10:32:28 genesis iredapd DEBUG: Skip plugin: reject_null_sender (protocol_state != END-OF-MESSAGE)
Jul 11 10:32:28 genesis iredapd DEBUG: Skip plugin: wblist_rdns (protocol_state != END-OF-MESSAGE)
Jul 11 10:32:28 genesis iredapd DEBUG: Skip plugin: reject_sender_login_mismatch (protocol_state != END-OF-MESSAGE)
Jul 11 10:32:28 genesis iredapd DEBUG: Skip plugin: greylisting (protocol_state != END-OF-MESSAGE)
Jul 11 10:32:28 genesis iredapd DEBUG: Skip plugin: ldap_maillist_access_policy (protocol_state != END-OF-MESSAGE)
Jul 11 10:32:28 genesis iredapd DEBUG: Skip plugin: amavisd_wblist (protocol_state != END-OF-MESSAGE)
Jul 11 10:32:28 genesis iredapd DEBUG: --> Apply plugin: whitelist_outbound_recipient
Jul 11 10:32:28 genesis iredapd DEBUG: No sasl_username found, skip.
Jul 11 10:32:28 genesis iredapd DEBUG: <-- Result: DUNNO
Jul 11 10:32:28 genesis iredapd DEBUG: Session ended.

Postfix Log

Jul 11 10:32:26 genesis postfix/smtpd[14845]: connect from omp.bbbyemail.com[12.130.137.223]
Jul 11 10:32:27 genesis postfix/smtpd[14845]: 45l3630v77z5xWs: client=omp.bbbyemail.com[12.130.137.223]
Jul 11 10:32:27 genesis postfix/cleanup[14849]: 45l3630v77z5xWs: message-id=<0.1.3F.EFD.1D5380E9AF5F39A.0@omp.bbbyemail.com>
Jul 11 10:32:28 genesis postfix/qmgr[1556]: 45l3630v77z5xWs: from=<BedBath&Beyond@emailbedbathandbeyond.com>, size=115084, nrcpt=1 (queue active)
Jul 11 10:32:28 genesis postfix/smtpd[14845]: disconnect from omp.bbbyemail.com[12.130.137.223] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jul 11 10:32:30 genesis postfix/10025/smtpd[14853]: connect from localhost[127.0.0.1]
Jul 11 10:32:30 genesis postfix/10025/smtpd[14853]: 45l3663D5Lz5xWt: client=localhost[127.0.0.1]
Jul 11 10:32:30 genesis postfix/cleanup[14849]: 45l3663D5Lz5xWt: message-id=<0.1.3F.EFD.1D5380E9AF5F39A.0@omp.bbbyemail.com>
Jul 11 10:32:30 genesis postfix/10025/smtpd[14853]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jul 11 10:32:30 genesis postfix/qmgr[1556]: 45l3663D5Lz5xWt: from=<BedBath&Beyond@emailbedbathandbeyond.com>, size=116240, nrcpt=1 (queue active)
Jul 11 10:32:30 genesis amavis[11255]: (11255-08) Passed CLEAN {RelayedInbound}, [12.130.137.223]:57472 [12.130.137.223] <BedBath&Beyond@emailbedbathandbeyond.com> -> <dummy@mydomain.com>, Queue-ID: 45l3630v77z5xWs, Message-ID: <0.1.3F.EFD.1D5380E9AF5F39A.0@omp.bbbyemail.com>, mail_id: cTifx0bichZu, Hits: -20.597, size: 115082, queued_as: 45l3663D5Lz5xWt, dkim_sd=emailbedbathandbeyondcom:emailbedbathandbeyond.com, 2236 ms, Tests [DKIMWL_WL_HIGH=-0.001,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,DKIM_VALID_EF=-0.1,ENV_AND_HDR_SPF_MATCH=-0.5,FROM_EXCESS_BASE64=0.001,HTML_FONT_LOW_CONTRAST=0.001,HTML_IMAGE_RATIO_02=0.001,HTML_MESSAGE=0.001,MIME_HTML_ONLY=0.1,RCVD_IN_DNSWL_NONE=-0.0001,RCVD_IN_RP_CERTIFIED=-3,RCVD_IN_RP_SAFE=-2,SPF_HELO_NONE=0.001,SPF_PASS=-0.001,USER_IN_DEF_DKIM_WL=-7.5,USER_IN_DEF_SPF_WL=-7.5]
Jul 11 10:32:30 genesis postfix/amavis/smtp[14850]: 45l3630v77z5xWs: to=<dummy@mydomain.com>, relay=1
27.0.0.1[127.0.0.1]:10024, delay=3.6, delays=1.4/0.01/0/2.2, 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 45l3663D5Lz5xWt)
Jul 11 10:32:30 genesis postfix/qmgr[1556]: 45l3630v77z5xWs: removed

----

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

2 Reply by KNERD

  • KNERD
  • Member
  • Offline
  • Registered: 2019-01-25
  • Posts: 63

Re: Strange Greylisting Behaviour

It seems the greylisting functions has issues so I just disabled it. If you really do not want mail coming in, just black list it

3 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,770

Re: Strange Greylisting Behaviour

chaz wrote:

Jul 11 10:32:27 genesis iredapd DEBUG: <-- Result: 451 4.7.1 Resource temporarily unavailable, please try again later

Greylisting plugin correctly returned smtp code "451 4.7.1". I see you changed the rejection text to "Resource temporarily unavailable".

The result seems fine, i don't understand why Postfix didn't reject it temporarily. Did you change ANY iRedAPD settings in /opt/iredapd/settings.py?

4 Reply by chaz

  • chaz
  • Member
  • Offline
  • Registered: 2019-06-07
  • Posts: 37

Re: Strange Greylisting Behaviour

Mr Zhang,

Yes I changed the rejection text. My /opt/iredapd/setting.py I removed the "throttle" plugin and added the "whitelist_outbound_recipient" plugin.

plugins = ["reject_null_sender", "wblist_rdns", "reject_sender_login_mismatch", "greylisting", "amavisd_wblist", "ldap_maillist_access_policy", "whitelist_outbound_recipient"]

With the exception of the sender and client, greylisting is working. I am not sure why Postfix is not rejecting it. I think I'll turn on Postfix debug next to see what is happening.

Here is another iredapd and Postfix log for the same sender different client address. The iredapd.log is missing a bunch of debug.

iredapd log

Jul 13 03:45:36 genesis iredapd DEBUG: [policy] request=smtpd_access_policy
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] protocol_state=RCPT
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] protocol_name=ESMTP
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] client_address=12.130.137.190
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] client_name=omp.bbbyemail.com
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] client_port=55953
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] reverse_client_name=omp.bbbyemail.com
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] helo_name=omp.bbbyemail.com
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] sender=BedBath&Beyond@emailbedbathandbeyond.com
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] recipient=dummy@mydomain.com
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] recipient_count=0
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] queue_id=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] instance=2a74.5d29b650.7c187.0
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] size=0
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] etrn_domain=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] stress=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] sasl_method=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] sasl_username=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] sasl_sender=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] ccert_subject=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] ccert_issuer=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] ccert_fingerprint=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] ccert_pubkey_fingerprint=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] encryption_protocol=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] encryption_cipher=
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] encryption_keysize=0
Jul 13 03:45:36 genesis iredapd DEBUG: [policy] policy_context=
Jul 13 03:45:36 genesis iredapd DEBUG: Session ended.
Jul 13 03:45:36 genesis iredapd INFO: [12.130.137.190] RCPT, bedbath&beyond@emailbedbathandbeyond.com -> dummy@mydomain.com, 451 4.7.1 Resource temporarily unavailable, please try again later  [sasl_username=, sender=bedbath&beyond@emailbedbathandbeyond.com, client_name=omp.bbbyemail.com, reverse_client_name=omp.bbbyemail.com, helo=omp.bbbyemail.com, encryption_protocol=, process_time=0.0170s]
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] request=smtpd_access_policy
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] protocol_state=END-OF-MESSAGE
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] request=smtpd_access_policy
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] protocol_state=END-OF-MESSAGE
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] protocol_name=ESMTP
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] client_address=12.130.137.190
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] client_name=omp.bbbyemail.com
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] client_port=55953
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] reverse_client_name=omp.bbbyemail.com
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] helo_name=omp.bbbyemail.com
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] sender=BedBath&Beyond@emailbedbathandbeyond.com
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] recipient=dummy@mydomain.com
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] recipient_count=1
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] queue_id=45m5zh5B5Cz5xTK
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] instance=2a74.5d29b650.7c187.0
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] size=212158
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] etrn_domain=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] stress=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] sasl_method=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] sasl_username=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] sasl_sender=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] ccert_subject=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] ccert_issuer=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] ccert_fingerprint=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] ccert_pubkey_fingerprint=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] encryption_protocol=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] encryption_cipher=
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] encryption_keysize=0
Jul 13 03:45:37 genesis iredapd DEBUG: [policy] policy_context=
Jul 13 03:45:37 genesis iredapd DEBUG: Skip plugin: reject_null_sender (protocol_state != END-OF-MESSAGE)
Jul 13 03:45:37 genesis iredapd DEBUG: Skip plugin: wblist_rdns (protocol_state != END-OF-MESSAGE)
Jul 13 03:45:37 genesis iredapd DEBUG: Skip plugin: reject_sender_login_mismatch (protocol_state !=END-OF-MESSAGE)
Jul 13 03:45:37 genesis iredapd DEBUG: Skip plugin: greylisting (protocol_state != END-OF-MESSAGE)
Jul 13 03:45:37 genesis iredapd DEBUG: Skip plugin: ldap_maillist_access_policy (protocol_state != END-OF-MESSAGE)
Jul 13 03:45:37 genesis iredapd DEBUG: Skip plugin: amavisd_wblist (protocol_state != END-OF-MESSAGE)
Jul 13 03:45:37 genesis iredapd DEBUG: --> Apply plugin: whitelist_outbound_recipient
Jul 13 03:45:37 genesis iredapd DEBUG: No sasl_username found, skip.
Jul 13 03:45:37 genesis iredapd DEBUG: <-- Result: DUNNO
Jul 13 03:45:37 genesis iredapd DEBUG: Session ended.
Jul 13 03:45:37 genesis iredapd INFO: [12.130.137.190] END-OF-MESSAGE, bedbath&beyond@emailbedbathandbeyond.com -> dummy@mydomain.com, DUNNO [recipient_count=1, size=212158, process_time=0.0017s]


Postfix Log

Jul 13 03:45:36 genesis postfix/smtpd[10868]: connect from omp.bbbyemail.com[12.130.137.190]
Jul 13 03:45:36 genesis postfix/cleanup[10872]: 45m5zh5B5Cz5xTK: message-id=<0.1.3.D69.1D5396818CE0488.0@omp.bbbyemail.com>
Jul 13 03:45:37 genesis postfix/qmgr[1556]: 45m5zh5B5Cz5xTK: from=<BedBath&Beyond@emailbedbathandbeyond.com>, size=212359, nrcpt=1 (queue active)
Jul 13 03:45:37 genesis postfix/smtpd[10868]: disconnect from omp.bbbyemail.com[12.130.137.190] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jul 13 03:45:38 genesis postfix/10025/smtpd[10876]: connect from localhost[127.0.0.1]
Jul 13 03:45:38 genesis postfix/10025/smtpd[10876]: 45m5zk6gmfz5xTf: client=localhost[127.0.0.1]
Jul 13 03:45:38 genesis postfix/cleanup[10872]: 45m5zk6gmfz5xTf: message-id=<0.1.3.D69.1D5396818CE0488.0@omp.bbbyemail.com>
Jul 13 03:45:39 genesis postfix/10025/smtpd[10876]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Jul 13 03:45:39 genesis postfix/qmgr[1556]: 45m5zk6gmfz5xTf: from=<BedBath&Beyond@emailbedbathandbeyond.com>, size=213515, nrcpt=1 (queue active)
Jul 13 03:45:39 genesis amavis[28068]: (28068-11) Passed CLEAN {RelayedInbound}, [12.130.137.190]:55
953 [12.130.137.190] <BedBath&Beyond@emailbedbathandbeyond.com> -> <dummy@mydomain.com>, Queue-ID: 45m5zh5B5Cz5xTK, Message-ID: <0.1.3.D69.1D5396818CE0488.0@omp.bbbyemail.com>, mail_id: 18NiMdzvvAoC, Hits: -20.597, size: 212357, queued_as: 45m5zk6gmfz5xTf, dkim_sd=emailbedbathandbeyondcom:emailbedbathandbeyond.com, 1146 ms, Tests [DKIMWL_WL_HIGH=-0.001,DKIM_SIGNED=0.1,DKIM_VALID=-0.1,DKIM_VALID_AU=-0.1,DKIM_VALID_EF=-0.1,ENV_AND_HDR_SPF_MATCH=-0.5,FROM_EXCESS_BASE64=0.001,HTML_FONT_LOW_CONTRAST=0.001,HTML_IMAGE_RATIO_02=0.001,HTML_MESSAGE=0.001,MIME_HTML_ONLY=0.1,RCVD_IN_DNSWL_NONE=-0.0001,RCVD_IN_RP_CERTIFIED=-3,RCVD_IN_RP_SAFE=-2,SPF_HELO_NONE=0.001,SPF_PASS=-0.001,USER_IN_DEF_DKIM_WL=-7.5,USER_IN_DEF_SPF_WL=-7.5]
Jul 13 03:45:39 genesis postfix/amavis/smtp[10873]: 45m5zh5B5Cz5xTK: to=<dummy@mydomain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.5, delays=1.3/0.01/0/1.2, 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 45m5zk6gmfz5xTf)
Jul 13 03:45:39 genesis postfix/qmgr[1556]: 45m5zh5B5Cz5xTK: removed

5 Reply by chaz

  • chaz
  • Member
  • Offline
  • Registered: 2019-06-07
  • Posts: 37

Re: Strange Greylisting Behaviour

I think I found the issue. When it did the policy check at smtpd_recipient_restrictions and smtp_end_of_data_restrictions, see logs below, it returned

"DUNNO Error: Invalid sender address: bedbath&beyond@emailbedbathandbeyond.com"

I notice there is a "&" in the address. Is that the cause of the problem?

Per the iredapd log below, it should have been rejected, but it didn't. The email got through away and as you can see from the iredapd.greylisting_tracking DB the passed = 0.

I have the full postfix log if you need that. Let me know.

iredapd Log

Jul 14 10:28:55 genesis iredapd INFO: [12.130.137.150] Client has not been seen before, greylisted.
Jul 14 10:28:55 genesis iredapd INFO: [12.130.137.150] RCPT, bedbath&beyond@emailbedbathandbeyond.com -> dummy@mydomain.com, 451 4.7.1 Resource temporarily unavailable, please try again later  [sasl_username=, sender=bedbath&beyond@emailbedbathandbeyond.com, client_name=omp.bbbyemail.com, reverse_client_name=omp.bbbyemail.com, helo=omp.bbbyemail.com, encryption_protocol=, process_time=0.0188s]
Jul 14 10:28:56 genesis iredapd INFO: [12.130.137.150] END-OF-MESSAGE, bedbath&beyond@emailbedbathandbeyond.com -> dummy@mydomain.com, DUNNO [recipient_count=1, size=167809, process_time=0.0004s]

MariaDB [(none)]> select * from iredapd.greylisting_tracking where sender_domain = 'emailbedbathandbeyond.com'\G
*************************** 1. row ***************************
            id: 973
        sender: bedbath&beyond@emailbedbathandbeyond.com
     recipient: dummy@mydomain.com
client_address: 12.130.137.150
sender_domain: emailbedbathandbeyond.com
   rcpt_domain: mydomain.com
     init_time: 1563125335
block_expired: 1563125515
record_expired: 1563211735
blocked_count: 1
        passed: 0
1 row in set (0.00 sec)

Partial Postfix Log

Jul 14 10:28:55 genesis postfix/smtpd[2332]: generic_checks: name=check_policy_service
Jul 14 10:28:55 genesis postfix/smtpd[2332]: trying... [127.0.0.1]
Jul 14 10:28:55 genesis postfix/smtpd[2332]: auto_clnt_open: connected to 127.0.0.1:7777
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr request = smtpd_access_policy
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr protocol_state = RCPT
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr protocol_name = ESMTP
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr client_address = 12.130.137.150
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr client_name = omp.bbbyemail.com
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr client_port = 36016
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr reverse_client_name = omp.bbbyemail.com
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr helo_name = omp.bbbyemail.com
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr sender = BedBath&Beyond@emailbedbathandbeyond.com
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr recipient = dummy@mydomain.com
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr recipient_count = 0
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr queue_id =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr instance = 91c.5d2b6657.68304.0
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr size = 0
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr etrn_domain =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr stress =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr sasl_method =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr sasl_username =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr sasl_sender =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr ccert_subject =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr ccert_issuer =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr ccert_fingerprint =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr ccert_pubkey_fingerprint =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr encryption_protocol =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr encryption_cipher =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr encryption_keysize = 0
Jul 14 10:28:55 genesis postfix/smtpd[2332]: send attr policy_context =
Jul 14 10:28:55 genesis postfix/smtpd[2332]: 127.0.0.1:7777: wanted attribute: action
Jul 14 10:28:55 genesis postfix/smtpd[2332]: input attribute name: action
Jul 14 10:28:55 genesis postfix/smtpd[2332]: input attribute value: DUNNO Error: Invalid sender address: bedbath&beyond@emailbedbathandbeyond.com
Jul 14 10:28:55 genesis postfix/smtpd[2332]: 127.0.0.1:7777: wanted attribute: (list terminator)
Jul 14 10:28:55 genesis postfix/smtpd[2332]: input attribute name: (end)
Jul 14 10:28:55 genesis postfix/smtpd[2332]: check_table_result: inet:127.0.0.1:7777 DUNNO Error: Invalid sender address: bedbath&beyond@emailbedbathandbeyond.com policy query
.
.
.
Jul 14 10:28:55 genesis postfix/smtpd[2332]: >>> START End-of-data RESTRICTIONS <<<
Jul 14 10:28:55 genesis postfix/smtpd[2332]: generic_checks: name=check_policy_service
Jul 14 10:28:55 genesis postfix/smtpd[2332]: warning: problem talking to server 127.0.0.1:7777: Success
Jul 14 10:28:56 genesis postfix/smtpd[2332]: auto_clnt_close: disconnect 127.0.0.1:7777 stream
Jul 14 10:28:56 genesis postfix/smtpd[2332]: trying... [127.0.0.1]
Jul 14 10:28:56 genesis postfix/smtpd[2332]: auto_clnt_open: connected to 127.0.0.1:7777
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr request = smtpd_access_policy
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr protocol_state = END-OF-MESSAGE
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr protocol_name = ESMTP
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr client_address = 12.130.137.150
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr client_name = omp.bbbyemail.com
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr client_port = 36016
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr reverse_client_name = omp.bbbyemail.com
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr helo_name = omp.bbbyemail.com
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr sender = BedBath&Beyond@emailbedbathandbeyond.com
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr recipient = dummy@mydomain.com
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr recipient_count = 1
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr queue_id = 45mttb4pXkz5x0F
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr instance = 91c.5d2b6657.68304.0
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr size = 167809
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr etrn_domain =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr stress =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr sasl_method =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr sasl_username =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr sasl_sender =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr ccert_subject =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr ccert_issuer =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr ccert_fingerprint =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr ccert_pubkey_fingerprint =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr encryption_protocol =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr encryption_cipher =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr encryption_keysize = 0
Jul 14 10:28:56 genesis postfix/smtpd[2332]: send attr policy_context =
Jul 14 10:28:56 genesis postfix/smtpd[2332]: 127.0.0.1:7777: wanted attribute: action
Jul 14 10:28:56 genesis postfix/smtpd[2332]: input attribute name: action
Jul 14 10:28:56 genesis postfix/smtpd[2332]: input attribute value: DUNNO Error: Invalid sender address: bedbath&beyond@emailbedbathandbeyond.com
Jul 14 10:28:56 genesis postfix/smtpd[2332]: 127.0.0.1:7777: wanted attribute: (list terminator)
Jul 14 10:28:56 genesis postfix/smtpd[2332]: input attribute name: (end)
Jul 14 10:28:56 genesis postfix/smtpd[2332]: check_table_result: inet:127.0.0.1:7777 DUNNO Error: Invalid sender address: bedbath&beyond@emailbedbathandbeyond.com policy query
Jul 14 10:28:56 genesis postfix/smtpd[2332]: generic_checks: name=check_policy_service status=0
Jul 14 10:28:56 genesis postfix/smtpd[2332]: >>> END End-of-data RESTRICTIONS <<<

6 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,770

Re: Strange Greylisting Behaviour

chaz wrote:

I notice there is a "&" in the address. Is that the cause of the problem?

Yes this is the cause. Please apply this patch and track this issue:
https://bitbucket.org/zhb/iredapd/commi … 1026646fde

7 Reply by chaz

  • chaz
  • Member
  • Offline
  • Registered: 2019-06-07
  • Posts: 37

Re: Strange Greylisting Behaviour

Mr Zhang,

I am happy to report that the fix solved the problem. Thanks.

I also saw iredapd v3.0 is out. Will update later this week.

8 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 30,770

Re: Strange Greylisting Behaviour

Thanks for the feedback. smile