From: Bill Landry (billinetmsg.com)
Date: Fri Jun 01 2007 - 16:03:34 CDT

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

I have been working with a customer to debug a mail delivery issue.
They have just recently reworked their network and installed 3 Barracuda
SMTP Gateway appliances. The mail admin person does not know if there
is a Cisco PIX sitting in front of the Barracuda gateways or not, and
their network guy was out-of-office today. Our delivery server is
running Postfix:

postconf mail_version
mail_version = 2.4.0

I tried setting the PIX workaround config options:

smtp_pix_workarounds = disable_esmtp, delay_dotcrlf
smtp_pix_workaround_delay_time = 10s
smtp_pix_workaround_threshold_time = 500s

But that did not help in this situation. I have since removed these PIX
workarounds settings:

postconf -n
alias_database = hash:/etc/postfix/aliases
alias_maps = hash:/etc/postfix/aliases
alternate_config_directories = /etc/postfix-tls
bounce_queue_lifetime = 2d
command_directory = /usr/sbin
config_directory = /etc/postfix
daemon_directory = /usr/libexec/postfix
default_destination_concurrency_limit = 25
default_privs = nobody
disable_vrfy_command = yes
header_checks = regexp:/etc/postfix/postfix-header-checks
html_directory = no
inet_interfaces = obgw1.example.com
local_destination_concurrency_limit = 5
local_recipient_maps = hash:/etc/postfix/valiases
mail_name = Secure Relay
mail_owner = postfix
mail_spool_directory = /var/spool/mail
mailq_path = /usr/bin/mailq
manpage_directory = /usr/local/man
maximal_queue_lifetime = 7d
mydestination = $mydomain, $myhostname, localhost.$mydomain, localhost
mydomain = example.com
myhostname = obgw1.example.com
mynetworks = 127.0.0.0/8, xx.xx.192.128/25
myorigin = $mydomain
newaliases_path = /usr/bin/newaliases
notify_classes = bounce, delay, policy, protocol, resource, software
queue_directory = /var/spool/postfix
readme_directory = /etc/postfix/README-FILES
sample_directory = /etc/postfix
sendmail_path = /usr/sbin/sendmail
setgid_group = postdrop
smtp_bind_address = xx.xx.192.170
smtpd_banner = $myhostname - Secure ESMTP Relay - UCE not permitted!
smtpd_client_restrictions =
smtpd_data_restrictions = reject_unauth_pipelining
smtpd_helo_required = yes
smtpd_helo_restrictions =
smtpd_recipient_restrictions = permit_mynetworks,
reject_unlisted_recipient, reject_unauth_destination, permit
smtpd_sender_restrictions =
soft_bounce = no
strict_rfc821_envelopes = yes
syslog_name = postfix-out
transport_maps = hash:/etc/postfix/transport-maps
unknown_local_recipient_reject_code = 550
virtual_alias_maps = hash:/etc/postfix/valiases

I have removed all messages from the queue for this domain using
"postsuper -d", stopped and restarted Postfix, and then sent a new
e-mail to the customer; however, it appears that Postfix is still using
the PIX workarounds:

Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: smtp_connect_addr:
bind xx.xx.192.170
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: smtp_connect_addr:
trying: xxx.xxx.157.16[xxx.xxx.157.16] port 25...
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: global TLS level: none
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: <
xxx.xxx.157.16[xxx.xxx.157.16]: 220
**********************************************************
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: name_mask: disable_esmtp
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: name_mask: delay_dotcrlf
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: DBF76280DF: enabling
PIX workarounds: disable_esmtp delay_dotcrlf for
xxx.xxx.157.16[xxx.xxx.157.16]:25
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: >
xxx.xxx.157.16[xxx.xxx.157.16]: HELO obgw1.example.com
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: <
xxx.xxx.157.16[xxx.xxx.157.16]: 250 mail.example.org
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: server features:
0x31000 size 0
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: >
xxx.xxx.157.16[xxx.xxx.157.16]: MAIL FROM:<meexample.com>
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: <
xxx.xxx.157.16[xxx.xxx.157.16]: 250 Ok
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: >
xxx.xxx.157.16[xxx.xxx.157.16]: RCPT TO:<themexample.org>
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: <
xxx.xxx.157.16[xxx.xxx.157.16]: 250 Ok
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: >
xxx.xxx.157.16[xxx.xxx.157.16]: DATA
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: <
xxx.xxx.157.16[xxx.xxx.157.16]: 354 End data with <CR><LF>.<CR><LF>
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: header_token:
multipart / mixed
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: header_token:
boundary = __1180728422233.seasigw01
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: PUSH boundary
__1180728422233.seasigw01
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: header_token: text / html
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: header_token: 7bit
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: header_token:
quoted-printable
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: header_token: text / html
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: POP boundary
__1180728422233.seasigw01
Jun 1 16:05:45 gateway01 postfix-out/smtp[29112]: >
xxx.xxx.157.16[xxx.xxx.157.16]: .
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: connect to subsystem
private/defer
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr nrequest = 0
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr flags = 0
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr queue_id =
DBF76280DF
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr
original_recipient = themexample.org
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr recipient =
themexample.org
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr offset = 740
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr
dsn_orig_rcpt = rfc822;themexample.org
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr
notify_flags = 0
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr status = 4.4.2
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr diag_type =
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr diag_text =
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr mta_type =
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr mta_mname =
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr action =
delayed
Jun 1 16:21:32 gateway01 postfix-out/smtp[29112]: send attr reason =
conversation with xxx.xxx.157.16[xxx.xxx.157.16] timed out while sending
end of data -- message may be sent more than once
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: private/defer socket:
wanted attribute: status
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: input attribute name:
status
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: input attribute value: 0
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: private/defer socket:
wanted attribute: (list terminator)
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: input attribute name:
(end)
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: DBF76280DF:
to=<themexample.org>, relay=xxx.xxx.157.16[xxx.xxx.157.16]:25,
delay=948, delays=0.23/0.54/0.09/947, dsn=4.4.2, status=deferred
(conversation with xxx.xxx.157.16[xxx.xxx.157.16] timed out while
sending end of data -- message may be sent more than once)
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: flush_add: site
example.org id DBF76280DF
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: match_hostname:
example.org ~? example.com
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: match_hostname:
example.org ~? obgw1.example.com
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: match_hostname:
example.org ~? localhost.example.com
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: match_hostname:
example.org ~? localhost
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: match_list_match:
example.org: no match
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: flush_add: site
example.org id DBF76280DF status 4
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: name_mask: bounce
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: name_mask: delay
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: name_mask: policy
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: name_mask: protocol
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: name_mask: resource
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: name_mask: software
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]:
deliver_request_final: send: "conversation with
xxx.xxx.157.16[xxx.xxx.157.16] timed out while sending end of data --
message may be sent more than once" -1
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr status = 4.4.2
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr diag_type =
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr diag_text =
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr mta_type =
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr mta_mname =
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr action =
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr reason =
conversation with xxx.xxx.157.16[xxx.xxx.157.16] timed out while sending
end of data -- message may be sent more than once
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: send attr status =
4294967295
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: master_notify: status 1
Jun 1 16:21:33 gateway01 postfix-out/smtp[29112]: connection closed

Not sure why Postfix is still attempting to use the PIX workarounds
since they have been removed from main.cf. Also, any idea why we might
be failing delivery here? Any suggestions would be greatly appreciated.

Thanks,

Bill

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]