Receiving thousands of cancellation emails

[ncirkel]

Today, one of our users kept receiving the same appointment cancellation via email. Removing from active mail queue did not help, as the email was generated again, restarting Zimbra did help. Lucky me, Zimbra had grouped the messages so I could easily delete them from inbox ,

I have no clue however how this happened and if it will happen again, this does not feel very safe right now.

Any ideas about what might have happened?

Thanks!
Nander

[ncirkel]

This keeps happening, and I don't have a clue why. Here is a recent log fragment (anonimized of course), this is repeated until I reset the server. Any thoughts?

Dec 14 14:25:56 office postfix/smtpd[14831]: connect from substitute.domain.com[xx.xx.xx.xx]
Dec 14 14:25:56 office postfix/smtpd[14831]: CA0172430CF29: client=substitute.domain.com[xx.xx.xx.xx]
Dec 14 14:25:56 office postfix/cleanup[18266]: CA0172430CF29: message-id=<1039918463.3282.1260797156825.JavaMail.root@substitute.domain.com>
Dec 14 14:25:56 office postfix/qmgr[614]: CA0172430CF29: from=<sender@domain.com>, size=117945, nrcpt=1 (queue active)
Dec 14 14:25:56 office postfix/smtpd[14831]: disconnect from substitute.domain.com[xx.xx.xx.xx]
Dec 14 14:25:56 office amavis[17707]: (17707-09) ESMTP::10024 /opt/zimbra/data/amavisd/tmp/amavis-20091214T142411-17707: <sender@domain.com> -> <receiver@domain.com> SIZE=117945 Received: from substitute.domain.com ([127.0.0.1]) by localhost (substitute.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <receiver@domain.com>; Mon, 14 Dec 2009 14:25:56 +0100 (CET)
Dec 14 14:25:57 office amavis[17707]: (17707-09) Checking: z53c4r6bvgYN [xx.xx.xx.xx] <sender@domain.com> -> <receiver@domain.com>
Dec 14 14:25:57 office amavis[17707]: (17707-09) cached 6cc7ad2f71f081fa04467262d91f22d8 from <sender@domain.com> (1,1)
Dec 14 14:25:57 office postfix/smtpd[29981]: connect from localhost.domain.com[127.0.0.1]
Dec 14 14:25:57 office postfix/smtpd[29981]: 31EA024123AB3: client=localhost.domain.com[127.0.0.1]
Dec 14 14:25:57 office postfix/cleanup[18266]: 31EA024123AB3: message-id=<1039918463.3282.1260797156825.JavaMail.root@substitute.domain.com>
Dec 14 14:25:57 office postfix/qmgr[614]: 31EA024123AB3: from=<sender@domain.com>, size=118480, nrcpt=1 (queue active)
Dec 14 14:25:57 office postfix/smtpd[29981]: disconnect from localhost.domain.com[127.0.0.1]
Dec 14 14:25:57 office amavis[17707]: (17707-09) FWD via SMTP: <sender@domain.com> -> <receiver@domain.com>,BODY=7BIT 250 2.0.0 Ok, id=17707-09, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 31EA024123AB3
Dec 14 14:25:57 office amavis[17707]: (17707-09) Passed CLEAN, [xx.xx.xx.xx] [xx.xx.xx.xx] <sender@domain.com> -> <receiver@domain.com>, Message-ID: <1039918463.3282.1260797156825.JavaMail.root@substitute.domain.com>, mail_id: z53c4r6bvgYN, Hits: 4.241, size: 117945, queued_as: 31EA024123AB3, 389 ms
Dec 14 14:25:57 office postfix/smtp[19441]: CA0172430CF29: to=<receiver@domain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.46, delays=0.07/0/0/0.39, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=17707-09, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 31EA024123AB3)
Dec 14 14:25:57 office postfix/qmgr[614]: CA0172430CF29: removed
Dec 14 14:25:57 office postfix/lmtp[17446]: 31EA024123AB3: to=<receiver@domain.com>, relay=substitute.domain.com[xx.xx.xx.xx]:7025, delay=0.25, delays=0.08/0/0/0.17, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)
Dec 14 14:25:57 office postfix/qmgr[614]: 31EA024123AB3: removed
Dec 14 14:25:57 office postfix/smtpd[14684]: connect from substitute.domain.com[xx.xx.xx.xx]
Dec 14 14:25:57 office postfix/smtpd[14684]: 9C9762430CF29: client=substitute.domain.com[xx.xx.xx.xx]
Dec 14 14:25:57 office postfix/cleanup[18266]: 9C9762430CF29: message-id=<922697521.3285.1260797157639.JavaMail.root@substitute.domain.com>
Dec 14 14:25:57 office postfix/qmgr[614]: 9C9762430CF29: from=<sender@domain.com>, size=118050, nrcpt=1 (queue active)
Dec 14 14:25:57 office postfix/smtpd[14684]: disconnect from substitute.domain.com[xx.xx.xx.xx]
Dec 14 14:25:57 office amavis[19208]: (19208-03) ESMTP::10024 /opt/zimbra/data/amavisd/tmp/amavis-20091214T142529-19208: <sender@domain.com> -> <receiver@domain.com> SIZE=118050 Received: from substitute.domain.com ([127.0.0.1]) by localhost (substitute.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <receiver@domain.com>; Mon, 14 Dec 2009 14:25:57 +0100 (CET)
Dec 14 14:25:57 office amavis[19208]: (19208-03) Checking: mxduBkSGD-8I [xx.xx.xx.xx] <sender@domain.com> -> <receiver@domain.com>
Dec 14 14:25:57 office amavis[19208]: (19208-03) cached 6cc7ad2f71f081fa04467262d91f22d8 from <sender@domain.com> (1,1)
Dec 14 14:25:58 office postfix/smtpd[24811]: 1A7F824123AAE: client=localhost.domain.com[127.0.0.1]
Dec 14 14:25:58 office postfix/cleanup[18266]: 1A7F824123AAE: message-id=<922697521.3285.1260797157639.JavaMail.root@substitute.domain.com>
Dec 14 14:25:58 office postfix/qmgr[614]: 1A7F824123AAE: from=<sender@domain.com>, size=118585, nrcpt=1 (queue active)
Dec 14 14:25:58 office amavis[19208]: (19208-03) FWD via SMTP: <sender@domain.com> -> <receiver@domain.com>,BODY=7BIT 250 2.0.0 Ok, id=19208-03, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1A7F824123AAE
Dec 14 14:25:58 office amavis[19208]: (19208-03) Passed CLEAN, [xx.xx.xx.xx] [xx.xx.xx.xx] <sender@domain.com> -> <receiver@domain.com>, Message-ID: <922697521.3285.1260797157639.JavaMail.root@substitute.domain.com>, mail_id: mxduBkSGD-8I, Hits: 4.335, size: 118050, queued_as: 1A7F824123AAE, 364 ms
Dec 14 14:25:58 office postfix/smtp[19441]: 9C9762430CF29: to=<receiver@domain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.55, delays=0.18/0/0/0.36, dsn=2.0.0, status=sent (250 2.0.0 Ok, id=19208-03, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 1A7F824123AAE)
Dec 14 14:25:58 office postfix/qmgr[614]: 9C9762430CF29: removed
Dec 14 14:25:58 office postfix/lmtp[17446]: 1A7F824123AAE: to=<receiver@domain.com>, relay=substitute.domain.com[xx.xx.xx.xx]:7025, delay=0.25, delays=0.07/0/0/0.17, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)
Dec 14 14:25:58 office postfix/qmgr[614]: 1A7F824123AAE: removed

[LMStone]

I understand why you would want to anonymize the logs, but we need more info please:

Are the appointments being canceled all created by one account?

Is the account canceling the appointment the creator?

If both are one and the same it is possible the account has been compromised; suggest changing the password.

If not, then we need to better understand the workflows here leading to these messages.

Hope that helps,
Mark

[ncirkel]

Hi Mark,

Thank you for your reply. Here are some answers.

This is happening for appointments created in different accounts. I think it is happening for all cancelations, the installation is fairly new.

The account canceling the appointment is the creator.

Because of the new install and this happening for different accounts, I don't expect accounts to be compromised.

In more detail, what happens is the following. Someone creates an appointment and shares it with someone else. Invitation mails are sent succesfully. Then, the creator of the appointment deletes the appointment. The invited user then starts receiving cancelation emails. In the quoted log, sender@domain.com is the user creating and deleting the appointment, receiver@domain.com is the invited user.

I hope this helps, I am of course available to perform any specific tests to narrow down the problem.

Thanks,
Nander

[LMStone]

The log file seems fine and I'm not seeing anything in bugzilla for anything like this.

Can't tell if the server is NAT'd or not from the log snippet, but if so, have you double checked that Split DNS is configured correctly?

Split DNS - Zimbra :: Wiki

Hope that helps,
Mark

[ncirkel]

Mark,

I'm not doing any translations, but the server is firewalled. I will configure Split DNS as suggested and let you know what happens.

Thanks for the suggestion.

Nander

[LMStone]

Hold on!

If the server is configured with a public IP address (meaning running ifconfig yields a public IP address) then Split DNS is not for you, and we don't want to make things worse.

I know it's late where you are, so take a break for a moment and let's get back to basics...

Please look through /var/log/zimbra.log and the logs in /opt/zimbra/log and paste any errors or warnings here.

You can also try reindexing this one user's mailbox.

Please also let us know something of your disk subsystem; if there is any sort of corruption here it would be nice to know what might have caused it, and also please confirm this server is physical, not virtual.

OK?

All the best,
Mark

[ncirkel]

Ok, you stopped me right there in the middle of the process

Split DNS sounded reasonable ("Installations of Zimbra behind a firewall often require the creation of some form of split DNS"), but server IP is public and all Zimbra ports accepted by the firewall, so I will take some coffee and try again.

The server is physical, not virtual.

I'm not sure if this is what you would like to see (subsystem), but here is the result of df -h:

Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/sda3            150792704  29806228 120986476  20% /
varrun                 1030748       184   1030564   1% /var/run
varlock                1030748         0   1030748   0% /var/lock
udev                   1030748        32   1030716   1% /dev
devshm                 1030748         0   1030748   0% /dev/shm
/dev/sda2               482246     83272    389014  18% /boot

And volumes from Zimbra console:

Volume name - Volume root path - Volume type - Compress blobs - Compression threshold
index1 - /opt/zimbra/index - Index - No - 4096 bytes
message1 - /opt/zimbra/store - Message - No - 4096 bytes

In zimbra.log, the only errors and warnings are in this fragment, don't thinks it's related, user@domain.com is recipient for the repeating mails.

Dec 14 14:25:02 office postfix/smtpd[18632]: connect from unknown[xx.xx.xx.xx]
Dec 14 14:25:03 office saslauthd[579]: zmauth: authenticating against elected url 'https://example.domain.com:7071/service/admin/soap/' ...
Dec 14 14:25:03 office saslauthd[579]: zmpost: url='https://example.domain.com:7071/service/admin/soap/' returned buffer->data='<soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope"><soap:Header><context xmlns="urn:zimbra"/></soap:Header><soap:Body><soap:Fault><soap:Code><soap:Value>soap:Sender</soap:Value></soap:Code><soap:Reason><soap:Text>authentication failed for user@domain.com</soap:Text></soap:Reason><soap:Detail><Error xmlns="urn:zimbra"><Code>account.AUTH_FAILED</Code><Trace>btpool0-0:https://xx.xx.xx.xx:7071/service/admin/soap/:1260797103657:a718034971e76858</Trace></Error></soap:Detail></soap:Fault></soap:Body></soap:Envelope>', hti->error=''
Dec 14 14:25:03 office saslauthd[579]: auth_zimbra: user@domain.com auth failed: authentication failed for user@domain.com
Dec 14 14:25:03 office saslauthd[579]: do_auth         : auth failure: [user=user@domain.com] [service=smtp] [realm=triplesconsultancy.com] [mech=zimbra] [reason=Unknown]
Dec 14 14:25:03 office postfix/smtpd[18632]: warning: SASL authentication failure: Password verification failed
Dec 14 14:25:03 office postfix/smtpd[18632]: warning: unknown[xx.xx.xx.xx]: SASL PLAIN authentication failed: authentication failure
Dec 14 14:25:03 office postfix/smtpd[18632]: lost connection after AUTH from unknown[xx.xx.xx.xx]
Dec 14 14:25:03 office postfix/smtpd[18632]: disconnect from unknown[xx.xx.xx.xx]
Dec 14 14:25:04 office postfix/smtpd[18632]: connect from unknown[xx.xx.xx.xx]

Browsed all relevant logs in /opt/zimbra/log (I think...), no warnings, errors or inregularities there.

Btw, I'm a bit surprised that this is the only problem so far, mails for inviting people are sent correct, all other email traffic works without problems...

Appreciate your help a lot!
Nander

[LMStone]

Hope there's a little extra something in your coffee there!

Here's how I'm looking at this now:

1. The server has been working fine so far.
2. This bizarre problem crops up impacting just one user.
3. The problem seems to be mailbox related, as Zimbra can't get a clue that the cancellation notice has already been sent so it keeps trying.
4. I have never seen anything like this before, and don't see anything like this in the forums or in bugzilla.
5. Your Zimbra system would be appear (without confirming everything) likely to be configured OK.
6. The sysadmin of the Zimbra system seems competent and detail oriented, so he has likely not done something wacky to the Zimbra installation he's not telling me about! ;-)

So, on the presumption that something in this one user's mailbox got borked, the first step is to make sure the mailbox is OK. To do that, I'd suggest reindexing the user's mailbox from the admin console, and see what the logs say about that.

The next step is to try to get an idea what may have caused this issue in the first place, and being a bit of a hardware geek I tend to think first (after the Zimbra config itself checks out OK) of things like a sub-par disk system, using NFS for MySQL databases and other risky behaviors, hence my questions about the disk subsystem as a start to try to probe in this area. Any chance there is some weak or less-than-desirable hardware here that could be the root cause?

So let's try the mailbox reindex (AFTER you check you have good backups!) and let us know what happens.

S'OK?

All the best,
Mark

[ncirkel]

New morning here... fresh backups this night... going for a reindex now. Will let you know what happens!