search

schweikert / postgrey

Postfix Greylisting Policy-Daemon
https://postgrey.schweikert.ch/
GNU General Public License v2.0
159 stars 47 forks source link

Lost email when new user in CC #93

Closed Stopi closed 2 years ago

Stopi commented 2 years ago

Hi,

on this server, we run CentOS 8 with postgrey.noarch:1.37-9.el8 (epel).

we received a mail for user1@from.ourdomain with a CC field which was asking for a copy to user2@from.ourdomain, user3@from.ourdomain and user4@from.ourdomain (plus more users from another domain we don't own).

2 days before, the same sender@host.from.outside already sent an email to user1@from.ourdomain, user2@from.ourdomain and user3@from.ourdomain. So the "triplets" were already in postgrey's db for those recipients.

Postgrey then detected that incoming mail as new and greylisted it ONLY for user4@from.ourdomain. So Postfix delivered the e-mail to the 3 other users.

More importantly, since the sender was notified his email was received, it never presented it again, so user4@from.ourdomain just never received that email (and no-one received any notification about that loss).

Here is the full postfix log for this problem:

Jan 14 12:13:57 mail postfix/smtpd[74086]: connect from smtp.host.from.outside[ip.address.from.outside]
Jan 14 12:13:57 mail postfix/smtpd[74086]: discarding EHLO keywords: CHUNKING
Jan 14 12:13:59 mail postfix/smtpd[74086]: Anonymous TLS connection established from smtp.host.from.outside[ip.address.from.outside]: TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
Jan 14 12:13:59 mail postfix/smtpd[74086]: discarding EHLO keywords: CHUNKING
Jan 14 12:14:03 mail policyd-spf[74094]: prepend Received-SPF: Pass (mailfrom) identity=mailfrom; client-ip=ip.address.from.outside; helo=smtp.host.from.outside; envelope-from=sender@host.from.outside; receiver=<UNKNOWN>
Jan 14 12:14:03 mail postgrey[4085467]: action=pass, reason=triplet found, client_name=smtp.host.from.outside, client_address=ip.address.from.outside, sender=sender@host.from.outside, recipient=user3@from.ourdomain
Jan 14 12:14:03 mail postfix/smtpd[74086]: 578783D72E: client=smtp.host.from.outside[ip.address.from.outside]
Jan 14 12:14:03 mail postgrey[4085467]: 578783D72E: action=pass, reason=triplet found, client_name=smtp.host.from.outside, client_address=ip.address.from.outside, sender=sender@host.from.outside, recipient=user1@from.ourdomain
Jan 14 12:14:04 mail postgrey[4085467]: 578783D72E: action=pass, reason=recipient whitelist, client_name=smtp.host.from.outside, client_address=ip.address.from.outside, sender=sender@host.from.outside, recipient=user2@from.ourdomain
Jan 14 12:14:06 mail postgrey[4085467]: 578783D72E: action=greylist, reason=new, client_name=smtp.host.from.outside, client_address=ip.address.from.outside, sender=sender@host.from.outside, recipient=user4@from.ourdomain
Jan 14 12:14:07 mail postfix/smtpd[74086]: 578783D72E: reject: RCPT from smtp.host.from.outside[ip.address.from.outside]: 450 4.2.0 <user4@from.ourdomain>: Recipient address rejected: Greylisted for 300 seconds; from=<sender@host.from.outside> to=<user4@from.ourdomain> proto=ESMTP helo=<smtp.host.from.outside>
Jan 14 12:14:07 mail postfix/cleanup[74098]: 578783D72E: message-id=<003801d80905$87b08a50$97119ef0$@host.from.outside>
Jan 14 12:14:09 mail opendkim[4085441]: 578783D72E: smtp.host.from.outside [ip.address.from.outside] not internal
Jan 14 12:14:09 mail opendkim[4085441]: 578783D72E: not authenticated
Jan 14 12:14:09 mail opendkim[4085441]: 578783D72E: no signing domain match for 'host.from.outside'
Jan 14 12:14:09 mail opendkim[4085441]: 578783D72E: no signing subdomain match for 'host.from.outside'
Jan 14 12:14:09 mail opendkim[4085441]: 578783D72E: DKIM verification successful
Jan 14 12:14:09 mail postfix/qmgr[4085731]: 578783D72E: from=<sender@host.from.outside>, size=311476, nrcpt=3 (queue active)
Jan 14 12:14:09 mail postfix/smtpd[74086]: disconnect from smtp.host.from.outside[ip.address.from.outside] ehlo=2 starttls=1 mail=1 rcpt=3/4 data=1 quit=1 commands=9/10
Jan 14 12:14:09 mail postfix/10025/smtpd[74109]: connect from localhost[127.0.0.1]
Jan 14 12:14:09 mail postfix/10025/smtpd[74109]: discarding EHLO keywords: CHUNKING
Jan 14 12:14:09 mail postfix/10025/smtpd[74109]: B9F6B3B289: client=localhost[127.0.0.1]
Jan 14 12:14:09 mail postfix/cleanup[74098]: B9F6B3B289: message-id=<003801d80905$87b08a50$97119ef0$@host.from.outside>
Jan 14 12:14:09 mail opendkim[4085441]: B9F6B3B289: no signing domain match for 'host.from.outside'
Jan 14 12:14:09 mail opendkim[4085441]: B9F6B3B289: no signing subdomain match for 'host.from.outside'
Jan 14 12:14:09 mail opendkim[4085441]: B9F6B3B289: DKIM verification successful
Jan 14 12:14:09 mail postfix/qmgr[4085731]: B9F6B3B289: from=<sender@host.from.outside>, size=312348, nrcpt=5 (queue active)
Jan 14 12:14:09 mail postfix/10025/smtpd[74109]: disconnect from localhost[127.0.0.1] ehlo=1 mail=1 rcpt=3 data=1 quit=1 commands=7
Jan 14 12:14:09 mail amavis[70340]: (70340-08) Passed CLEAN {RelayedInternal}, ORIGINATING LOCAL [ip.address.from.outside]:59184 [another.ip.address.from.outside] <sender@host.from.outside> -> <user3@from.ourdomain>,<user2@from.ourdomain>,<user1@from.ourdomain>, Queue-ID: 578783D72E, Message-ID: <003801d80905$87b08a50$97119ef0$@host.from.outside>, mail_id: fBZWv2QsaXXG, Hits: -, size: 311936, queued_as: B9F6B3B289, 517 ms
Jan 14 12:14:09 mail postfix/amavis/smtp[74107]: 578783D72E: to=<user3@from.ourdomain>, relay=127.0.0.1[127.0.0.1]:10026, delay=10, delays=9.8/0.02/0/0.52, 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 B9F6B3B289)
Jan 14 12:14:09 mail postfix/amavis/smtp[74107]: 578783D72E: to=<user2@from.ourdomain>, relay=127.0.0.1[127.0.0.1]:10026, delay=10, delays=9.8/0.02/0/0.52, 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 B9F6B3B289)
Jan 14 12:14:09 mail postfix/amavis/smtp[74107]: 578783D72E: to=<user1@from.ourdomain>, relay=127.0.0.1[127.0.0.1]:10026, delay=10, delays=9.8/0.02/0/0.52, 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 B9F6B3B289)
Jan 14 12:14:09 mail postfix/qmgr[4085731]: 578783D72E: removed
Jan 14 12:14:10 mail dovecot[74119]: lda(user1@from.ourdomain)<74119><OsYbAaIG4WGHIQEARKbHOg>: sieve: msgid=<003801d80905$87b08a50$97119ef0$@host.from.outside>: stored mail into mailbox 'INBOX'
Jan 14 12:14:10 mail postfix/pipe[74117]: B9F6B3B289: to=<user1@from.ourdomain>, relay=dovecot, delay=0.83, delays=0.22/0.02/0/0.59, dsn=2.0.0, status=sent (delivered via dovecot service (lda(user1@from.ourdomain): Error: net_connect_unix(/run/dovecot/stats-writer) failed: Permis))
Jan 14 12:14:10 mail dovecot[74118]: lda(user2@from.ourdomain)<74118><ILvIAKIG4WGGIQEARKbHOg>: sieve: msgid=<003801d80905$87b08a50$97119ef0$@host.from.outside>: stored mail into mailbox 'INBOX'
Jan 14 12:14:10 mail dovecot[74116]: lda(user3@from.ourdomain)<74116><x8V0AKIG4WGEIQEARKbHOg>: sieve: msgid=<003801d80905$87b08a50$97119ef0$@host.from.outside>: stored mail into mailbox 'INBOX'
Jan 14 12:14:10 mail postfix/pipe[74115]: B9F6B3B289: to=<user2@from.ourdomain>, relay=dovecot, delay=0.86, delays=0.22/0.01/0/0.62, dsn=2.0.0, status=sent (delivered via dovecot service (lda(user2@from.ourdomain): Error: net_connect_unix(/run/dovecot/stats-writer) failed: Permission denied))
Jan 14 12:14:10 mail postfix/pipe[74113]: B9F6B3B289: to=<user3@from.ourdomain>, relay=dovecot, delay=0.86, delays=0.22/0.01/0/0.62, dsn=2.0.0, status=sent (delivered via dovecot service (lda(user3@from.ourdomain): Error: net_connect_unix(/run/dovecot/stats-writer) failed: Permission))
Jan 14 12:14:17 mail postfix/qmgr[4085731]: B9F6B3B289: removed

I don't know if this is a known issue, but if some users don't receive emails then it's severe enough.

Somehow, I would think when a sender has passed greylisting once, then it should not be greylisted again for another recipient. Is there a way to configure Postgrey to have that behavior? Any help would be appreciated.

Please don't mind the final postfix's Permission denied in those logs since it's another unrelated issue I've fixed, messages were properly delivered by dovecot.

fleish commented 2 years ago

I can confirm this behavior but do not think it's a postgrey issue. Each CLIENT_IP / SENDER / RECIPIENT triplet is unique and evaluated independently regardless if the recipient is found in the TO, CC, or BCC field. For this reason, it also doesn't make any difference if the recipient was added on to an existing email thread. The sending mail server smtp.host.from.outside[ip.address.from.outside] should continue re-trying to deliver the message to user4@from.ourdomain just like any other SMTP transient failure with a 4xx response code.

Stopi commented 2 years ago

Thanks for your answer.

I thought it should be like that. But then I have no explanation on why this mail was never presented again to user4@from.ourdomain. I see no track in the logs, even days after.

I guess will never know...

fleish commented 2 years ago

Yeah, short of asking the admin of the sending MTA to check their logs I think you'll have to write that one.