email addresses with forwarding receive duplicate emails sent by postfix

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

email addresses with forwarding receive duplicate emails sent by postfix

Andy Yen
Hi Postfixer,
         I am running into a relatively uncommon bug that is showing up
occasionally. Basically, every once in a while, an email address that is
receiving email from my postfix server will get 3 copies of the same email.

The common denominator that I have found is that all of the recipients
that are encountering this problem have email forwarding enabled on
their email addresses.

It seems my postfix server is the only one that has this problem. If I
send to those same recipient from another email address, they do not get
the duplicate emails which is why I suspect it is something to do with
my postfix configuration. I am basically using the default settings that
ship with CentOS postfix.

Is there a setting I can change to fix this?

Thanks,
Andy
Reply | Threaded
Open this post in threaded view
|

Re: email addresses with forwarding receive duplicate emails sent by postfix

Viktor Dukhovni
On Mon, Apr 28, 2014 at 10:37:41PM -0400, Andy Yen wrote:

> Is there a setting I can change to fix this?

Change the setting that enables you to ask questions that non-psychics
can answer:

    http://www.postfix.org/DEBUG_README.html#mail

When mail delivered multiple times that will be recorded in your
logs.  You need to identify all log entries pertaining to some
sample messages that were delivered more than once.

Avoid virtual alias expansion on both sides of a content filter,
as that can generate a second copy of a forwarding address.

Watch for deliveries that time-out at end of data, Postfix logs
make a fuss about these:

    <some problem> sending end of data -- message may be sent more than once

--
        Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: email addresses with forwarding receive duplicate emails sent by postfix

Andy Yen
Hi, sorry, it appears I forgot to add the logs. They are included below.
This is called with PHPMailer just once, but postfix show it is being
sent 3 times for some reason....

This is the output from /var/log/maillog

Apr 28 21:50:27 mail postfix/smtp[13404]: 8F8E3142500B4:
to=<[hidden email]>,
relay=mail.somedomain.com[216.70.96.226]:25, delay=1.2,
delays=0.05/0/0.98/0.2, dsn=2.0.0, status=sent (250 ok 1398736227 qp 7475)
Apr 28 22:06:47 mail postfix/smtp[15276]: 2D7D3142500D1:
to=<[hidden email]>,
relay=mail.somedomain.com[216.70.96.226]:25, delay=0.75,
delays=0.05/0/0.5/0.2, dsn=2.0.0, status=sent (250 ok 1398737207 qp 7660)
Apr 28 22:15:00 mail postfix/smtp[16179]: A56FD142500D8:
to=<[hidden email]>,
relay=mail.somedomain.com[216.70.96.226]:25, delay=0.57,
delays=0.06/0.01/0.3/0.2, dsn=2.0.0, status=sent (250 ok 1398737700 qp 7767)

And just for good measure, here is the header of one of the duplicate
emails:

Delivered-To: [hidden email]
Received: by 10.50.18.109 with SMTP id v13csp167834igd;
         Mon, 28 Apr 2014 19:15:01 -0700 (PDT)
X-Received: by 10.224.43.202 with SMTP id x10mr38107986qae.33.1398737701104;
         Mon, 28 Apr 2014 19:15:01 -0700 (PDT)
Return-Path: <[hidden email]>
Received: from somedomain2.com (somedomain2.com. [216.70.96.226])
         by mx.google.com with ESMTPS id
m6si8788039qay.264.2014.04.28.19.15.00
         for <[hidden email]>
         (version=TLSv1 cipher=RC4-SHA bits=128/128);
         Mon, 28 Apr 2014 19:15:00 -0700 (PDT)
Received-SPF: fail (google.com: domain of [hidden email] does
not designate 216.70.96.226 as permitted sender) client-ip=216.70.96.226;
Authentication-Results: mx.google.com;
        spf=hardfail (google.com: domain of [hidden email]
does not designate 216.70.96.226 as permitted sender)
smtp.mail=[hidden email];
        dkim=pass header.i=@mypostfixserver.ch
Received: (qmail 7773 invoked by uid 110); 28 Apr 2014 19:15:00 -0700
Delivered-To: [hidden email]
Received: (qmail 7768 invoked from network); 28 Apr 2014 19:15:00 -0700
Received: from mail.mypostfixserver.ch (37.35.106.36)
   by somedomain2.com with SMTP; 28 Apr 2014 19:15:00 -0700
Received: by mail.mypostfixserver.ch (Postfix, from userid 48)
     id A56FD142500D8; Tue, 29 Apr 2014 02:14:59 +0000 (UTC)
DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/simple; d=mypostfixserver.ch;
     s=default; t=1398737699;
     bh=IaVP+ibSl+fsj6ZF5y3K4650oRFesmd8IIBibB3ng30=;
     h=To:Subject:Date:From;
b=MoMkBbWKC9Ww3SETh8O6Jtey5fhxp6BYvJ6/B5nESlYD5ZZKih+JfmfUucecTdiGQ
  WECZ20XW9SH8NoccKt62p+JJCDwuiIZ/fDw9b2CUE0ZuukUe35OGpWf8kUlWKgjZWd
      5h8daZ4zbdLRYaL1GWMTjQD1bEB0fhWX9ectYn7M=
To: [hidden email]

On 4/28/2014 10:49 PM, Viktor Dukhovni wrote:

> On Mon, Apr 28, 2014 at 10:37:41PM -0400, Andy Yen wrote:
>
>> Is there a setting I can change to fix this?
> Change the setting that enables you to ask questions that non-psychics
> can answer:
>
>      http://www.postfix.org/DEBUG_README.html#mail
>
> When mail delivered multiple times that will be recorded in your
> logs.  You need to identify all log entries pertaining to some
> sample messages that were delivered more than once.
>
> Avoid virtual alias expansion on both sides of a content filter,
> as that can generate a second copy of a forwarding address.
>
> Watch for deliveries that time-out at end of data, Postfix logs
> make a fuss about these:
>
>      <some problem> sending end of data -- message may be sent more than once
>

Reply | Threaded
Open this post in threaded view
|

Re: email addresses with forwarding receive duplicate emails sent by postfix

Stan Hoeppner
On 4/28/2014 10:17 PM, Andy Yen wrote:

> Hi, sorry, it appears I forgot to add the logs. They are included below.
> This is called with PHPMailer just once, but postfix show it is being
> sent 3 times for some reason....
>
> This is the output from /var/log/maillog
>
> Apr 28 21:50:27 mail postfix/smtp[13404]: 8F8E3142500B4:
> to=<[hidden email]>,
> relay=mail.somedomain.com[216.70.96.226]:25, delay=1.2,
> delays=0.05/0/0.98/0.2, dsn=2.0.0, status=sent (250 ok 1398736227 qp 7475)
> Apr 28 22:06:47 mail postfix/smtp[15276]: 2D7D3142500D1:
> to=<[hidden email]>,
> relay=mail.somedomain.com[216.70.96.226]:25, delay=0.75,
> delays=0.05/0/0.5/0.2, dsn=2.0.0, status=sent (250 ok 1398737207 qp 7660)
> Apr 28 22:15:00 mail postfix/smtp[16179]: A56FD142500D8:
> to=<[hidden email]>,
> relay=mail.somedomain.com[216.70.96.226]:25, delay=0.57,
> delays=0.06/0.01/0.3/0.2, dsn=2.0.0, status=sent (250 ok 1398737700 qp
> 7767)

This simply demonstrates what you already know--3 messages queued, 3
delivered.  You need to locate the smtpd log entries showing the
injection point of each of the 3 message IDs, and any alias expansions.
 You mentioned this only occurs with users who have "email forwarding
enabled on their email addresses".  Describe precisely how you are
performing such forwarding.  This is probably the root of the problem.

> And just for good measure, here is the header of one of the duplicate
> emails:

The header won't tell us anything about injection.

...
> On 4/28/2014 10:49 PM, Viktor Dukhovni wrote:
>> On Mon, Apr 28, 2014 at 10:37:41PM -0400, Andy Yen wrote:
>>
>>> Is there a setting I can change to fix this?
>> Change the setting that enables you to ask questions that non-psychics
>> can answer:
>>
>>      http://www.postfix.org/DEBUG_README.html#mail

Per the instructions, paste the output of "postconf -n" into your
message.  This allows us to spot Postfix configuration errors.

>> When mail delivered multiple times that will be recorded in your
>> logs.  You need to identify all log entries pertaining to some
>> sample messages that were delivered more than once.
>>
>> Avoid virtual alias expansion on both sides of a content filter,
>> as that can generate a second copy of a forwarding address.
>>
>> Watch for deliveries that time-out at end of data, Postfix logs
>> make a fuss about these:
>>
>>      <some problem> sending end of data -- message may be sent more
>> than once



Cheers,

Stan

Reply | Threaded
Open this post in threaded view
|

Re: email addresses with forwarding receive duplicate emails sent by postfix

Viktor Dukhovni
In reply to this post by Andy Yen
On Mon, Apr 28, 2014 at 11:17:36PM -0400, Andy Yen wrote:

> Hi, sorry, it appears I forgot to add the logs.
>
> This is the output from /var/log/maillog
>
> Apr 28 21:50:27 mail postfix/smtp[13404]: 8F8E3142500B4:
> to=<[hidden email]>, relay=mail.somedomain.com[216.70.96.226]:25,
> delay=1.2, delays=0.05/0/0.98/0.2, dsn=2.0.0, status=sent (250 ok 1398736227
> qp 7475)
> Apr 28 22:06:47 mail postfix/smtp[15276]: 2D7D3142500D1:
> to=<[hidden email]>, relay=mail.somedomain.com[216.70.96.226]:25,
> delay=0.75, delays=0.05/0/0.5/0.2, dsn=2.0.0, status=sent (250 ok 1398737207
> qp 7660)
> Apr 28 22:15:00 mail postfix/smtp[16179]: A56FD142500D8:
> to=<[hidden email]>, relay=mail.somedomain.com[216.70.96.226]:25,
> delay=0.57, delays=0.06/0.01/0.3/0.2, dsn=2.0.0, status=sent (250 ok
> 1398737700 qp 7767)

With 3 queue files you get three deliveries.  The real there are
three is to be found earlier in the logs by applying curiosity
and initiative to track these back to their origin.

These messages have timestamps 16 minutes and 9 minutes apart
respectively, there is very little chance that they are duplicated
inside Postfix.  They are independent transmissions.

> And just for good measure, here is the header of one of the duplicate
> emails:

If you're claiming something is a duplicate, sure it would make
sense to to show at least two of it.

> Received: from mail.mypostfixserver.ch (37.35.106.36)
>   by somedomain2.com with SMTP; 28 Apr 2014 19:15:00 -0700
> Received: by mail.mypostfixserver.ch (Postfix, from userid 48)
>     id A56FD142500D8; Tue, 29 Apr 2014 02:14:59 +0000 (UTC)

This message came into the Postfix queue directly via pickup, and
was delivered to a remote qmail system without any content filter
or other hops.  If the other messages took the same route, then
your PHP script injected three messages into the Postfix queue.
The pickup daemon is how mail submitted via the sendmail(1) command
enters the Postfix queue.

Reading the other log entries for the above queue ids is required
follow-up work.

Please spend some time doing a bit of reading the data you collect
and following the chain of evidence rather than punting logs you've
not bothered to read to the list.

--
        Viktor.