postfix cleanup process dropping messages

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

postfix cleanup process dropping messages

Ramprasad-5
My postfix servers remain pretty busy throughout the day getting around
100 - 200 mails / second

I have seen that for every 100 k mails around 20 mails disappear from
the queue.
 From maillogs , I can see smtpd accepting the connection , creating a
queue-id and then cleanup picking it up.
But nothing after that , no qmgr lines no discard etc




If I enable cleanup in  debug mode I can see  errors like this  ( esp
cleanup_flush: status 1 )

How do I debug this further ?


Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: open incoming/6262B115F
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_open: open
incoming/6262B115F
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr queue_id =
6262B115F
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup socket: wanted
attribute: flags
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: flags
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute value: 178
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup socket: wanted
attribute: (list terminator)
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: (end)
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup flags =
enable_header_body_filter enable_automatic_bcc enable_address_mapping
enable_smtp_reply
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope T
1531399835 381154
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
log_ident=6262B115F
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
rewrite_context=remote
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
sasl_method=PLAIN
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
sasl_username=justdialf
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope S
XXXXXXXXXXX
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr request = rewrite
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr rule = local
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr address =
[hidden email]
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: private/rewrite socket:
wanted attribute: flags
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: flags
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute value: 0
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: private/rewrite socket:
wanted attribute: address
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: address
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute value:
[hidden email]
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: private/rewrite socket:
wanted attribute: (list terminator)
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: (end)
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: rewrite_clnt: local:
XXXXXXXXXx
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
log_client_name=unknown
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
log_client_address=10.139.64.141
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
log_client_port=10802
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
log_message_origin=unknown[10.139.64.141]
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
log_helo_name=localhost.localdomain
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
log_protocol_name=ESMTP
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
client_name=unknown
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
reverse_client_name=unknown
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
client_address=10.139.64.141
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
client_port=10802
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
server_address=10.139.64.82
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
server_port=25
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
helo_name=localhost.localdomain
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
protocol_name=ESMTP
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
client_address_type=2
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope A
dsn_orig_rcpt=XXXXXXXXXX
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope R
XXXXXXXXXXXXXXXXXXXxx
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr request = rewrite
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr rule = local
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr address =
XXXXXXXXXXXXXXXXXXXXXXXXXx
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: private/rewrite socket:
wanted attribute: flags
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: flags
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute value: 0
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: private/rewrite socket:
wanted attribute: address
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: address
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute value:
XXXXXXXX
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: private/rewrite socket:
wanted attribute: (list terminator)
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: input attribute name: (end)
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: rewrite_clnt: local:
XXXXXXXXXx
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: been_here: XXXXXXXXx
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: initial envelope M
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'Received: from XXXXXXXX'
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'MIME-Version: 1.0'
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'Content-Disposition: inline'
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: header_token: 8bit
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'Content-Transfer-Encoding: 8bit'
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: header_token: text / html
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'Content-Type: text/html; charset="UTF-8"'
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'X-Mailer: MIME::Lite 3.027 (F2.77; T1.28; A2.04; B3.08; Q3.08)'
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'Date: Thu, 12 Jul 2018 18:20:35 +0530'
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'From: XXXXXXX
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_header_callback:
'To: XXXXXXXXXXXXx
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: 6262B115F:
message-id=<XXXXXXXXXXx
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_flush: status 1
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr status = 1
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr reason =
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: master_notify: status 1
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: connection closed
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: connection established
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: master_notify: status 0
Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: mail_flow_get: 1 1







this is my postconf output

alias_database = hash:/etc/aliases
alias_maps = hash:/etc/aliases
alternate_config_directories =
always_add_missing_headers = yes
append_at_myorigin = no
append_dot_mydomain = no
bounce_size_limit = 10000
broken_sasl_auth_clients = yes
command_directory = /usr/sbin
compatibility_level = 2
daemon_directory = /usr/libexec/postfix
data_directory = /var/lib/postfix
debug_peer_level = 2
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd
$daemon_directory/$process_name $process_id & sleep 5
default_destination_concurrency_limit = 50
default_destination_recipient_limit = 1
default_process_limit = 300
html_directory = no
inet_interfaces = all
inet_protocols = all
line_length_limit = 5096
local_recipient_maps =
mail_owner = postfix
mailq_path = /usr/bin/mailq.postfix
manpage_directory = /usr/share/man
maximal_backoff_time = 40s
message_size_limit = 50000000
meta_directory = /etc/postfix
minimal_backoff_time = 30s
mydestination = XXXXXXXXXXXX
myhostname = XXXXXXXXXXXXXXXX
mynetworks = /etc/postfix/mynetworks
nested_header_checks =
newaliases_path = /usr/bin/newaliases.postfix
qmgr_message_active_limit = 80000
queue_directory = /var/spool/postfix
queue_run_delay = 30s
readme_directory = /usr/share/doc/postfix-3.1.1/README_FILES
relayhost = [202.162.247.189]:27
remote_header_rewrite_domain =
sample_directory = /usr/share/doc/postfix-3.1.1/samples
sendmail_path = /usr/sbin/sendmail.postfix
setgid_group = postdrop
shlib_directory = /usr/lib64/postfix
smtp_line_length_limit = 9900000
smtpd_banner = ESMTP SMTPBP1 Ready
smtpd_client_connection_count_limit = 200
smtpd_client_connection_rate_limit = 3000
smtpd_client_event_limit_exceptions = $mynetworks,
/etc/postfix/rate_exception,
smtpd_client_message_rate_limit = 1000
smtpd_helo_required = no
smtpd_junk_command_limit = 10000
smtpd_recipient_limit = 3000
smtpd_recipient_restrictions = permit_sasl_authenticated,
reject_unauth_destination, reject
smtpd_restriction_classes = check_env_from
smtpd_sasl_auth_enable = yes
smtpd_sasl_authenticated_header = yes
smtpd_sasl_local_domain =
smtpd_sasl_security_options = noanonymous
smtpd_soft_error_limit = 10000
syslog_name = smtpbp1
unknown_local_recipient_reject_code = 550



https://netcore.in/resources/webinar/how-has-browser-push-notification-grown-as-channel/

Reply | Threaded
Open this post in threaded view
|

Re: postfix cleanup process dropping messages

Viktor Dukhovni
On Thu, Jul 12, 2018 at 07:20:26PM +0530, Ram wrote:

> My postfix servers remain pretty busy throughout the day getting around
> 100 - 200 mails / second
>
> I have seen that for every 100 k mails around 20 mails disappear from
> the queue.
>  From maillogs , I can see smtpd accepting the connection , creating a
> queue-id and then cleanup picking it up.

If you look closely, you'll see smtpd reporting early connection
termination after the queue file was created, and message-id written
but before the message is fully received (".").

> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: open incoming/6262B115F
> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: 6262B115F:
> message-id=<XXXXXXXXXXx
> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_flush: status 1
> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr status = 1
> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr reason =
> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: master_notify: status 1
> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: connection closed

What is the corresponding logging on the smtpd(8) side?

--
        Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: postfix cleanup process dropping messages

Ramprasad-5


On 07/12/2018 07:36 PM, Viktor Dukhovni wrote:

> On Thu, Jul 12, 2018 at 07:20:26PM +0530, Ram wrote:
>
>> My postfix servers remain pretty busy throughout the day getting around
>> 100 - 200 mails / second
>>
>> I have seen that for every 100 k mails around 20 mails disappear from
>> the queue.
>>   From maillogs , I can see smtpd accepting the connection , creating a
>> queue-id and then cleanup picking it up.
> If you look closely, you'll see smtpd reporting early connection
> termination after the queue file was created, and message-id written
> but before the message is fully received (".").
>
>> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: open incoming/6262B115F
>> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: 6262B115F:
>> message-id=<XXXXXXXXXXx
>> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_flush: status 1
>> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr status = 1
>> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr reason =
>> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: master_notify: status 1
>> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: connection closed
> What is the corresponding logging on the smtpd(8) side?
>
I will look at smtp logs too. The logs are a bit  verbose for me to make
sense , but that should be done
But the smtp-client closing connection before "." is unlikely , because
the sender got a full DSN with an OK queued as ...







https://netcore.in/resources/webinar/how-has-browser-push-notification-grown-as-channel/

Reply | Threaded
Open this post in threaded view
|

Re: postfix cleanup process dropping messages

Viktor Dukhovni
On Thu, Jul 12, 2018 at 08:08:17PM +0530, Ram wrote:

> On 07/12/2018 07:36 PM, Viktor Dukhovni wrote:
> > On Thu, Jul 12, 2018 at 07:20:26PM +0530, Ram wrote:
> >
> >> My postfix servers remain pretty busy throughout the day getting around
> >> 100 - 200 mails / second
> >>
> >> I have seen that for every 100 k mails around 20 mails disappear from
> >> the queue.
> >>   From maillogs , I can see smtpd accepting the connection , creating a
> >> queue-id and then cleanup picking it up.
> > If you look closely, you'll see smtpd reporting early connection
> > termination after the queue file was created, and message-id written
> > but before the message is fully received (".").
> >
> >> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: open incoming/6262B115F
> >> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: 6262B115F:
> >> message-id=<XXXXXXXXXXx
> >> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: cleanup_flush: status 1
> >> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr status = 1
> >> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: send attr reason =
> >> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: master_notify: status 1
> >> Jul 12 18:20:35 smtpbp1 smtpbp1/cleanup[9121]: connection closed
> > What is the corresponding logging on the smtpd(8) side?
>
> I will look at smtp logs too. The logs are a bit  verbose for me to make
> sense , but that should be done
> But the smtp-client closing connection before "." is unlikely , because
> the sender got a full DSN with an OK queued as ...

The sender may have retried at a different MX or a later time.
Postfix does not return "250 OK" to the sender after "." until
cleanup commits (fsync) the complete queue file to stable storage.

There's no need for the verbose logging you're generating, it just
makes it harder to see the logs that matter.

--
        Viktor.