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 - 07:21:34 GMT
To: postfix-users@postfix.org

On Thu, Oct 14, 2010 at 3:27 PM, Alberto Lepe <dev@alepe.com> wrote:

> On Thu, Oct 14, 2010 at 2:56 PM, captain_claw <ryanclaw@gmail.com> wrote:
>
>>
>>
>> On Thu, Oct 14, 2010 at 1:08 PM, Alberto Lepe <dev@alepe.com> wrote:
>>
>>> 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
>>>
>>
>> Are those users having problem is in remote office/site? I think even the
>> user's MUA is new you can't tell how the users sent/receive mails. Sent
>> Items (which is 567MB) is only part of the user's pst file (how about the
>> inbox/deleted or other folders the user creates). you can't even know how
>> may email he receives per day which also adds to the size of the pst file.
>> If you want to know about the version of M$ their using then look on the
>> internet headers of an email from the problematics user. (somethig like
>> X-Mailer: Microsoft Outlook Express 6.00.2900.3598/X-Mailer: Microsoft
>> Outlook, Build 10.0.6626).
>>
>>
>> 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)
>> ==============================================================
>>
>> 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
>>
>> I don't see any problem on the logs. the logs in my opinion tells me that
>> queue ID 1748E1CD09 was delivered to your content filter and you content
>> filter give queue ID 62E551CD0B for content checking and removed from queue
>> and delivered to destination (I guess).
>>
>
> Thank you Ryan,
>
> Ok. got it! The client is: Microsoft Outlook Express 6.00.2900.2869
>
> Sorry to ask, but when you say:
>
> > "I don't see any problem on the logs."
> Do you mean:
> a) Logs are fine, the server setup seems fine.
> b) Logs are fine, there is no problem with the email client.
> Sorry, my English is not very good...
>
> The reason why I think the problem is related to the client is that in less
> than 30 minutes nakata@example.com is sending a 4MB file, 12 times to the
> same mailbox: yuuichi@host.co.jp.
> And every time the mail is originated in the client[p2147...] which may
> rule out a problem in the server.
> Is that assumption correct?
>
> A.Lepe
>

I went through other accounts in the same domain and found that there are
other accounts that seems to have the same pattern (even though they haven't
report it yet), in which the same email (same size) is being sent to the
same account in a small period of time. I checked four other domains and I
didn't find that pattern.

The client [p2147...] is actually a smtp proxy server (more specifically a
software proxy, very old, named "Black Jumbo Dog" (it seems it is quite
famous in Japan) see:http://whzat.dyns.net/bjd/mail/index.html), which is
used by all users in the "example.com" domain.

So I think there is a BIG chance that something is going on in that proxy
which is resending the emails several times.

I found a similar problem with other proxy:
http://www.astaro.org/astaro-gateway-products/mail-security-smtp-pop3-antispam-antivirus/17706-many-many-repeated-mails-smtp-proxy.html

I will ask the logs of that proxy to be 100% sure.

A. Lepe