postfix-users October 2010 archive
Main Archive Page > Month Archives  > postfix-users archives
postfix-users: Re: Repeated mails

Re: Repeated mails

From: Alberto Lepe <dev_at_nospam>
Date: Thu Oct 14 2010 - 05:08:02 GMT
To: postfix-users@postfix.org

On Thu, Oct 14, 2010 at 12:38 PM, captain_claw <ryanclaw@gmail.com> wrote:

>
>
> On Thu, Oct 14, 2010 at 10:40 AM, Matt Hayes <dominian@slackadelic.com>wrote:
>
>> On 10/13/2010 10:17 PM, Alberto Lepe wrote:
>>
>>> Yes Matt, I agree with you.
>>>
>>> However, for some reason a customer is complaining that some people are
>>> receiving several copies (in one case up to 15 copies) with exactly the
>>> same content, when he/she sent just one mail.
>>>
>>> I thought at the beginning it may be a problem with his mail client but
>>> after checking the logs I didn't see anything strange but those repeated
>>> lines.
>>>
>>> I now understand that those repeated logs are normal as the filter is
>>> re-injecting them into postfix. The only irregular thing I saw is that
>>> his/her mails are being marked as SPAM (but not rejected), which then
>>> are sent to quarantine. As far as I know, I have to manually "release"
>>> them from quarantine in order to be send, right?
>>> For now, I use those emails in quarantine to adjust the values of
>>> spamassassin until I can reach some comfortable setup in order to start
>>> blocking emails.
>>>
>>> Is there any other way I could analyze the "duplicated mails" problem?
>>>
>>> Thanks again.
>>>
>>
>>
>> What email client is the client using?
>>
>> -Matt
>>
>
> If you find that the problem is only on that user, I think you have to
> check his/her email client. if it's M$ outlook/express kindly check the
> pst/dbx file size of the user. cases that the MUA reaches its max size of
> 2gb (for M$ outlook 2003 below) the tendency is MUA can't write additional
> entry to pst/dbx and thus it remains to outbox. So if the users tries to
> send/receive the MUA re-send it to the recipient co'z the MUA assumed that
> there is still mail seating on the outbox. However if everybody is
> experiencing this problem then you have investigate more on your logs.
>
> -Ryan
>
>
>
The email client is M$ Outlook. I don't have the exact version yet (Is there
a way to get that from logs?). However, I don't think their pst/dbx file is
that large as the email account is few months old, and according to the
logs, this user have sent 605 emails with a total size of 567MB. (very
interesting though... I will take note of that. Thank you Ryan!)

Actually analyzing those logs to get the total size, helped me to found
something I didn't notice before (which is repeated several times in that
specific account (I haven't check others)):

A fragment of the summary of sent mail:

...
Oct 11 16:55:27 mail postfix/qmgr[5276]: 4A48F1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 16:55:29 mail postfix/qmgr[5276]: 8A58A1CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 16:58:22 mail postfix/qmgr[5276]: D2C821CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 16:58:23 mail postfix/qmgr[5276]: 4CD5B1CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:01:09 mail postfix/qmgr[5276]: 99ABF1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:01:11 mail postfix/qmgr[5276]: B02BC1CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:03:56 mail postfix/qmgr[5276]: 3272A1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:03:56 mail postfix/qmgr[5276]: 6E4671CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:06:42 mail postfix/qmgr[5276]: B80AB1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:06:45 mail postfix/qmgr[5276]: 329751CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:09:29 mail postfix/qmgr[5276]: AC4FC1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:09:30 mail postfix/qmgr[5276]: 2C09A1CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:12:16 mail postfix/qmgr[5276]: AC4B31CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:12:18 mail postfix/qmgr[5276]: C29611CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:15:03 mail postfix/qmgr[5276]: 493771CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:15:03 mail postfix/qmgr[5276]: B183E1CD0E: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:17:50 mail postfix/qmgr[5276]: 0082D1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:17:52 mail postfix/qmgr[5276]: 5BB201CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:20:36 mail postfix/qmgr[5276]: CA2A11CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:20:37 mail postfix/qmgr[5276]: 3A1541CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:23:23 mail postfix/qmgr[5276]: 82D0C1CD0B: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:23:25 mail postfix/qmgr[5276]: A1F911CD09: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:26:10 mail postfix/qmgr[5276]: 1748E1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:26:10 mail postfix/qmgr[5276]: 62E551CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
...

Interesting: The same size for different emails was sent with nrcpt=1.

I picked some of them to have a closer look and I found that those emails
were sent to the same mailbox: yuuichi@host.co.jp, which make me think that
the problem should be the client (as the same client [p2147- ... ] is listed
everytime). Right?

Here are the detailed logs (Those with size=4214840 were the re-injected
ones):
------------------------------------------------------------------------------------------------------
Oct 11 16:53:41 mail postfix/smtpd[3672]: 4A48F1CD09: client=
p2147-ipad21xsajima.ne.jp[20.0.0.147]
Oct 11 16:53:41 mail postfix/cleanup[3675]: 4A48F1CD09:
message-id=<00c501cb6919$3fbd98c0$180115ac@nagamatsu>
Oct 11 16:55:27 mail postfix/qmgr[5276]: 4A48F1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 16:55:29 mail postfix/smtp[3686]: 4A48F1CD09: to=<yuuichi@host.co.jp>,
relay=127.0.0.1[127.0.0.1]:10024, delay=108, delays=106/0/0/2.3, dsn=2.0.0,
status=sent (250 2.0.0 Ok: queued as 8A58A1CD0B)
Oct 11 16:55:29 mail postfix/qmgr[5276]: 4A48F1CD09: removed
------------------------------------------------------------------------------------------------------
Oct 11 16:55:29 mail postfix/smtpd[3694]: 8A58A1CD0B:
client=localhost[127.0.0.1]
Oct 11 16:55:29 mail postfix/cleanup[3685]: 8A58A1CD0B:
message-id=<00c501cb6919$3fbd98c0$180115ac@nagamatsu>
Oct 11 16:55:29 mail postfix/qmgr[5276]: 8A58A1CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 16:55:29 mail amavis[29234]: (29234-11) Passed CLEAN, [20.0.0.147]
[20.0.0.147] <nakata@example.com> -> <yuuichi@host.co.jp>, Message-ID:
<00c501cb6919$3fbd98c0$180115ac@nagamatsu>, mail_id: s6KqbwCR9IiA, Hits: -,
size: 4214
Oct 11 16:56:08 mail postfix/smtp[3695]: 8A58A1CD0B: to=<yuuichi@host.co.jp>,
relay=mail.global.hostmail.com[100.199.180.150]:25, delay=39,
delays=0.11/0/1.2/38, dsn=2.6.0, status=sent (250 2.6.0
<00c501cb6919$3fbd98c0$180115ac@nag
Oct 11 16:56:08 mail postfix/qmgr[5276]: 8A58A1CD0B: removed
------------------------------------------------------------------------------------------------------
Oct 11 16:56:36 mail postfix/smtpd[3672]: D2C821CD09: client=
p2147-ipad21xsajima.ne.jp[20.0.0.147]
Oct 11 16:56:36 mail postfix/cleanup[3675]: D2C821CD09:
message-id=<00c601cb6919$a8626270$180115ac@nagamatsu>
Oct 11 16:58:22 mail postfix/qmgr[5276]: D2C821CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 16:58:23 mail postfix/smtp[4289]: D2C821CD09: to=<yuuichi@host.co.jp>,
relay=127.0.0.1[127.0.0.1]:10024, delay=107, delays=106/0/0/0.51, dsn=2.0.0,
status=sent (250 2.0.0 Ok: queued as 4CD5B1CD0B)
Oct 11 16:58:23 mail postfix/qmgr[5276]: D2C821CD09: removed
------------------------------------------------------------------------------------------------------
Oct 11 16:58:23 mail postfix/smtpd[4299]: 4CD5B1CD0B:
client=localhost[127.0.0.1]
Oct 11 16:58:23 mail postfix/cleanup[3675]: 4CD5B1CD0B:
message-id=<00c601cb6919$a8626270$180115ac@nagamatsu>
Oct 11 16:58:23 mail postfix/qmgr[5276]: 4CD5B1CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 16:58:23 mail amavis[30396]: (30396-12) Passed CLEAN, [20.0.0.147]
[20.0.0.147] <nakata@example.com> -> <yuuichi@host.co.jp>, Message-ID:
<00c601cb6919$a8626270$180115ac@nagamatsu>, mail_id: Ty33aevnDtOr, Hits: -,
size: 4214
Oct 11 16:58:49 mail postfix/smtp[4301]: 4CD5B1CD0B: to=<yuuichi@host.co.jp>,
relay=mail.global.hostmail.com[200.32.180.22]:25, delay=26,
delays=0.12/0/0.74/25, dsn=2.6.0, status=sent (250 2.6.0
<00c601cb6919$a8626270$180115ac@naga
Oct 11 16:58:49 mail postfix/qmgr[5276]: 4CD5B1CD0B: removed
------------------------------------------------------------------------------------------------------
Oct 11 17:24:24 mail postfix/smtpd[6935]: 1748E1CD09: client=
p2147-ipad21xsajima.ne.jp[20.0.0.147]
Oct 11 17:24:24 mail postfix/cleanup[3675]: 1748E1CD09:
message-id=<00d001cb691d$8a221a90$180115ac@nagamatsu>
Oct 11 17:26:10 mail postfix/qmgr[5276]: 1748E1CD09: from=<
nakata@example.com>, size=4214332, nrcpt=1 (queue active)
Oct 11 17:26:10 mail postfix/smtp[6902]: 1748E1CD09: to=<yuuichi@host.co.jp>,
relay=127.0.0.1[127.0.0.1]:10024, delay=106, delays=106/0/0/0.53, dsn=2.0.0,
status=sent (250 2.0.0 Ok: queued as 62E551CD0B)
Oct 11 17:26:10 mail postfix/qmgr[5276]: 1748E1CD09: removed
------------------------------------------------------------------------------------------------------
Oct 11 17:26:10 mail postfix/smtpd[6910]: 62E551CD0B:
client=localhost[127.0.0.1]
Oct 11 17:26:10 mail postfix/cleanup[6937]: 62E551CD0B:
message-id=<00d001cb691d$8a221a90$180115ac@nagamatsu>
Oct 11 17:26:10 mail postfix/qmgr[5276]: 62E551CD0B: from=<
nakata@example.com>, size=4214840, nrcpt=1 (queue active)
Oct 11 17:26:10 mail amavis[7065]: (07065-02) Passed CLEAN, [20.0.0.147]
[20.0.0.147] <nakata@example.com> -> <yuuichi@host.co.jp>, Message-ID:
<00d001cb691d$8a221a90$180115ac@nagamatsu>, mail_id: IF+6lje-GaDe, Hits: -,
size: 42143
Oct 11 17:26:33 mail postfix/smtp[7426]: 62E551CD0B: to=<yuuichi@host.co.jp>,
relay=mail.global.hostmail.com[300.55.88.22]:25, delay=23,
delays=0.13/0/0.69/22, dsn=2.6.0, status=sent (250 2.6.0
<00d001cb691d$8a221a90$180115ac@nagam
Oct 11 17:26:33 mail postfix/qmgr[5276]: 62E551CD0B: removed