diff --git a/postfix/.indent.pro b/postfix/.indent.pro index f55941ec6..df2a7dea4 100644 --- a/postfix/.indent.pro +++ b/postfix/.indent.pro @@ -42,6 +42,7 @@ -TCTABLE_ENTRY -TDELIVER_ATTR -TDELIVER_REQUEST +-TDELTA_TIME -TDICT -TDICT_CDBM -TDICT_CDBQ diff --git a/postfix/HISTORY b/postfix/HISTORY index 9aab3391e..923d9d9c7 100644 --- a/postfix/HISTORY +++ b/postfix/HISTORY @@ -11276,15 +11276,15 @@ Apologies for any names omitted. 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 @@ -11314,6 +11314,19 @@ Apologies for any names omitted. 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, diff --git a/postfix/RELEASE_NOTES b/postfix/RELEASE_NOTES index 41c376b06..e839b6ef0 100644 --- a/postfix/RELEASE_NOTES +++ b/postfix/RELEASE_NOTES @@ -17,6 +17,12 @@ Incompatibility with Postfix 2.1 and earlier 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 ====================================== @@ -54,8 +60,9 @@ Postfix logfile records. - 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 diff --git a/postfix/html/postconf.5.html b/postfix/html/postconf.5.html index bfbe472e4..4a0b822f4 100644 --- a/postfix/html/postconf.5.html +++ b/postfix/html/postconf.5.html @@ -1913,13 +1913,13 @@ Specify a power of 10 in the range from 1 to 100000.

diff --git a/postfix/man/man5/postconf.5 b/postfix/man/man5/postconf.5 index c0be00d98..2622fa1c0 100644 --- a/postfix/man/man5/postconf.5 +++ b/postfix/man/man5/postconf.5 @@ -1041,13 +1041,13 @@ Specify a power of 10 in the range from 1 to 100000. .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 diff --git a/postfix/proto/postconf.proto b/postfix/proto/postconf.proto index cb499c97f..b26ae0ea6 100644 --- a/postfix/proto/postconf.proto +++ b/postfix/proto/postconf.proto @@ -8653,20 +8653,20 @@ DNS lookup and increases the maximal inbound delivery rate.

%PARAM delay_logging_time_resolution 10000

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.

The format of the "delays=a/b/c/d" logging is as follows:

diff --git a/postfix/src/cleanup/cleanup_envelope.c b/postfix/src/cleanup/cleanup_envelope.c index ca0149310..d7b4f0d80 100644 --- a/postfix/src/cleanup/cleanup_envelope.c +++ b/postfix/src/cleanup/cleanup_envelope.c @@ -210,7 +210,8 @@ static void cleanup_envelope_process(CLEANUP_STATE *state, int type, 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; } @@ -300,11 +301,8 @@ static void cleanup_envelope_process(CLEANUP_STATE *state, int type, 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; } diff --git a/postfix/src/global/log_adhoc.c b/postfix/src/global/log_adhoc.c index 1237bce7e..a47bf08e2 100644 --- a/postfix/src/global/log_adhoc.c +++ b/postfix/src/global/log_adhoc.c @@ -69,6 +69,16 @@ #include #include + /* + * 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, @@ -76,11 +86,11 @@ 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; /* @@ -92,13 +102,16 @@ void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, 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. @@ -119,35 +132,37 @@ void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, * * 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 { @@ -163,35 +178,31 @@ void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, 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); diff --git a/postfix/src/global/mail_version.h b/postfix/src/global/mail_version.h index 6ce77da97..cd57710e6 100644 --- a/postfix/src/global/mail_version.h +++ b/postfix/src/global/mail_version.h @@ -20,7 +20,7 @@ * 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 diff --git a/postfix/src/global/post_mail.c b/postfix/src/global/post_mail.c index 09cd26829..0904e6e0c 100644 --- a/postfix/src/global/post_mail.c +++ b/postfix/src/global/post_mail.c @@ -199,8 +199,8 @@ static void post_mail_init(VSTREAM *stream, const char *sender, * 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", diff --git a/postfix/src/global/rec_type.h b/postfix/src/global/rec_type.h index 353f34fa6..106c87ef7 100644 --- a/postfix/src/global/rec_type.h +++ b/postfix/src/global/rec_type.h @@ -118,7 +118,23 @@ * 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. diff --git a/postfix/src/local/forward.c b/postfix/src/local/forward.c index 28326c536..9ab147b27 100644 --- a/postfix/src/local/forward.c +++ b/postfix/src/local/forward.c @@ -152,9 +152,8 @@ static FORWARD_INFO *forward_open(DELIVER_REQUEST *request, const char *sender) * 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); /* diff --git a/postfix/src/oqmgr/qmgr_message.c b/postfix/src/oqmgr/qmgr_message.c index d437a160c..8abc36b2f 100644 --- a/postfix/src/oqmgr/qmgr_message.c +++ b/postfix/src/oqmgr/qmgr_message.c @@ -534,10 +534,7 @@ static int qmgr_message_read(QMGR_MESSAGE *message) } 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) { @@ -647,7 +644,7 @@ static int qmgr_message_read(QMGR_MESSAGE *message) 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; } @@ -748,7 +745,8 @@ void qmgr_message_update_warn(QMGR_MESSAGE *message) */ 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); diff --git a/postfix/src/postcat/postcat.c b/postfix/src/postcat/postcat.c index e61268eb9..f1389c595 100644 --- a/postfix/src/postcat/postcat.c +++ b/postfix/src/postcat/postcat.c @@ -65,6 +65,7 @@ #include #include +#include #include #include #include @@ -101,6 +102,7 @@ static void postcat(VSTREAM *fp, VSTRING *buffer, int flags) { int prev_type = 0; int rec_type; + struct timeval tv; time_t time; int first = 1; int ch; @@ -142,8 +144,13 @@ static void postcat(VSTREAM *fp, VSTRING *buffer, int flags) 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; diff --git a/postfix/src/postdrop/postdrop.c b/postfix/src/postdrop/postdrop.c index 5bfa810d1..461369cc2 100644 --- a/postfix/src/postdrop/postdrop.c +++ b/postfix/src/postdrop/postdrop.c @@ -372,8 +372,8 @@ int main(int argc, char **argv) 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 */ diff --git a/postfix/src/qmgr/qmgr_message.c b/postfix/src/qmgr/qmgr_message.c index 0bf8d221f..2ffb93011 100644 --- a/postfix/src/qmgr/qmgr_message.c +++ b/postfix/src/qmgr/qmgr_message.c @@ -567,10 +567,7 @@ static int qmgr_message_read(QMGR_MESSAGE *message) } 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) { @@ -680,7 +677,7 @@ static int qmgr_message_read(QMGR_MESSAGE *message) 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; } @@ -790,7 +787,8 @@ void qmgr_message_update_warn(QMGR_MESSAGE *message) */ 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); diff --git a/postfix/src/qmqpd/qmqpd.c b/postfix/src/qmqpd/qmqpd.c index 236cafa3f..558515d4c 100644 --- a/postfix/src/qmqpd/qmqpd.c +++ b/postfix/src/qmqpd/qmqpd.c @@ -252,9 +252,8 @@ static void qmqpd_open_file(QMQPD_STATE *state) * 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); } diff --git a/postfix/src/smtp/smtp.h b/postfix/src/smtp/smtp.h index 6f865f131..c042ad9be 100644 --- a/postfix/src/smtp/smtp.h +++ b/postfix/src/smtp/smtp.h @@ -182,6 +182,7 @@ typedef struct SMTP_SESSION { 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 */ diff --git a/postfix/src/smtp/smtp_proto.c b/postfix/src/smtp/smtp_proto.c index ee415bd71..56429fcc8 100644 --- a/postfix/src/smtp/smtp_proto.c +++ b/postfix/src/smtp/smtp_proto.c @@ -384,7 +384,7 @@ int smtp_helo(SMTP_STATE *state, NOCLOBBER int misc_flags) 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", @@ -415,7 +415,7 @@ int smtp_helo(SMTP_STATE *state, NOCLOBBER int misc_flags) 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); } @@ -1220,7 +1220,7 @@ static int smtp_loop(SMTP_STATE *state, NOCLOBBER int send_state, 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) @@ -1232,7 +1232,7 @@ static int smtp_loop(SMTP_STATE *state, NOCLOBBER int send_state, 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; @@ -1511,7 +1511,7 @@ static int smtp_loop(SMTP_STATE *state, NOCLOBBER int send_state, && request->msg_stats.incoming_arrival.tv_sec < vstream_ftime(session->stream) - var_smtp_pix_thresh) { msg_info("%s: enabling PIX . 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 */ } diff --git a/postfix/src/smtp/smtp_rcpt.c b/postfix/src/smtp/smtp_rcpt.c index 425e939de..1b64f6b06 100644 --- a/postfix/src/smtp/smtp_rcpt.c +++ b/postfix/src/smtp/smtp_rcpt.c @@ -150,7 +150,7 @@ void smtp_rcpt_done(SMTP_STATE *state, SMTP_RESP *resp, RECIPIENT *rcpt) 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); diff --git a/postfix/src/smtp/smtp_session.c b/postfix/src/smtp/smtp_session.c index 6347e2206..e9d8caf60 100644 --- a/postfix/src/smtp/smtp_session.c +++ b/postfix/src/smtp/smtp_session.c @@ -221,6 +221,10 @@ SMTP_SESSION *smtp_session_alloc(VSTREAM *stream, const char *dest, 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; @@ -295,6 +299,7 @@ void smtp_session_free(SMTP_SESSION *session) myfree(session->host); myfree(session->addr); myfree(session->namaddr); + myfree(session->namaddrport); if (session->helo) myfree(session->helo); diff --git a/postfix/src/smtp/smtp_trouble.c b/postfix/src/smtp/smtp_trouble.c index 9e218daa4..82429292d 100644 --- a/postfix/src/smtp/smtp_trouble.c +++ b/postfix/src/smtp/smtp_trouble.c @@ -237,7 +237,7 @@ static int smtp_bulk_fail(SMTP_STATE *state, DSN *dsn, int throttle_queue) 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); @@ -410,7 +410,7 @@ void smtp_rcpt_fail(SMTP_STATE *state, RECIPIENT *rcpt, const char *mta_name, 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); diff --git a/postfix/src/smtpd/smtpd.c b/postfix/src/smtpd/smtpd.c index 9ff30cde1..2832c6527 100644 --- a/postfix/src/smtpd/smtpd.c +++ b/postfix/src/smtpd/smtpd.c @@ -1317,9 +1317,8 @@ static void mail_open_stream(SMTPD_STATE *state) * 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",