duplicated emails

[SaratogaSam]

Hi -

I think I may have a qmail problem; that's why I stopped by. Maybe you can help me verify my suspicions.

I run a php-based bulletin board (phpBB) that can issue email notifications to members who are watching specific forums for new messages. The problem I'm experiencing is that the bulletin board will issue 1 email notification to a user, but the user's email client will intermittently receive duplicate or triplicate email notifications...all identical. Luckily this is happening to me, so I have been able to collect a bunch of example duplicates.

At first I thought it was a problem with the bulletin board software. I hired a programmer to write some code to create and capture a list of the email recipients along with the bulletin board's unique message ID#. This code ran everytime an email notification was sent. This way I could link the duplicated emails (by their message ID#'s) with the list of intended email recipients. Lo and behold; I was able to trace 2 identical email notifications in my email inbox to an email recipient list that had only 1 user email address in it...my own. This meant that the bulletin board was sending out 1 email notification but I was receiving 2 in my Outlook Express inbox.

So I ruled out the bulletin board software as being problematic. I then began comparing the headers of the duplicated emails to see if anything jumped out at me. Here are the headers of two duplicated email notifications:

=============================================================================
X-Apparently-To: myname@sbcglobal.net via 206.190.37.98; Mon, 22 Nov 2004 18:20:04 -0800
X-Originating-IP: [209.216.209.23]
Return-Path: <autoreply@capstone.com>
Received: from 207.115.57.34 (EHLO ylpvm03.prodigy.net) (207.115.57.34)
by mta817.mail.yahoo.com with SMTP; Mon, 22 Nov 2004 18:20:04 -0800
X-Originating-IP: [209.216.209.23]
Received: from admin.capstone.com (admin.capstone.com [209.216.209.23])
by ylpvm03.prodigy.net (8.12.10 083104/8.12.10) with ESMTP id iAN2KJB6019255
for <myname@sbcglobal.net>; Mon, 22 Nov 2004 21:20:19 -0500
Received: (qmail 20621 invoked by uid 48); 23 Nov 2004 02:10:32 -0000
To:
Subject: <My reply> Admin: "New topic test"
Reply-to: autoreply@capstone.com
From: autoreply@capstone.com
Message-ID: <5bc5b11d070cdb19ed5c8a6bd309927e@shadow.capstone.com>
MIME-Version: 1.0
Content-type: text/plain; charset=iso-8859-1
Content-transfer-encoding: 8bit
Date: Mon, 22 Nov 2004 18:10:32 -0800
X-Priority: 3
X-MSMail-Priority: Normal
X-Mailer: PHP
X-MimeOLE: Produced By phpBB2
=============================================================================

X-Apparently-To: myname@sbcglobal.net via 206.190.37.92; Mon, 22 Nov 2004 18:50:04 -0800
X-Originating-IP: [209.216.209.23]
Return-Path: <autoreply@capstone.com>
Received: from 207.115.57.39 (EHLO ylpvm08.prodigy.net) (207.115.57.39)
by mta821.mail.sc5.yahoo.com with SMTP; Mon, 22 Nov 2004 18:50:04 -0800
X-Originating-IP: [209.216.209.23]
Received: from admin.capstone.com (admin.capstone.com [209.216.209.23])
by ylpvm08.prodigy.net (8.12.10 083104/8.12.10) with ESMTP id iAN2nvep007233
for <myname@sbcglobal.net>; Mon, 22 Nov 2004 21:49:57 -0500
Received: (qmail 20621 invoked by uid 48); 23 Nov 2004 02:10:32 -0000
To:
Subject: <My reply> Admin: "New topic test"
Reply-to: autoreply@capstone.com
From: autoreply@capstone.com
Message-ID: <5bc5b11d070cdb19ed5c8a6bd309927e@shadow.capstone.com>
MIME-Version: 1.0
Content-type: text/plain; charset=iso-8859-1
Content-transfer-encoding: 8bit
Date: Mon, 22 Nov 2004 18:10:32 -0800
X-Priority: 3
X-MSMail-Priority: Normal
X-Mailer: PHP
X-MimeOLE: Produced By phpBB2
=============================================================================

What I noticed is that both headers start out the same (at the bottom) but diverge once qmail is invoked. Notice how the line immediately following "Received: (qmail 20621 invoked by uid 48); 23 Nov 2004 02:10:32 -0000" differs in its timestamp. It looks to me like qmail took one email and duplicated it.

Am I reading these headers correctly?


Thanks for your expertise.

 

[thedaver]

Have you considered the possibility that phpBB has a feature enabled that mails a copy of the outgoing traffic to a list administrator?

It's awfully hard to debug this when you're sending to yourself as a user and an admin.

How about getting yourself a free yahoo account, add that to the distribution list, and again monitor the email flow?

Hosting Solutions for Home or Business.

http://www.surfinbox.com/hosting/

 

[SaratogaSam]

Thedaver -

Thanks for the response. The phpBB software that issues the forum notifications does not distinguish between an admin and a user. It simply scans a table in the MySQL database looking for people who have chosen to "watch" the specific forum and then emails each of them one notification.

In addition, I've had 8 other normals users report to me that they are receiving duplicate email notifications.

Which brings me back to my original question.

Do the headers I posted indicate that qmail is duplicating the incoming email from the phpBB?

(I just want to make sure I'm not interpreting these headers incorrectly.)

Thanks

 

[thedaver]

Your first message header:

<snip>
Received: from admin.capstone.com (admin.capstone.com [209.216.209.23])
by ylpvm03.prodigy.net (8.12.10 083104/8.12.10) with ESMTP id iAN2KJB6019255
for <myname@sbcglobal.net>; Mon, 22 Nov 2004 21:20:19 -0500
Received: (qmail 20621 invoked by uid 48); 23 Nov 2004 02:10:32 -0000
</snip>
<snip>
Message-ID: <5bc5b11d070cdb19ed5c8a6bd309927e@shadow.capstone.com>
</snip>

Your second message header:

<snip>
Received: from admin.capstone.com (admin.capstone.com [209.216.209.23])
by ylpvm08.prodigy.net (8.12.10 083104/8.12.10) with ESMTP id iAN2nvep007233
for <myname@sbcglobal.net>; Mon, 22 Nov 2004 21:49:57 -0500
Received: (qmail 20621 invoked by uid 48); 23 Nov 2004 02:10:32 -0000
</snip>
<snip>
Message-ID: <5bc5b11d070cdb19ed5c8a6bd309927e@shadow.capstone.com>
</snip>

From the bottom up, I read this as:
The same, single message is being sent in both headers; number 5bc5b11...09927e.
I conclude from this that qmail is sending a single message.

You have apparently stripped out the TO: line contents so that makes it rather had to debug.

I do see two distinct ESTMP ids from prodigy's servers. This and the timestamps indicate that there were two seperate attempts to transmit the message to prodigy.

My interpretation, with incomplete facts, is that there are multiple instances of the same message being sent to prodigy. This may indicate that addressees are duplicated in the To, CC and BCC fields. This may indicate that you have unknown .qmail files. This may indicate a fault in SMTP handshaking/timeout between your SMTP outbound and the prodigy server.






Hosting Solutions for Home or Business.

http://www.surfinbox.com/hosting/

 

[SaratogaSam]

You have apparently stripped out the TO: line contents so that makes it rather had to debug.

Actually I did not strip out anything. What I provided here was the entire Message Properties supplied by Outlook Express. Is there another place where I can get more complete header information?

I do see two distinct ESTMP ids from prodigy's servers. This and the timestamps indicate that there were two seperate attempts to transmit the message to prodigy.

My interpretation, with incomplete facts, is that there are multiple instances of the same message being sent to prodigy. This may indicate that addressees are duplicated in the To, CC and BCC fields. This may indicate that you have unknown .qmail files. This may indicate a fault in SMTP handshaking/timeout between your SMTP outbound and the prodigy server.

I got my hands on qmail's mail log. What I found is this:

Nov 30 19:01:00 admin qmail: 1101870060.971405 new msg 323878926
Nov 30 19:01:00 admin qmail: 1101870060.971589 info msg 323878926: bytes 325 from qp 31177 uid 0
Nov 30 19:01:01 admin qmail: 1101870061.050143 starting delivery 1675: msg 323878926 to remote myname@sbcglobal.net
Nov 30 19:01:01 admin qmail: 1101870061.050224 status: local 0/10 remote 1/20
Nov 30 19:03:02 admin qmail: 1101870182.783608 delivery 1675: deferral: Connected_to_207.115.57.17_but_connection_died._Possible_duplicate!_(#4.4.2)/
Nov 30 19:03:02 admin qmail: 1101870182.783690 status: local 0/10 remote 0/20
Nov 30 19:08:22 admin qmail: 1101870502.774982 starting delivery 1676: msg 323878926 to remote myname@sbcglobal.net
Nov 30 19:08:22 admin qmail: 1101870502.775052 status: local 0/10 remote 1/20
Nov 30 19:08:24 admin qmail: 1101870504.329189 delivery 1676: success: 207.115.57.17_accepted_message./Remote_host_said:_250_2.0.0_iB138nIA022458_Message_accepted_for_delivery/
Nov 30 19:08:24 admin qmail: 1101870504.329583 status: local 0/10 remote 0/20
Nov 30 19:08:24 admin qmail: 1101870504.329978 end msg 323878926

Any idea what it means when the "connection dies"?

 

[thedaver]

“Connection Dies” - I have NEVER encountered this error - probably means either:
1) You have some setting (I don't know what) that is telling SMTPd to use a fairly intolerant timeout that is more aggressive than the default - I have no idea even IF there is a setting for this…..
2) You have a shoddy network connection that is doing nasty things to your connection.
3) Prodigy's SMTPd server(s) suck.

Obviously 1 and 2 are items you can do something about.
I would be surprised if #3 is really the case, although I would have no problem bashing prodigy off-topic.

Do me a favor and run your log snippet through 'tai64nlocal' to convert the timestamps to human readable format and we'll see how long these transactions are taking before failure. That'll help identify if it's a timeout problem.

eg: "tai64nlocal < qmaillogfile > ~/qmailsample.log"

Re-snip your example above and post that output here.



Hosting Solutions for Home or Business.

http://www.surfinbox.com/hosting/

 

[SaratogaSam]

thedaver -

Thanks for your reply.

I took a look at the documentation for tai64nlocal and it says that it looks for logfile timestamps that begin with "@" and then converts them. The log file that I've provided contains no timestamp information preceded with an "@" sign! This logfile must be the output of some other converter. I simply asked my host provider to tell me where to find the qmail log files and this is what they gave me.

Do I need to ask them for something more specific? Like, the "raw" qmail log file callled "qmaillogfile"?

Also, I realized after re-reading the thread that I had posted the wrong qmail log file above. I've discovered 2 cases that cause duplicate emails. The email properties that I started this thread with are from case #1. The qmail log file that I posted most recently is from case #2. Sorry for the confusion.

Here is the qmail log that belongs to case #1. In this case, jeff@mydomain.us is an email redirect hosted on a registrar called directnic.com. The redirect goes to my real email address at myname@sbcglobal.net.

Nov 22 18:20:02 admin qmail: 1101176402.150912 new msg 323878929
Nov 22 18:20:02 admin qmail: 1101176402.151001 info msg 323878929: bytes 1419 from <autoreply@capstone.com> qp 20621 uid 48
Nov 22 18:20:02 admin qmail: 1101176402.478221 delivery 2: deferral: Connected_to_204.251.10.82_but_greeting_failed./Remote_host_said:_421_4.3.2_iris2.directnic.com_is_too_busy_to_accept_mail_right_now/
Nov 22 18:20:02 admin qmail: 1101176402.478305 status: local 0/10 remote 3/20
Nov 22 18:20:02 admin qmail: 1101176402.478356 delivery 3: deferral: Connected_to_204.251.10.82_but_greeting_failed./Remote_host_said:_421_4.3.2_iris2.directnic.com_is_too_busy_to_accept_mail_right_now/
Nov 22 18:20:02 admin qmail: 1101176402.478409 status: local 0/10 remote 2/20
Nov 22 18:20:02 admin qmail: 1101176402.770648 starting delivery 5: msg 323878929 to remote myname@sbcglobal.net
Nov 22 18:20:02 admin qmail: 1101176402.872565 status: local 0/10 remote 3/20
Nov 22 18:20:03 admin qmail: 1101176403.612622 delivery 4: success: 217.160.230.12_accepted_message./Remote_host_said:_250_Message_0MKv6A-1CWQHj3nD7-0002TK_accepted_for_delivery/
Nov 22 18:50:01 admin qmail: 1101178201.707173 status: local 0/10 remote 0/20
Nov 22 18:50:01 admin qmail: 1101178201.708187 starting delivery 1: msg 323878928 to remote admail.direct@unsubscribenow.info
Nov 22 18:50:01 admin qmail: 1101178201.708240 status: local 0/10 remote 1/20
Nov 22 18:50:01 admin qmail: 1101178201.708284 starting delivery 2: msg 323878927 to remote jeff@mydomain.us
Nov 22 18:50:01 admin qmail: 1101178201.708325 status: local 0/10 remote 2/20
Nov 22 18:50:01 admin qmail: 1101178201.710739 starting delivery 3: msg 323878929 to remote myname@sbcglobal.net
Nov 22 18:50:01 admin qmail: 1101178201.710833 status: local 0/10 remote 3/20
Nov 22 18:50:01 admin qmail: 1101178201.710875 starting delivery 4: msg 323878926 to remote jeff@mydomain.us
Nov 22 18:50:01 admin qmail: 1101178201.710915 status: local 0/10 remote 4/20

 

[thedaver]

You have three possible deliveries (#2-4) headed for your real account.

You have two simultaneous deliveries to the same jeff@ address and another will arrive via the myname@ address.

I'm still convinced that you have an issue in how the email is being queued.

What you might want to consider is to try and grab a copy of the actual message text when generated from the queue/mess/XXXX folder by using a "grep -iR " on the message number.

Something still looks odd from outside of qmail.

What happens if you just do this:

echo "myname@sbcglobal.net" | /var/qmail/bin/qmail-inject




Hosting Solutions for Home or Business.

http://www.surfinbox.com/hosting/

 

[SaratogaSam]

thedaver -

Sorry for not getting back to you. Over the last week I have been conversing with my host provider trying to solve the problem and juggling Christmas stuff. Yikes!

I have not tried the GREP and the qmail-inject that you suggested yet, however I do have some additional data that might lead you to a conclusion.

Initially, my hosting provider wanted to blame the phpBB for issuing duplicate emails. I told them about the software I hired a guy to write to verify that single emails were being issued. They were not impressed. They suggested writing me a CRON job that sends me an email every 10 minutes; this way we'd be removing the phpBB variable from the problem. I though it was a good idea so we did it. Here's the code: (I've disguised my email address)

#!/usr/bin/php -q
<?php
$to = "myname@sbcglobal.net";
$headers = "From: wicronmailer";
$subject = "wi cron mailer";
$message = "This is from the Webintellects CRON job.\n";
$message .= "The time is now ".date("H:i:s");
mail($to, $subject, $message, $headers);
?>

Sure enough, in less than an hour I got my first duplicate email. Now they want to blame the @sbcglobal.net domain. Here's their theory:

"Okay, here is what I have found. I believe the issue is that sbcglobal's MTA (eMail server) is not sending the required 2xx code once data transmission is complete. This leads qmail to believe the transfer failed, and qmail requeues the email for future delivery."

The problem with this theory is that I've also had complaints of duplicated emails from 5 people using @yahoo.com domains, 2 people using @scu.edu domains and 1 person using a @hp.com domain. Do all of these domains have faulty MTA's? Unlikely. In addition, my @sbcglobal.net email account has never, ever, received any duplicated emails from anyone else except from my troubled phpBB and their CRON job. This leads me to believe that the problem lies within the hosts' server and probably with a qmail setting. I challenged them on this and am still awaiting an answer.

In the mean time I've been perusing qmail's documentation and found a reference to these qmail attributes:

File / default / program
===============================
timeoutconnect 60 qmail-remote
timeoutremote 1200 qmail-remote
timeoutsmtpd 1200 qmail-smtpd

Here's my theory on what's happening: The qmail timeout settings on the server I am renting are set to values that are too small. When qmail delivers an email it waits a certain amount of time for a response -- if it doesn't get the response it resends and duplicates. I can believe that @yahoo and @scu.edu, both being free email domains, have slow overloaded servers. If they get overloaded they can't respond in time to qmail. The largest percentage of duplications occurred with users on @yahoo.com and @scu.edu domains.

What do you think - am I barking up the wrong tree?

 

[thedaver]

I raised this concern (and somewhat abandoned it) in my third post. My conclusion that the "other guy" was at fault because of a crappy SMTPd receiving session is consistent with your investigation, but it now appears that YOU have the problem.

I have never changed the delivery defaults in qmail in terms of the three parameters you listed in your most recent post.

Are you running from a shared instance? Is the server busy and is it time-slicing a lot? Meaning, is the box running slow such that the timeouts are being hit?

Also, you may want to understand which patches and which versions of patches the qmail is running with, you may find that there's some patch in there that's affecting that qmail build's interpretation of SMTPd responses from the other parties.

I'm grasping at straws a bit here....

When in doubt, rebuild qmail.... IF YOU'RE CONVINCED that their network is healthy. I wouldn't yet rule out that the actual connections to the other servers are subject to line noise or other factors that lead to an abandoned delivery effort.




Hosting Solutions for Home or Business.

http://www.surfinbox.com/hosting/