-TCTABLE_ENTRY
-TDELIVER_ATTR
-TDELIVER_REQUEST
+-TDELTA_TIME
-TDICT
-TDICT_CDBM
-TDICT_CDBQ
Completion of support for time stamps from different stages
of message delivery. The information is now logged as
- "delays=a/b/c/d" where a=time before queue manager; b=time
- in queue manager; c=connection setup including DNS, HELO
- and TLS; d=message transmission time. Unlike Victor's example
- which used time differences, this implementation uses
- absolute times. The decision of what numbers to subtract
- actually depends on program history, so we want to do it
- in one place. Files: global/log_adhoc.c, smtp/smtp_connect.c,
- smtp/smtp_proto.c, smtp/smtp_trouble.c, lmtp/lmtp_proto.c,
- lmtp/lmtp_trouble.c.
+ "delays=a/b/c/d" where a=time before queue manager, including
+ message transmission; b=time in queue manager; c=connection
+ setup including DNS, HELO and TLS; d=message transmission
+ time. Unlike Victor's example which used time differences,
+ this implementation uses absolute times. The decision of
+ what numbers to subtract actually depends on program history,
+ so we want to do it in one place. Files: global/log_adhoc.c,
+ smtp/smtp_connect.c, smtp/smtp_proto.c, smtp/smtp_trouble.c,
+ lmtp/lmtp_proto.c, lmtp/lmtp_trouble.c.
20051103
smtpd/smtpd.c, qmqpd/qmqpd.c, *qmgr/qmgr_message.c,
*qmgr/qmgr_active.c, local/forward.c.
+20061106
+
+ The SMTP client logs the remote server port in the form of
+ relay=hostname[hostaddr]:port to the local maillog file.
+ The port number is NOT included in DSN status reports,
+ because remote users have no need to know such internal
+ information. Files: smtp/smtp_session.c, smtp/smtp_proto.c,
+ smtp/smtp_trouble.c.
+
+ Cleanup: encapsulated queue file time read/write operations
+ with a few simple macros, to make future changes in time
+ representation less painful.
+
Open problems:
"postsuper -r" no longer resets the message arrival time,
If you upgrade from Postfix 2.1 or earlier, read RELEASE_NOTES-2.2
before proceeding.
+Incompatibility with snapshot 20051106
+======================================
+
+The relay=... logging has changed and now includes the remote SMTP
+server port number as hostname[hostaddr]:port.
+
Incompatibility with snapshot 20051105
======================================
- Better insight into the nature of performance bottle necks, with
detailed logging of delays in various stages of message delivery.
Postfix logs additional delay information as "delays=a/b/c/d" where
-a=time before queue manager; b=time in queue manager; c=connection
-setup time including DNS, HELO and TLS; d=message transmission time.
+a=time before queue manager, including message transmission; b=time
+in queue manager; c=connection setup time including DNS, HELO and
+TLS; d=message transmission time.
- Logging of the connection reuse count when SMTP connections are
used for more than one message delivery. This information is needed
<ul>
-<li> a = time before the queue manager selected the queue file
+<li> a = time before the queue manager, including message transmission
<li> b = time in queue manager
<li> c = time in connection setup, including DNS, EHLO and TLS
-<li> d = time in message transfer
+<li> d = time in message transmission
</ul>
.PP
The format of the "delays=a/b/c/d" logging is as follows:
.IP \(bu
-a = time before the queue manager selected the queue file
+a = time before the queue manager, including message transmission
.IP \(bu
b = time in queue manager
.IP \(bu
c = time in connection setup, including DNS, EHLO and TLS
.IP \(bu
-d = time in message transfer
+d = time in message transmission
.PP
Delay values less than delay_logging_time_resolution are logged
as "0", while delay values less than 10s are logged with at most
%PARAM delay_logging_time_resolution 10000
<p> The time resolution (microseconds) of the sub-second delay
-values that are logged for subsequent message delivery stages.
+values that are logged for subsequent message delivery stages.
Specify a power of 10 in the range from 1 to 100000. </p>
<p> The format of the "delays=a/b/c/d" logging is as follows: </p>
<ul>
-<li> a = time before the queue manager selected the queue file
+<li> a = time before the queue manager, including message transmission
<li> b = time in queue manager
<li> c = time in connection setup, including DNS, EHLO and TLS
-<li> d = time in message transfer
+<li> d = time in message transmission
</ul>
if ((state->flags & CLEANUP_FLAG_WARN_SEEN) == 0
&& var_delay_warn_time > 0) {
cleanup_out_format(state, REC_TYPE_WARN, REC_TYPE_WARN_FORMAT,
- (long) state->arrival_time.tv_sec + var_delay_warn_time);
+ REC_TYPE_WARN_ARG(state->arrival_time.tv_sec
+ + var_delay_warn_time));
}
state->flags |= CLEANUP_FLAG_INRCPT;
}
if (type == REC_TYPE_TIME) {
/* First instance wins. */
if (state->arrival_time.tv_sec == 0) {
- state->arrival_time.tv_sec = atol(buf);
+ REC_TYPE_TIME_SCAN(buf, state->arrival_time);
cleanup_out(state, type, buf, len);
- while (ISDIGIT(*buf))
- buf++;
- state->arrival_time.tv_usec = atol(buf);
}
return;
}
#include <log_adhoc.h>
#include <mail_params.h>
+ /*
+ * Don't use "struct timeval" for time differences; use explicit signed
+ * types instead. The code below relies on signed values to detect clocks
+ * jumping back.
+ */
+typedef struct {
+ int dt_sec; /* make sure it's signed */
+ int dt_usec; /* make sure it's signed */
+} DELTA_TIME;
+
/* log_adhoc - ad-hoc logging */
void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient,
const char *status)
{
static VSTRING *buf;
- struct timeval delay;
- struct timeval pdelay; /* time before queue manager */
- struct timeval adelay; /* queue manager latency */
- struct timeval sdelay; /* connection set-up latency */
- struct timeval xdelay; /* transmission latency */
+ DELTA_TIME delay;
+ DELTA_TIME pdelay; /* time before queue manager */
+ DELTA_TIME adelay; /* queue manager latency */
+ DELTA_TIME sdelay; /* connection set-up latency */
+ DELTA_TIME xdelay; /* transmission latency */
struct timeval now;
/*
buf = vstring_alloc(100);
/*
- * First, general information that identifies the transaction.
+ * First, critical information that identifies the nature of the
+ * transaction.
*/
vstring_sprintf(buf, "%s: to=<%s>", id, recipient->address);
if (recipient->orig_addr && *recipient->orig_addr
&& strcasecmp(recipient->address, recipient->orig_addr) != 0)
vstring_sprintf_append(buf, ", orig_to=<%s>", recipient->orig_addr);
vstring_sprintf_append(buf, ", relay=%s", relay);
+ if (stats->reuse_count > 0)
+ vstring_sprintf_append(buf, ", conn_use=%d", stats->reuse_count + 1);
/*
* Next, performance statistics.
*
* Don't compute the sdelay (connection setup latency) if there is no time
* stamp for connection setup completion.
- *
- * Instead of floating point, use integer math where practical.
*/
#define DELTA(x, y, z) \
do { \
- (x).tv_sec = (y).tv_sec - (z).tv_sec; \
- (x).tv_usec = (y).tv_usec - (z).tv_usec; \
- if ((x).tv_usec < 0) { \
- (x).tv_usec += 1000000; \
- (x).tv_sec -= 1; \
+ (x).dt_sec = (y).tv_sec - (z).tv_sec; \
+ (x).dt_usec = (y).tv_usec - (z).tv_usec; \
+ if ((x).dt_usec < 0) { \
+ (x).dt_usec += 1000000; \
+ (x).dt_sec -= 1; \
} \
- if ((x).tv_sec < 0) \
- (x).tv_sec = (x).tv_usec = 0; \
+ if ((x).dt_sec < 0) \
+ (x).dt_sec = (x).dt_usec = 0; \
} while (0)
- if (stats->deliver_done.tv_sec)
+#define DELTA_ZERO(x) ((x).dt_sec = (x).dt_usec = 0)
+
+#define TIME_STAMPED(x) ((x).tv_sec > 0)
+
+ if (TIME_STAMPED(stats->deliver_done))
now = stats->deliver_done;
else
GETTIMEOFDAY(&now);
DELTA(delay, now, stats->incoming_arrival);
- adelay.tv_sec = adelay.tv_usec =
- sdelay.tv_sec = sdelay.tv_usec =
- xdelay.tv_sec = xdelay.tv_usec = 0;
- if (stats->active_arrival.tv_sec) {
+ DELTA_ZERO(adelay);
+ DELTA_ZERO(sdelay);
+ DELTA_ZERO(xdelay);
+ if (TIME_STAMPED(stats->active_arrival)) {
DELTA(pdelay, stats->active_arrival, stats->incoming_arrival);
- if (stats->agent_handoff.tv_sec) {
+ if (TIME_STAMPED(stats->agent_handoff)) {
DELTA(adelay, stats->agent_handoff, stats->active_arrival);
- if (stats->conn_setup_done.tv_sec) {
+ if (TIME_STAMPED(stats->conn_setup_done)) {
DELTA(sdelay, stats->conn_setup_done, stats->agent_handoff);
DELTA(xdelay, now, stats->conn_setup_done);
} else {
DELTA(pdelay, now, stats->incoming_arrival);
}
- if (stats->reuse_count > 0)
- vstring_sprintf_append(buf, ", conn_use=%d", stats->reuse_count + 1);
-
/*
* XXX Eliminate dependency on floating point. Wietse insists, however,
* that precision be limited to avoid logfile clutter. That is, numbers
* less than 100 must look as if they were formatted with %.2g, not as if
- * they were formatted with %.2f.
+ * they were formatted with %.2f, and numbers of 10 and up must have no
+ * sub-second detail at all.
*/
#define MILLION 1000000
#define DMILLION ((double) MILLION)
-#define PRETTY_FORMAT(b, slash, x) \
+#define PRETTY_FORMAT(b, text, x) \
do { \
- if ((x).tv_sec > 9 \
- || ((x).tv_sec == 0 && (x).tv_usec < var_delay_resolution)) { \
- vstring_sprintf_append((b), slash "%ld", \
- (long) (x).tv_sec + ((x).tv_usec > (MILLION / 2))); \
+ if ((x).dt_sec > 9 \
+ || ((x).dt_sec == 0 && (x).dt_usec < var_delay_resolution)) { \
+ vstring_sprintf_append((b), text "%ld", \
+ (long) (x).dt_sec + ((x).dt_usec > (MILLION / 2))); \
} else { \
- vstring_sprintf_append((b), slash "%.2g", (x).tv_sec \
- + ((x).tv_usec - (x).tv_usec % var_delay_resolution) \
+ vstring_sprintf_append((b), text "%.2g", (x).dt_sec \
+ + ((x).dt_usec - (x).dt_usec % var_delay_resolution) \
/ DMILLION); \
} \
} while (0)
- vstring_sprintf_append(buf, ", delay=");
- PRETTY_FORMAT(buf, "", delay);
- vstring_sprintf_append(buf, ", delays=");
- PRETTY_FORMAT(buf, "", pdelay);
+ PRETTY_FORMAT(buf, ", delay=", delay);
+ PRETTY_FORMAT(buf, ", delays=", pdelay);
PRETTY_FORMAT(buf, "/", adelay);
PRETTY_FORMAT(buf, "/", sdelay);
PRETTY_FORMAT(buf, "/", xdelay);
* Patches change both the patchlevel and the release date. Snapshots have no
* patchlevel; they change the release date only.
*/
-#define MAIL_RELEASE_DATE "20051105"
+#define MAIL_RELEASE_DATE "20051106"
#define MAIL_VERSION_NUMBER "2.3"
#ifdef SNAPSHOT
* Generate a minimal envelope section. The cleanup service will add a
* size record.
*/
- rec_fprintf(stream, REC_TYPE_TIME, "%ld %ld",
- (long) now.tv_sec, (long) now.tv_usec);
+ rec_fprintf(stream, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
+ REC_TYPE_TIME_ARG(now));
rec_fprintf(stream, REC_TYPE_ATTR, "%s=%s",
MAIL_ATTR_ORIGIN, MAIL_ATTR_ORG_LOCAL);
rec_fprintf(stream, REC_TYPE_ATTR, "%s=%d",
* this value when there are deferred mesages in the queue is dangerous!
*/
#define REC_TYPE_WARN_FORMAT "%15ld" /* warning time format */
-#define REC_TYPE_WARN_CAST long
+#define REC_TYPE_WARN_ARG(tv) ((long) (tv))
+#define REC_TYPE_WARN_SCAN(cp, tv) ((tv) = atol(cp))
+
+ /*
+ * Time information is not updated in place, but it does have complex
+ * formatting requirements, so we centralize things here.
+ */
+#define REC_TYPE_TIME_FORMAT "%ld %ld"
+#define REC_TYPE_TIME_ARG(tv) (long) (tv).tv_sec, (long) (tv).tv_usec
+#define REC_TYPE_TIME_SCAN(cp, tv) \
+ do { \
+ const char *_p = cp; \
+ (tv).tv_sec = atol(_p); \
+ while (ISDIGIT(*_p)) \
+ _p++; \
+ (tv).tv_usec = atol(_p); \
+ } while (0)
/*
* Programmatic interface.
* Send initial message envelope information. For bounces, set the
* designated sender: mailing list owner, posting user, whatever.
*/
- rec_fprintf(cleanup, REC_TYPE_TIME, "%ld %ld",
- (long) info->posting_time.tv_sec,
- (long) info->posting_time.tv_usec);
+ rec_fprintf(cleanup, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
+ REC_TYPE_TIME_ARG(info->posting_time));
rec_fputs(cleanup, REC_TYPE_FROM, sender);
/*
}
if (rec_type == REC_TYPE_TIME) {
if (message->arrival_time.tv_sec == 0)
- message->arrival_time.tv_sec = atol(start);
- while(ISDIGIT(*start))
- start++;
- message->arrival_time.tv_usec = atol(start);
+ REC_TYPE_TIME_SCAN(start, message->arrival_time);
continue;
}
if (rec_type == REC_TYPE_FILT) {
if (rec_type == REC_TYPE_WARN) {
if (message->warn_offset == 0) {
message->warn_offset = curr_offset;
- message->warn_time = atol(start);
+ REC_TYPE_WARN_SCAN(start, message->warn_time);
}
continue;
}
*/
if (qmgr_message_open(message)
|| vstream_fseek(message->fp, message->warn_offset, SEEK_SET) < 0
- || rec_fprintf(message->fp, REC_TYPE_WARN, REC_TYPE_WARN_FORMAT, 0L) < 0
+ || rec_fprintf(message->fp, REC_TYPE_WARN, REC_TYPE_WARN_FORMAT,
+ REC_TYPE_WARN_ARG(0)) < 0
|| vstream_fflush(message->fp))
msg_fatal("update queue file %s: %m", VSTREAM_PATH(message->fp));
qmgr_message_close(message);
#include <sys_defs.h>
#include <sys/stat.h>
+#include <sys/time.h>
#include <stdlib.h>
#include <unistd.h>
#include <time.h>
{
int prev_type = 0;
int rec_type;
+ struct timeval tv;
time_t time;
int first = 1;
int ch;
vstream_printf("%9lu ", (unsigned long) offset);
switch (rec_type) {
case REC_TYPE_TIME:
+ REC_TYPE_TIME_SCAN(STR(buffer), tv);
+ time = tv.tv_sec;
+ vstream_printf("%s: %s", rec_type_name(rec_type),
+ asctime(localtime(&time)));
+ break;
case REC_TYPE_WARN:
- time = atol(STR(buffer));
+ REC_TYPE_WARN_SCAN(STR(buffer), time);
vstream_printf("%s: %s", rec_type_name(rec_type),
asctime(localtime(&time)));
break;
buf = vstring_alloc(100);
expected = segment_info;
/* Override time information from the untrusted caller. */
- rec_fprintf(dst->stream, REC_TYPE_TIME, "%ld %ld",
- (long) start.tv_sec, (long) start.tv_usec);
+ rec_fprintf(dst->stream, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
+ REC_TYPE_TIME_ARG(start));
for (;;) {
rec_type = rec_get(VSTREAM_IN, buf, var_line_limit);
if (rec_type == REC_TYPE_EOF) { /* request cancelled */
}
if (rec_type == REC_TYPE_TIME) {
if (message->arrival_time.tv_sec == 0)
- message->arrival_time.tv_sec = atol(start);
- while(ISDIGIT(*start))
- start++;
- message->arrival_time.tv_usec = atol(start);
+ REC_TYPE_TIME_SCAN(start, message->arrival_time);
continue;
}
if (rec_type == REC_TYPE_FILT) {
if (rec_type == REC_TYPE_WARN) {
if (message->warn_offset == 0) {
message->warn_offset = curr_offset;
- message->warn_time = atol(start);
+ REC_TYPE_WARN_SCAN(start, message->warn_time);
}
continue;
}
*/
if (qmgr_message_open(message)
|| vstream_fseek(message->fp, message->warn_offset, SEEK_SET) < 0
- || rec_fprintf(message->fp, REC_TYPE_WARN, REC_TYPE_WARN_FORMAT, 0L) < 0
+ || rec_fprintf(message->fp, REC_TYPE_WARN, REC_TYPE_WARN_FORMAT,
+ REC_TYPE_WARN_ARG(0)) < 0
|| vstream_fflush(message->fp))
msg_fatal("update queue file %s: %m", VSTREAM_PATH(message->fp));
qmgr_message_close(message);
* bloody likely, but present for the sake of consistency with all other
* Postfix points of entrance).
*/
- rec_fprintf(state->cleanup, REC_TYPE_TIME, "%ld %ld",
- (long) state->arrival_time.tv_sec,
- (long) state->arrival_time.tv_usec);
+ rec_fprintf(state->cleanup, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
+ REC_TYPE_TIME_ARG(state->arrival_time));
if (*var_filter_xport)
rec_fprintf(state->cleanup, REC_TYPE_FILT, "%s", var_filter_xport);
}
char *namaddr; /* mail exchanger */
char *helo; /* helo response */
unsigned port; /* network byte order */
+ char *namaddrport; /* mail exchanger, incl. port */
VSTRING *buffer; /* I/O buffer */
VSTRING *scratch; /* scratch buffer */
if (strcasecmp(word, var_myhostname) == 0
&& (misc_flags & SMTP_MISC_FLAG_LOOP_DETECT) != 0) {
msg_warn("host %s replied to HELO/EHLO with my own hostname %s",
- session->namaddr, var_myhostname);
+ session->namaddrport, var_myhostname);
if (session->features & SMTP_FEATURE_BEST_MX)
return (smtp_site_fail(state, DSN_BY_LOCAL_MTA,
SMTP_RESP_FAKE(&fake, 554, "5.4.6",
if ((word = mystrtok(&words, " \t")) != 0) {
if (!alldig(word))
msg_warn("bad EHLO SIZE limit \"%s\" from %s",
- word, session->namaddr);
+ word, session->namaddrport);
else
session->size_limit = off_cvt_string(word);
}
case SMTP_STATE_XFORWARD_NAME_ADDR:
if (resp->code / 100 != 2)
msg_warn("host %s said: %s (in reply to %s)",
- session->namaddr,
+ session->namaddrport,
translit(resp->str, "\n", " "),
xfer_request[SMTP_STATE_XFORWARD_NAME_ADDR]);
if (session->send_proto_helo)
case SMTP_STATE_XFORWARD_PROTO_HELO:
if (resp->code / 100 != 2)
msg_warn("host %s said: %s (in reply to %s)",
- session->namaddr,
+ session->namaddrport,
translit(resp->str, "\n", " "),
xfer_request[SMTP_STATE_XFORWARD_PROTO_HELO]);
recv_state = SMTP_STATE_MAIL;
&& request->msg_stats.incoming_arrival.tv_sec
< vstream_ftime(session->stream) - var_smtp_pix_thresh) {
msg_info("%s: enabling PIX <CRLF>.<CRLF> workaround for %s",
- request->queue_id, session->namaddr);
+ request->queue_id, session->namaddrport);
smtp_flush(session->stream); /* hurts performance */
sleep(var_smtp_pix_delay); /* not to mention this */
}
status = sent(DEL_REQ_TRACE_FLAGS(request->flags),
request->queue_id, &request->msg_stats, rcpt,
- session->namaddr, &dsn);
+ session->namaddrport, &dsn);
if (status == 0)
if (request->flags & DEL_REQ_FLAG_SUCCESS)
deliver_completed(state->src, rcpt->offset);
smtp_chat_init(session);
session->mime_state = 0;
+ vstring_sprintf(session->buffer, "%s:%d",
+ session->namaddr, ntohs(session->port));
+ session->namaddrport = mystrdup(STR(session->buffer));
+
session->sndbufsize = 0;
session->send_proto_helo = 0;
myfree(session->host);
myfree(session->addr);
myfree(session->namaddr);
+ myfree(session->namaddrport);
if (session->helo)
myfree(session->helo);
status = (soft_error ? defer_append : bounce_append)
(DEL_REQ_TRACE_FLAGS(request->flags), request->queue_id,
&request->msg_stats, rcpt,
- session ? session->namaddr : "none", dsn);
+ session ? session->namaddrport : "none", dsn);
if (status == 0)
deliver_completed(state->src, rcpt->offset);
SMTP_RCPT_DROP(state, rcpt);
status = (soft_error ? defer_append : bounce_append)
(DEL_REQ_TRACE_FLAGS(request->flags), request->queue_id,
&request->msg_stats, rcpt,
- session ? session->namaddr : "none", &dsn);
+ session ? session->namaddrport : "none", &dsn);
if (status == 0)
deliver_completed(state->src, rcpt->offset);
SMTP_RCPT_DROP(state, rcpt);
* attributes.
*/
if (SMTPD_STAND_ALONE(state) == 0) {
- rec_fprintf(state->cleanup, REC_TYPE_TIME, "%ld %ld",
- (long) state->arrival_time.tv_sec,
- (long) state->arrival_time.tv_usec);
+ rec_fprintf(state->cleanup, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
+ REC_TYPE_TIME_ARG(state->arrival_time));
if (*var_filter_xport)
rec_fprintf(state->cleanup, REC_TYPE_FILT, "%s", var_filter_xport);
rec_fprintf(state->cleanup, REC_TYPE_ATTR, "%s=%s",
projects / thirdparty / postfix.git / commitdiff
