Message disappears between MTA and mailbox server

[andrew_l]

This is probably the weirdest thing I've seen since we started using Zimbra 6 months ago. It's not a widespread problem; I got a specific report that a user was not receiving mail from a particular listserv. So I got a date and time when a message was sent and traced the logs from our mailman server, to the MTA, to the mailbox server...except there wasn't anything logged on the mailbox server for this recipient.

Here is a log sample from the MTA. I generated this by grepping on the ID ("5079E6204CA"). I have anonymized the addresses but otherwise changed nothing:

Dec 2 16:55:01 shiva postfix/smtpd[7885]: 5079E6204CA: client=localhost.localdomain[127.0.0.1]
Dec 2 16:55:01 shiva postfix/cleanup[6801]: 5079E6204CA: message-id=<432381256.2072651228253326164.JavaMail.root@ga nesh.example.com>
Dec 2 16:55:01 shiva postfix/qmgr[31256]: 5079E6204CA: from=<listserv-bounces@example.com>, size=6168, nrcpt=6 (queue active)
Dec 2 16:55:01 shiva postfix/smtp[11982]: 2E1456203EC: to=<outside-forwarded-address@example2.com>, orig_to=<user2@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.16, delays=0.05/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5079E6204CA)
Dec 2 16:55:01 shiva postfix/smtp[11982]: 2E1456203EC: to=<user1@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.16, delays=0.05/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5079E6204CA)
Dec 2 16:55:01 shiva postfix/smtp[11982]: 2E1456203EC: to=<user2@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.16, delays=0.05/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5079E6204CA)
Dec 2 16:55:01 shiva postfix/smtp[11982]: 2E1456203EC: to=<user3@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.16, delays=0.05/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5079E6204CA)
Dec 2 16:55:01 shiva postfix/smtp[11982]: 2E1456203EC: to=<user4@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.16, delays=0.05/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5079E6204CA)
Dec 2 16:55:01 shiva postfix/smtp[11982]: 2E1456203EC: to=<user5@example.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.16, delays=0.05/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5079E6204CA)
Dec 2 16:55:04 shiva postfix/lmtp[1763]: 5079E6204CA: to=<user1@example.com>, relay=zmailbox.example.com[<ip removed>]:7025, delay=3, delays=0.01/0.01/0/2.9, dsn=2.1.5, status=sent (250 2.1.5 OK)
Dec 2 16:55:04 shiva postfix/lmtp[1763]: 5079E6204CA: to=<user2@example.com>, relay=zmailbox.example.com[<ip removed>]:7025, delay=3, delays=0.01/0.01/0/2.9, dsn=2.1.5, status=sent (250 2.1.5 OK)
Dec 2 16:55:04 shiva postfix/lmtp[1763]: 5079E6204CA: to=<user3@example.com>, relay=zmailbox.example.com[<ip removed>]:7025, delay=3, delays=0.01/0.01/0/2.9, dsn=2.1.5, status=sent (250 2.1.5 OK)
Dec 2 16:55:04 shiva postfix/lmtp[1763]: 5079E6204CA: to=<user4@example.com>, relay=zmailbox.example.com[<ip removed>]:7025, delay=3, delays=0.01/0.01/0/2.9, dsn=2.1.5, status=sent (250 2.1.5 OK)
Dec 2 16:55:04 shiva postfix/lmtp[1763]: 5079E6204CA: to=<user5@example.com>, relay=zmailbox.example.com[<ip removed>]:7025, delay=3, delays=0.01/0.01/0/2.9, dsn=2.1.5, status=sent (250 2.1.5 OK)
Dec 2 16:55:06 shiva postfix/smtp[11757]: 5079E6204CA: to=<outside-forwarded-address@example2.com>, relay=mta.example2.com[<ip removed>]:25, delay=5.4, delays=0.01/0.01/5.3/0.14, dsn=2.0.0, status=sent (250 2.0.0 mB2Lt6cD003232 Message accepted for delivery)
Dec 2 16:55:06 shiva postfix/qmgr[31256]: 5079E6204CA: removed


So, the original message had 5 recipients, one had a forward set to an outside account, so nrcpt=6. The forwarded message was passed to the outside account, and the other 5 are passed on to our mailbox server. So far, so good. Now, we look at the mailbox server mailbox.log. I generated this by grepping on the LmtpServer id ("LmtpServer-88936") that handled this message:

2008-12-02 16:55:01,389 INFO [LmtpServer-88936] [ip=<ip removed>;] lmtp - Delivering message: size=6168 bytes, nrcpts=5, sender=listserv-bounces@example.com, msgid=<432381256.2072651228253326164.JavaMail.root @ganesh.example.com>
2008-12-02 16:55:01,391 INFO [LmtpServer-88936] [name=user1@example.com;mid=5375;] mailop - Adding Message: id=3235, Message-ID=<432381256.2072651228253326164.JavaMail.root@ga nesh.example.com>, parentId=-1, folderId=2, folderName=Inbox.
2008-12-02 16:55:02,361 INFO [LmtpServer-88936] [] lmtp - accepted and discarded message for user2@example.com: local delivery is disabled
2008-12-02 16:55:02,362 INFO [LmtpServer-88936] [name=user3@example.com;mid=5637;] mailop - Adding Message: id=1352, Message-ID=<432381256.2072651228253326164.JavaMail.root@ga nesh.example.com>, parentId=-1, folderId=2, folderName=Inbox.
2008-12-02 16:55:03,393 INFO [LmtpServer-88936] [name=user5@example.com;mid=2524;] mailop - Adding Message: id=7914, Message-ID=<432381256.2072651228253326164.JavaMail.root@ga nesh.example.com>, parentId=-1, folderId=2, folderName=Inbox.
2008-12-02 16:55:04,296 INFO [LmtpServer-88936] [] ProtocolHandler - Handler exiting normally


So here's the burning question: What happened to the message for user4@example.com? The mailbox server still shows nrcpts=5, but it only attempts to deliver to 4 users! There is no error message or anything for user4@example.com.

Any ideas?

-Andrew L

[uxbod]

Have a look before the LMTP entries to see what Postfix and Amavis did with them prior to being sent onto the mailboxes.

[andrew_l]

Wouldn't all the postfix and amavis activity take place on the MTA rather than on the mailbox server? The first chunk of logs I posted came from the MTA (our MTAs are separate from our mailbox server). That MTA log seems to show the messages being handed off to the mailbox server.

-Andrew L

[uxbod]

Have a look on your mailbox server in /opt/zimbra/logs and see what mailbox.log says. Make sure there is not another error somewhere.

[andrew_l]

The second log chunk I posted is from the mailbox.log. I got that one by looking through and finding the name of the LmtpServer thread that seemed to have handled this message, and grepping on that. I also tried grepping on the username, which got me nothing (no entries for that user around the time this message came through). Any other patterns that you can think of that I should try grepping on? Otherwise I would have to go through the mailbox.log line-by-line. Thanks,

-Andrew L

[Jesster]

One time I was troubleshooting a similar issue, and I realized that the mailstore java/lmtp process wouldn't deliver some messages (even thought my external MTA's accepted them).

In our case, the problem was the recipients already had matching emails in their mailbox (or more specifically, matching/duplicate Message-ID)

[andrew_l]

I've seen that before too, but it's always logged a "Not delivering message with duplicate Message-ID" error in the mailbox.log. There is no such error for the user in question in the whole day's log. Have you seen cases where it did this without logging the error?

-Andrew L

[Jesster]

Originally Posted by andrew_l

I've seen that before too, but it's always logged a "Not delivering message with duplicate Message-ID" error in the mailbox.log. There is no such error for the user in question in the whole day's log. Have you seen cases where it did this without logging the error?

-Andrew L

You're right, i should have also noted that mailbox.log does log the duplicate. Ofcourse, on a very active system, it's easy to miss the first dozen times (in my case)

The only other case of a missing email I've worked on related to Amavis rejecting emails with password protected files (excel/word?) I can't remember the details. There was a Zimbra option to disable that Amavis setting, which fixed it for us.

Update: The Amavis Option I mention above is zimbraVirusBlockEncryptedArchive (global option) - in the UI it says "Block encrypted archives"

[ArcaneMagus]

If that was the issue though it would affect all the users on the zimbra server....not just the one that isn't getting the mail.

If you can repeat this problem try running a tcpdump on the loopback interface as I believe this will catch the communication between the processes and might reveal some issue not shown in the logs (just guessing here but it might help).

[d-petro]

I just ran across this, and it turned out to be a filter setup on the receiving users' mailbox. Simple solution, but more explicit log messages in a more commonly viewed log would be appreciated.