problem confirming delivery of a deferred message in PostFix logs

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

problem confirming delivery of a deferred message in PostFix logs

pandorasbox55
We have recently begun using PostFix to replace one of our legacy systems. For the most part, the system appears to be running fine under load. Recently we have begun seeing some sporadic delivery errors. One error in particular is hard to trace back to its original message and confirm that the message was delivered. 

The error we see in the logs looks like: 

Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: ldap:/etc/postfix/ldap-aliases.cf lookup error for "redacted@domain"
Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: 745EC6AC49: virtual_alias_maps map lookup problem for redacted@domain -- deferring delivery

We also receive an email with this content: 
===========
Transcript of session follows.

Out: 220 redactedServer ESMTP Postfix
In:  EHLO redacted2Server
Out: 250-redactedServer
Out: 250-PIPELINING
Out: 250-SIZE 36700160
Out: 250-VRFY
Out: 250-ETRN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In:  MAIL From:<redacted@domain> SIZE=1302
Out: 250 2.1.0 Ok
In:  RCPT To:<redacted@domain>
Out: 250 2.1.5 Ok
In:  DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error
In:  QUIT
Out: 221 2.0.0 Bye


For other details, see the local mail logfile
=======

Emails sent to the same user, before and after this error occurs, are delivered without issue. We have three questions regarding this issue: 

1 If we search for the message ID that is included in the error in the logs, in this case 745EC6AC49, it doesn't appear to pull any log data on the original email. We can search for emails to that the same recipient, with the same sender, and confirm that a message was delivered. However, in some cases the person receives multiple messages from the same sender so it is hard to determine if we are seeing the original message being delivered or not. Is there some additional logging we could turn on so we could definitively confirm the delivery of the deferred email? 

2 Since emails before and after the errors are delivered properly, we believe the issue might be caused by a timeout/network interruption of some sort between the server and the LDAP it is checking for address lookups. Is there a logging parameter we can use to gather more data specifically on this type of connection issue? 

3 Because we're still moving into our PostFix environment, the system is set to soft bounce. When we turn that off, if the system has an error of this type, will it still defer the message or will this type of error generate a permanent failure at that time? 

tia, 
=lc
Reply | Threaded
Open this post in threaded view
|

Re: problem confirming delivery of a deferred message in PostFix logs

Wietse Venema
l carr:
> Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: ldap:/etc/postfix/ldap-aliases.cf lookup error for "redacted@domain"
> Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: 745EC6AC49: virtual_alias_maps map lookup problem for redacted@domain -- deferring delivery

And:

> In:  DATA
> Out: 354 End data with <CR><LF>.<CR><LF>
> Out: 451 4.3.0 Error: queue file write error

The mail delivery transaction failed due to some LDAP error, therefore
Postfix replied with a 451 (try again alter) status. Postfix removed
the queue file because the transaction failed. This is how SMTP works.

It's up to system administrator to fix the LDAP error, and it is
up to the client to resend the message.

To fix the LDAP error, I suggest that you use "proxy:ldap:" instead
of "ldap:". This reduces the number of concurrent connections to the
LDAP server.

As the error message says, "deferring delivery", this will defer
delivery (the soft-bounce safety net is implemented elsewhere).

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: problem confirming delivery of a deferred message in PostFix logs

pandorasbox55
Thanks for the suggestion on using proxy:ldap, we will look into that. We already believed the LDAP error was an issue at the LDAP side, or communication to the LDAP server, and not an issue with how Postfix was working. We were just trying to get a little more information on what Postfix was seeing when it connected to the LDAP, to assist with troubleshooting on the LDAP side. (thus the LDAP log question.) 

Our other question is there a way to link the error message in the logs to the original message that was deferred. (Even if it requires turning on additional logging.) 

As it is logged currently, there doesn't appear to be a unique value that we could key on that is provided in both the error log entry and the message log entry.  So we can only 'assume' the message was re-delivered successfully by searching the logs for an email from the same sender, to the same recipient, after the error occurred. 

As for the actual error transaction itself,

> In:  DATA
> Out: 354 End data with <CR><LF>.<CR><LF>
> Out: 451 4.3.0 Error: queue file write error

that all makes perfect sense to us. 

And thanks for confirming that the error will continue to be treated as a temp fail even when we remove the soft bounce. 

many thanks again, 
=lc 

From: [hidden email] <[hidden email]> on behalf of Wietse Venema <[hidden email]>
Sent: Wednesday, March 28, 2018 8:55 AM
To: Postfix users
Subject: Re: problem confirming delivery of a deferred message in PostFix logs
 
l carr:
> Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: ldap:/etc/postfix/ldap-aliases.cf lookup error for "redacted@domain"
> Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: 745EC6AC49: virtual_alias_maps map lookup problem for redacted@domain -- deferring delivery

And:

> In:  DATA
> Out: 354 End data with <CR><LF>.<CR><LF>
> Out: 451 4.3.0 Error: queue file write error

The mail delivery transaction failed due to some LDAP error, therefore
Postfix replied with a 451 (try again alter) status. Postfix removed
the queue file because the transaction failed. This is how SMTP works.

It's up to system administrator to fix the LDAP error, and it is
up to the client to resend the message.

To fix the LDAP error, I suggest that you use "proxy:ldap:" instead
of "ldap:". This reduces the number of concurrent connections to the
LDAP server.

As the error message says, "deferring delivery", this will defer
delivery (the soft-bounce safety net is implemented elsewhere).

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: problem confirming delivery of a deferred message in PostFix logs

/dev/rob0
On Wed, Mar 28, 2018 at 02:16:47PM +0000, l carr wrote:
> Our other question is there a way to link the error message in
> the logs to the original message that was deferred.

The queue ID is always logged after it has been assigned.  Also set
    enable_long_queue_ids = yes
in any supported Postfix version, to ensure that queue IDs are
unique.

> (Even if it requires turning on additional logging.)

No, don't do that.

> As it is logged currently, there doesn't appear to be a unique
> value that we could key on that is provided in both the error log
> entry and the message log entry.  So we can only 'assume' the

> > Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: ldap:/etc/postfix/ldap-aliases.cf lookup error for "redacted@domain"
> > Mar 27 16:20:54 redactedServer postfix/cleanup[24237]: warning: 745EC6AC49: virtual_alias_maps map lookup problem for redacted@domain -- deferring delivery

The first line isn't really specific to queue ID 745EC6AC49, but the
following line mentions it.  You could grep 745EC6AC49, but the best
choice is usually to use a pager like less, and search using its
search function.

If/when 745EC6AC49 is finally delivered or permanently bounced for
some reason such as maximal_queue_lifetime, the queue ID will be
mentioned in logs describing the final disposition.
--
  http://rob0.nodns4.us/
  Offlist GMX mail is seen only if "/dev/rob0" is in the Subject:
Reply | Threaded
Open this post in threaded view
|

Re: problem confirming delivery of a deferred message in PostFix logs

Viktor Dukhovni


> On Mar 28, 2018, at 1:15 PM, /dev/rob0 <[hidden email]> wrote:
>
> If/when 745EC6AC49 is finally delivered or permanently bounced for
> some reason such as maximal_queue_lifetime, the queue ID will be
> mentioned in logs describing the final disposition.

The queue file was deleted when virtual expansion failed, so
there'll be no further mention of that queue-id.  The message
will be resent by the client, and will get a new queue-id at
that time.

--
        Viktor.