Re: env_from set to <> after Z action

> Ned Freed wrote:
> > I'm more suspicious that the message didn't have an envelope from to begin 
> > with.

> No, it didn't.  Here are the [sanitized] logs:

I'm afraid these logs are so incomplete it's very difficult to tell what's
going on. And this has nothing to do with the sanitization - you have focused
on a single recipient address, with the result that we cannot see other
recipients handling for the same message. Even more important, we cannot be
sure if all of this actually all relates to the same message since you're not
logging filename or process information.

> here is the log of the normal enqueue:

> 21-Jun-2008 06:11:11.92 tcp_intranet avs          EE 6
> LOCALUSER-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx 
> rfc822;REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx
> REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx 
> <e53191252b2e.485cefe0-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx> mailsrv
> LOCAL.DOMAIN (STORE.LOCAL.DOMAIN [1.2.3.4])

> 21-Jun-2008 06:11:14.01 avs          tcp_local    E 7
> LOCALUSER-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx 
> rfc822;REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx
> REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx 
> <e53191252b2e.485cefe0-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx> mailsrv
> avs-daemon.MTA.LOCAL.DOMAIN

> 21-Jun-2008 06:11:14.11 avs                       D 6
> LOCALUSER-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx 
> rfc822;REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx
> REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx 
> <e53191252b2e.485cefe0-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx> mailsrv

OK, so here we see a message come in from some local system, get sent to avs
which I presume is some kind of antispam/antivirus scanner, which then
apparently turns right around and sends it back. Once it has come back we then
see the initial copy being dequeued.

> here's the enqueue of the rewritten form of the message:

> 21-Jun-2008 06:11:16.09 avs          tcp_local    E 7
> rfc822;REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx 
> REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx
> <e53191252b2e.485cefe0-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx> mailsrv 
> avs-daemon.MTA.LOCAL.DOMAIN

It isn't clear if this is a different message or not and it won't be unless you
start logging filenames. if we assume this is the same message, this would
correspond to the requeue as a result of a 4xy error, and it does appear that
the envelope from is not present.

> here is the Z rejection of the original form of the message:

> 21-Jun-2008 06:11:16.09 tcp_local                 ZE 7
> LOCALUSER-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx 
> rfc822;REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx
> REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx 
> <e53191252b2e.485cefe0-F1FbuMAf82JPjaDqJt1ogQ@xxxxxxxxxxxxxxxx> mailsrv
> REMOTE.DOMAIN dns;REMOTE.DOMAIN (TCP|2.3.4.5|59912|3.4.5.6|25)
> (REMOTE.SERVER ESMTP **************************) smtp;552
> <REMOTEUSER-RKDGOo/4GHQ9E24vwMF+KA@xxxxxxxxxxxxxxxx>: Recipient address 
> rejected: 5.2.2 Over quota

The timestamp being exactly the same as the preceeding E entry makes it pretty
likely that this is corresponds to the same message as the previous E entry.
However, the interesting thing here is that Z records are actually written by
the dequeue routines, which have their own separate copy of the envelope from
address taken straight from the queue file and never modified in any way. (More
precisely, there are actually multiple copies of the envelope from address even
at this level: One for the dequeue routines as a whole and one per recipient in
the data structure corresponding to a log entry. And all of these copies are
made before passing the information to the SMTP client.) As a result even if
the reenqueue process managed to lose the address somehow that cannot possibly
affect what ends up in the Z record.

And the chances of some sort of corruption or locking problem managing to
corrupt two different storage areas in exactly the same way and in the process
not touching any of the literally hundreds of adjacent fields (which if done 
would be pretty much guaranteed to cause a crash) is, well, remote. (You could
also check what's in the D record for the recipient that made it through. If it
also shows an empty envelope from - and I bet it will since it comes from the
same place as the Z record - you're now talking about corruption striking three
different places in memory that happen to have copies of the same bit of
information. The chances of that are way beyond remote.)

So could the address be lost by the dequeue routines themselves? This is 
theoretically possible, but now you're talking about code that is used for
literally every message that's ever dequeued, never mind all of the Z record
stuff. The chances of a bug in this code that has remained undiscovered for
literally 20 years and only happens when Z records are written in this one case
are again more than remote. It's preposterously unlikely.

So what does all this mean? Is means that far and away the most likely
explanation here is that the queue entry on disk didn't have an envelope from
address to begin with.

And given that the initial enqueue shown by these log entries does have an
envelope from address, does this mean that it is likely we're dealing two
different messages here? The answer, quite surprisingly, is no. It turns that
in most cases the envelope from logged in E (and V) records is the original
envelope from on the incoming message, not the rewritten one that's actually
associated with the queue entry the log record describes, the one exception
being E records for the bitbucket channel. 

I think what happened is that something went wonky in your rewriting process
and turned the envelope from into an empty string. (This could even be an LDAP
glitch of some kind.) And since this stuff is cached pretty aggressively, it
ended up affecting some set of messages. And then for whatever reason the
problem went away.

> > But the only way to figure out what's happening is to get some
> > debugging going.

> I can't simulate it.  I tried using the same recipient address, using
> the same production server environment.

Creating condiitions under which a Z record gets written is actually not that
complicated. All you need to do is set up two recipients on  some system
somewhere, one of which works and the other is over quota or has some other
problemn that results in a 4xy error. Then send a single message from another
to both recipients on this system. The sending system should end up with a Z
record.

> This happened when one of our local user accounts was compromised by a
> spammer and used to send thousands of messages out via our webmail
> interface.  The vast majority of the queued messages had the env_from
> set to the original address.  Around 100 had the env_from set to <>.

And if during all this the LDAP entry for the user got messed up, that would
explain this.

                                Ned