queue manager delaying delivery of message

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

queue manager delaying delivery of message

George Forman
Hi,

I am running into a problem where (it seems) queue manager
doesn't pickup the queued message for delivery.  SMTPD returns
a 250 OK at 16:26:39. However, oqmgr doesn't pick it up until 16:35:41.
The is no post queue processing on the message.  I turned up logging
on cleanup, qmgr and oqmgr (see below). I could not find any clues
as to why there would be a delay. Any help is greatly appreciated.  - George

Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: open incoming/883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: cleanup_open: open incoming/883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: send attr queue_id = 883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/smtpd[28280]: input attribute value: 883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/smtpd[28280]: 883D938000CBB: client=mx2.todaysdailypromotion.net[11.111.111.111]
Dec 14 16:26:39 mtain-da12 postfix/smtpd[28280]: milter_macro_lookup: result "883D938000CBB"
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: cleanup_header_callback: 'Received: from mx2.todaysdailypromotion.net (mx2.todaysdailypromotion.net [66.248.158.200])??by mtain-da12.example.com (Internet Inbound) with SMTP id 883D938000CBB??for <[hidden email]>; Mon, 1'
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: 883D938000CBB: message-id=<[hidden email]>
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: milter_macro_lookup: result "883D938000CBB"
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: milter_macro_lookup: result "883D938000CBB"
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_HEADER; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_EOH; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_BODY; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/cleanup[28236]: event: SMFIC_BODYEOB; macros: i=883D938000CBB
Dec 14 16:26:39 mtain-da12 postfix/smtpd[28280]: > mx2.todaysdailypromotion.net[11.111.111.111]: 250 2.0.0 Ok: queued as 883D938000CBB
Dec 14 16:35:41 mtain-da12 postfix/oqmgr[32135]: 883D938000CBB: from=<[hidden email]>, size=2598, nrcpt=1 (queue active)
Dec 14 16:35:41 mtain-da12 postfix/smtp[32446]: 883D938000CBB: to=<[hidden email]>, relay=relay.example.com[111.11.111.11]:25, delay=542, delays=542/0.03/0/0.15, dsn=2.0.0, status=sent (250 OK)
Dec 14 16:35:41 mtain-da12 postfix/oqmgr[32135]: 883D938000CBB: removed





postconf -n below:

2bounce_notice_recipient = /dev/null
bounce_notice_recipient = /dev/null
bounce_queue_lifetime = 4h
bounce_size_limit = 1
bounce_template_file = $config_directory/bounce.cf
command_directory = /opt/postfix/sbin
config_directory = /opt/postfix/conf
daemon_directory = /opt/postfix/libexec
data_directory = /opt/postfix/data
debug_peer_level = 2
default_destination_concurrency_limit = 500
default_rbl_reply = $rbl_code : (RLY:B1) http://postmaster.example.com/errors/554rlyb1.html
delay_notice_recipient = /dev/null
disable_vrfy_command = yes
empty_address_recipient = MAILER-DAEMON
error_notice_recipient = /dev/null
html_directory = no
lmtp_destination_concurrency_limit = 1200
local_recipient_maps = proxy:ldap:$config_directory/ldap-vam.cf
mail_name = Internet Inbound
mail_owner = postfix
mailq_path = /opt/postfix/sbin/mailq
manpage_directory = /opt/postfix/man
maximal_queue_lifetime = 1d
message_size_limit = 23000000
milter_connect_macros = j {daemon_name} v {client_name} {client_ptr}
milter_protocol = 2
mydestination =
mynetworks = $config_directory/mynetworks
myorigin = example.com
newaliases_path = /opt/postfix/sbin/newaliases
notify_classes =
qmgr_message_active_limit = 100000
qmgr_message_recipient_limit = 100000
queue_directory = /postfix/mqueues/spool
rbl_reply_maps = hash:$config_directory/rbl_reply_maps
readme_directory = no
recipient_canonical_maps = hash:$config_directory/recipient_canonical_maps
relay_domains = $config_directory/relay_domains
relay_recipient_maps = hash:$config_directory/relay_recipient_maps
sample_directory = /opt/postfix/conf
sender_dependent_relayhost_maps = hash:$config_directory/sender_dependent_relayhost_maps
sendmail_path = /opt/postfix/sbin/sendmail
setgid_group = postdrop
smtpd_client_restrictions = reject_unauth_pipelining,     reject_rbl_client dnsbl.example.com=127.0.0.2,     reject_rbl_client dnsbl2.example.com=127.0.0.11,     reject_rbl_client dnsbl3.example.com=127.0.0.10,     reject_rbl_client dnsbl4.example.com=127.0.0.12,     reject_rbl_client dnsbl5.example.com
smtpd_data_restrictions = reject_unauth_pipelining
smtpd_delay_reject = no
smtpd_etrn_restrictions = reject
smtpd_helo_required = yes
smtpd_helo_restrictions =
smtpd_milters = inet:localhost:12345
smtpd_null_access_lookup_key = <>
smtpd_recipient_limit = 100
smtpd_recipient_restrictions = reject_unknown_recipient_domain,      reject_non_fqdn_recipient,      permit_mynetworks,      reject_unauth_destination,      reject_invalid_hostname,      permit
smtpd_sender_restrictions = reject_non_fqdn_sender      reject_unknown_sender_domain
transport_maps = hash:$config_directory/transport_maps           proxy:ldap:$config_directory/ldap-transport.cf                 regexp:$config_directory/transport_maps-reserved
unknown_local_recipient_reject_code = 550
virtual_alias_maps = hash:$config_directory/virtual_alias_maps               proxy:ldap:$config_directory/ldap-vam.cf
virtual_mailbox_domains = $config_directory/virtual_mailbox_domains,                      proxy:ldap:$config_directory/ldap-vmd.cf
virtual_transport = error




Hotmail: Free, trusted and rich email service. Get it now.
Reply | Threaded
Open this post in threaded view
|

Re: queue manager delaying delivery of message

Wietse Venema
The queue manager will leave a file in the incoming queue when:

1) Some "security" software does not allow the cleanup daemon
to write to the qmgr FIFO. Try without SeLinux, AppArmor, etc.

2) The queue file system is not on a local disk, and either file
server's clock and the Postfix machine's clock are out of whack.

3) Mailscanner or other non-Postfix software directly manipulates
Postfix queue files.

4) The file system does weird things with the "execute" file
permission bit. Postfix sets this bit when a queue file is ready
for delivery.

5) The queue manager is blocked for other reasons. Some vendors
make changes to Postfix source code and thereby break things.

To investigate, does the delay happen with local submission
(the Postfix sendmail command)?

You wrote that you made the queue manager verbose, but there is
no verbose queue manager logging in your report.

        Wietse
Reply | Threaded
Open this post in threaded view
|

RE: queue manager delaying delivery of message

George Forman
> Subject: Re: queue manager delaying delivery of message

> To: [hidden email]; [hidden email]
> Date: Mon, 14 Dec 2009 19:31:44 -0500
> From: [hidden email]
>
> The queue manager will leave a file in the incoming queue when:
>
> 1) Some "security" software does not allow the cleanup daemon
> to write to the qmgr FIFO. Try without SeLinux, AppArmor, etc.
>
> 2) The queue file system is not on a local disk, and either file
> server's clock and the Postfix machine's clock are out of whack.
>
> 3) Mailscanner or other non-Postfix software directly manipulates
> Postfix queue files.
>
> 4) The file system does weird things with the "execute" file
> permission bit. Postfix sets this bit when a queue file is ready
> for delivery.
>
> 5) The queue manager is blocked for other reasons. Some vendors
> make changes to Postfix source code and thereby break things.
>
> To investigate, does the delay happen with local submission
> (the Postfix sendmail command)?
>
We are trying to replace our inbound MTA.  Because of the
problems encountered, we brought down the server.
I will try this tomorrow and report back with the results.

> You wrote that you made the queue manager verbose, but there is
> no verbose queue manager logging in your report.

Unfortunately, I don't know how to associate the queue manager's
output with respect to the email message queue id. The log file is
huge, I will see if I can find the logs entries and included them.

Thanks for the information,
George




Your E-mail and More On-the-Go. Get Windows Live Hotmail Free. Sign up now.
Reply | Threaded
Open this post in threaded view
|

Re: queue manager delaying delivery of message

Wietse Venema
George Forman:

>
> > Subject: Re: queue manager delaying delivery of message
> > To: [hidden email]; [hidden email]
> > Date: Mon, 14 Dec 2009 19:31:44 -0500
> > From: [hidden email]
> >
> > The queue manager will leave a file in the incoming queue when:
> >
> > 1) Some "security" software does not allow the cleanup daemon
> > to write to the qmgr FIFO. Try without SeLinux, AppArmor, etc.
> >
> > 2) The queue file system is not on a local disk, and either file
> > server's clock and the Postfix machine's clock are out of whack.
> >
> > 3) Mailscanner or other non-Postfix software directly manipulates
> > Postfix queue files.
> >
> > 4) The file system does weird things with the "execute" file
> > permission bit. Postfix sets this bit when a queue file is ready
> > for delivery.
> >
> > 5) The queue manager is blocked for other reasons. Some vendors
> > make changes to Postfix source code and thereby break things.
> >
> > To investigate, does the delay happen with local submission
> > (the Postfix sendmail command)?
> >
> We are trying to replace our inbound MTA.  Because of the
> problems encountered, we brought down the server.
> I will try this tomorrow and report back with the results.
>
> > You wrote that you made the queue manager verbose, but there is
> > no verbose queue manager logging in your report.
>
> Unfortunately, I don't know how to associate the queue manager's
> output with respect to the email message queue id. The log file is
> huge, I will see if I can find the logs entries and included them.

Don't bother, you have no idea what records are triggered
by cleanup server activity.

The queue manager handles other deliveries while it is ignoring
this file? The cleanup server attempts to write to the qmgr FIFO,
and the queue manager will log that it receives a request.

Dec 14 20:04:13 tail postfix/qmgr[2053]: trigger_server_accept_fifo: trigger arrived

If there is no such logging then the cleanup-to-qmgr notification
is broken, and delivery is delayed until the queue manager does
the routine queue_run_delay=300s queue scan.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: queue manager delaying delivery of message

lst_hoe02
In reply to this post by George Forman
Zitat von George Forman <[hidden email]>:

>
> Hi,
>
> I am running into a problem where (it seems) queue manager
> doesn't pickup the queued message for delivery.  SMTPD returns
> a 250 OK at  16:26:39. However, oqmgr doesn't pick it up until 16:35:41.
> The is no post queue processing on the message.  I turned up logging
> on cleanup, qmgr and oqmgr (see below). I could not find any clues
> as to why there would be a delay. Any help is greatly appreciated.  - George

Why do you run oqmgr instead of the default qmgr?? I hope you don't  
try to run both of them. Can you show master.cf additionally?

Regards

Andreas


smime.p7s (8K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

RE: queue manager delaying delivery of message

George Forman
In reply to this post by Wietse Venema

> Subject: Re: queue manager delaying delivery of message
> To: [hidden email]
> Date: Mon, 14 Dec 2009 20:08:41 -0500
> From: [hidden email]
>
> George Forman:
> >
> > > Subject: Re: queue manager delaying delivery of message
> > > To: [hidden email]; [hidden email]
> > > Date: Mon, 14 Dec 2009 19:31:44 -0500
> > > From: [hidden email]
> > >
> > > The queue manager will leave a file in the incoming queue when:
> > >
> > > 1) Some "security" software does not allow the cleanup daemon
> > > to write to the qmgr FIFO. Try without SeLinux, AppArmor, etc.
> > >
> > > 2) The queue file system is not on a local disk, and either file
> > > server's clock and the Postfix machine's clock are out of whack.
> > >
> > > 3) Mailscanner or other non-Postfix software directly manipulates
> > > Postfix queue files.
> > >
> > > 4) The file system does weird things with the "execute" file
> > > permission bit. Postfix sets this bit when a queue file is ready
> > > for delivery.
> > >
> > > 5) The queue manager is blocked for other reasons. Some vendors
> > > make changes to Postfix source code and thereby break things.
> > >
> > > To investigate, does the delay happen with local submission
> > > (the Postfix sendmail command)?
> > >
> > We are trying to replace our inbound MTA. Because of the
> > problems encountered, we brought down the server.
> > I will try this tomorrow and report back with the results.
> >
> > > You wrote that you made the queue manager verbose, but there is
> > > no verbose queue manager logging in your report.
> >
> > Unfortunately, I don't know how to associate the queue manager's
> > output with respect to the email message queue id. The log file is
> > huge, I will see if I can find the logs entries and included them.
>
> Don't bother, you have no idea what records are triggered
> by cleanup server activity.
>
> The queue manager handles other deliveries while it is ignoring
> this file? The cleanup server attempts to write to the qmgr FIFO,
> and the queue manager will log that it receives a request.
>
> Dec 14 20:04:13 tail postfix/qmgr[2053]: trigger_server_accept_fifo: trigger arrived
>
> If there is no such logging then the cleanup-to-qmgr notification
> is broken, and delivery is delayed until the queue manager does
> the routine queue_run_delay=300s queue scan.
>
> Wietse

I am seeing trigger_server_accept_fifo log entries unfortunately I cannot
associate the trigger to a specific message. I did notice the number
of qmgr trigger log entries are 60% the number of message  processed
log entries. I know postfix logs a single line per recipient and that could
account for some but not a 40% difference.

I completely left out one observation. The messages are accepted, they
are sitting in the incoming queue. There is little or no mail in the defer
queue. The active queue has a few hundred messages. I am not seeing
any significant number of errors for milter nor ldap queries.






Hotmail: Trusted email with Microsoft’s powerful SPAM protection. Sign up now.
Reply | Threaded
Open this post in threaded view
|

Re: queue manager delaying delivery of message

Wietse Venema
George Forman:

> > George Forman:
> > >
> > > > Subject: Re: queue manager delaying delivery of message
> > > > To: [hidden email]; [hidden email]
> > > > Date: Mon, 14 Dec 2009 19:31:44 -0500
> > > > From: [hidden email]
> > > >
> > > > The queue manager will leave a file in the incoming queue when:
> > > >
> > > > 1) Some "security" software does not allow the cleanup daemon
> > > > to write to the qmgr FIFO. Try without SeLinux, AppArmor, etc.
> > > >
> > > > 2) The queue file system is not on a local disk, and either file
> > > > server's clock and the Postfix machine's clock are out of whack.
> > > >
> > > > 3) Mailscanner or other non-Postfix software directly manipulates
> > > > Postfix queue files.
> > > >
> > > > 4) The file system does weird things with the "execute" file
> > > > permission bit. Postfix sets this bit when a queue file is ready
> > > > for delivery.
> > > >
> > > > 5) The queue manager is blocked for other reasons. Some vendors
> > > > make changes to Postfix source code and thereby break things.
> > > >
> > > > To investigate, does the delay happen with local submission
> > > > (the Postfix sendmail command)?
> > > >
> > > We are trying to replace our inbound MTA.  Because of the
> > > problems encountered, we brought down the server.
> > > I will try this tomorrow and report back with the results.
> > >
> > > > You wrote that you made the queue manager verbose, but there is
> > > > no verbose queue manager logging in your report.
> > >
> > > Unfortunately, I don't know how to associate the queue manager's
> > > output with respect to the email message queue id. The log file is
> > > huge, I will see if I can find the logs entries and included them.
> >
> > Don't bother, you have no idea what records are triggered
> > by cleanup server activity.
> >
> > The queue manager handles other deliveries while it is ignoring
> > this file? The cleanup server attempts to write to the qmgr FIFO,
> > and the queue manager will log that it receives a request.
> >
> > Dec 14 20:04:13 tail postfix/qmgr[2053]: trigger_server_accept_fifo: trigger arrived
> >
> > If there is no such logging then the cleanup-to-qmgr notification
> > is broken, and delivery is delayed until the queue manager does
> > the routine queue_run_delay=300s queue scan.
> >
> > Wietse
>
> I am seeing trigger_server_accept_fifo log entries unfortunately
> I cannotassociate the trigger to a specific message. I did notice
> the numberof qmgr trigger log entries are 60% the number of message
> processedlog entries. I know postfix logs a single line per
> recipient and that couldaccount for some but not a 40% difference.
> I completely left out one observation. The messages are accepted,
> theyare sitting in the incoming queue. There is little or no mail
> in the deferqueue. The active queue has a few hundred messages.
> I am not seeingany significant number of errors for milter nor
> ldap queries.

For the purpose of trouble shooting, I suggest running the tests on
a NON-MX machine so that one can trace the flow of a single message
without being flooded by unrelated logging, and so that the analysis
is not confused by you deleting logfile evidence without telling me.

Could you answer my questions, regarding items 2) .. 4, and regarding
other deliveries while a message sits in the incoming queue?

Note that I provide ZERO SUPPORT for configurations that correspond
with 3) above.

        Wietse