On 8/23/2018 7:04 PM, Wietse Venema wrote:
deoren:
On 8/21/2018 6:25 PM, Wietse Venema wrote:
Have you looked in Postfix LOGs? For example, if there is a delay
from the start of the probe to the first Postfix logfile record,
then that would indicate a delay with looking up the client hostname,
and then the address for that hostname.
Thank you for the response.
I find entries like these:
2018-08-21T08:11:19.456927-05:00 relay1 postfix/smtpd[30722]: connect
from unknown[192.168.2.199]
2018-08-21T08:11:34.332901-05:00 relay1 postfix/smtpd[30852]: connect
from unknown[192.168.2.199]
2018-08-21T08:11:43.392959-05:00 relay1 postfix/smtpd[30853]: connect
from unknown[192.168.2.199]
2018-08-21T08:11:52.424982-05:00 relay1 postfix/smtpd[30863]: connect
from unknown[192.168.2.199]
2018-08-21T08:12:01.472960-05:00 relay1 postfix/smtpd[30865]: connect
from unknown[192.168.2.199]
2018-08-21T08:12:07.465312-05:00 relay1 postfix/smtpd[30863]: lost
connection after MAIL from unknown[192.168.2.199]
2018-08-21T08:12:07.466254-05:00 relay1 postfix/smtpd[30863]: disconnect
from unknown[192.168.2.199] ehlo=1 mail=0/1 commands=1/2
2018-08-21T08:12:11.816850-05:00 relay1 postfix/smtpd[30722]: lost
connection after MAIL from unknown[192.168.2.199]
2018-08-21T08:12:11.817737-05:00 relay1 postfix/smtpd[30722]: disconnect
from unknown[192.168.2.199] ehlo=1 mail=0/1 commands=1/2
2018-08-21T08:12:12.884866-05:00 relay1 postfix/smtpd[30865]: connect
from unknown[192.168.2.199]
'mail=0/1' means that Postfix rejected the MAIL FROM command (the
client sent 1 MAIL FROM command, and Postfix accepted 0 MAIL FROM
commands).
Thank you for the response and for going into detail.
I suspect I completely overlooked it, but do you recall offhand where
one can read more about the specific fields used in the messages that
Postfix logs?
Regarding the rejection for the MAIL FROM command, HAProxy noted the
same thing and declared the health check a failure. Here is the relevant
line in the HAProxy config:
https://github.com/deoren/postfix-examples/blob/1f954130ee89032b3e5e3151a35f12dbd44e593b/load-balancer/etc/haproxy/haproxy.cfg#L479
You may want to examine the logs a little closer than looking for
'connect'.
That is a valid suggestion. I originally tried to find all log entries
within the same 1 minute time frame as when the health check failure was
noted by HAProxy. I don't recall for sure why the first block of log
entries was recorded in our ticket, other than perhaps just an
illustration of the type of messages that were logged around that time
or, perhaps to confirm what systems were actively making connections at
that time.
What else did processes 30863 and 30722 log for that
SMTP session?
$ sudo zgrep -E '30863|30722' mail.log-20180822.gz | grep '8:12'
2018-08-21T08:12:07.465312-05:00 relay1 postfix/smtpd[30863]: lost
connection after MAIL from unknown[192.168.2.199]
2018-08-21T08:12:07.466254-05:00 relay1 postfix/smtpd[30863]: disconnect
from unknown[192.168.2.199] ehlo=1 mail=0/1 commands=1/2
2018-08-21T08:12:11.816850-05:00 relay1 postfix/smtpd[30722]: lost
connection after MAIL from unknown[192.168.2.199]
2018-08-21T08:12:11.817737-05:00 relay1 postfix/smtpd[30722]: disconnect
from unknown[192.168.2.199] ehlo=1 mail=0/1 commands=1/2
2018-08-21T08:12:21.012939-05:00 relay1 postfix/smtpd[30863]: connect
from unknown[192.168.2.199]
2018-08-21T08:12:21.020352-05:00 relay1 postfix/smtpd[30863]: NOQUEUE:
permit: RCPT from unknown[192.168.2.199]: action=OK for Client
host=unknown[192.168.2.199] from
proxy:mysql:/etc/postfix/mysql-relay_access.cf;
from=<haproxy-smtp-ch...@subdomain.example.org>
to=<devn...@subdomain.example.org> proto=ESMTP
helo=<relay-lb1.subdomain.example.org>
2018-08-21T08:12:21.037991-05:00 relay1 postfix/smtpd[30863]:
0938F3FCB0: client=unknown[192.168.2.199]
2018-08-21T08:12:21.071673-05:00 relay1 postfix/smtpd[30863]: disconnect
from unknown[192.168.2.199] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
2018-08-21T08:12:29.204911-05:00 relay1 postfix/smtpd[30722]: connect
from unknown[192.168.2.199]
2018-08-21T08:12:29.209091-05:00 relay1 postfix/smtpd[30722]: NOQUEUE:
permit: RCPT from unknown[192.168.2.199]: action=OK for Client
host=unknown[192.168.2.199] from
proxy:mysql:/etc/postfix/mysql-relay_access.cf;
from=<haproxy-smtp-ch...@subdomain.example.org>
to=<devn...@subdomain.example.org> proto=ESMTP
helo=<relay-lb1.subdomain.example.org>
2018-08-21T08:12:29.226697-05:00 relay1 postfix/smtpd[30722]:
374CF3FCB0: client=unknown[192.168.2.199]
2018-08-21T08:12:29.268665-05:00 relay1 postfix/smtpd[30722]: disconnect
from unknown[192.168.2.199] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
