postfix-2.3-20051106

postfix/.indent.pro

@@ -42,6 +42,7 @@
 -TCTABLE_ENTRY
 -TDELIVER_ATTR
 -TDELIVER_REQUEST
+-TDELTA_TIME
 -TDICT
 -TDICT_CDBM
 -TDICT_CDBQ

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
+	"delays=a/b/c/d" where a=time before queue manager, including
-	in queue manager; c=connection setup including DNS, HELO
+	message transmission; b=time in queue manager; c=connection
-	and TLS; d=message transmission time. Unlike Victor's example
+	setup including DNS, HELO and TLS; d=message transmission
-	which used time differences, this implementation uses
+	time. Unlike Victor's example which used time differences,
-	absolute times. The decision of what numbers to subtract
+	this implementation uses absolute times. The decision of
-	actually depends on program history, so we want to do it
+	what numbers to subtract actually depends on program history,
-	in one place.  Files: global/log_adhoc.c, smtp/smtp_connect.c,
+	so we want to do it in one place.  Files: global/log_adhoc.c,
-	smtp/smtp_proto.c, smtp/smtp_trouble.c, lmtp/lmtp_proto.c,
+	smtp/smtp_connect.c, smtp/smtp_proto.c, smtp/smtp_trouble.c,
-	lmtp/lmtp_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,

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
+a=time before queue manager, including message transmission; b=time
-setup time including DNS, HELO and TLS; d=message transmission 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

postfix/html/postconf.5.html

@@ -1913,13 +1913,13 @@ Specify a power of 10 in the range from 1 to 100000. </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>
 

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

postfix/proto/postconf.proto

@@ -8653,20 +8653,20 @@ DNS lookup and increases the maximal inbound delivery rate. </p>
 %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>
 

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;
     }

postfix/src/global/log_adhoc.c

@@ -69,6 +69,16 @@
 #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,
@@ -76,11 +86,11 @@ void    log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient,
 		          const char *status)
 {
     static VSTRING *buf;
-    struct timeval delay;
+    DELTA_TIME delay;
-    struct timeval pdelay;		/* time before queue manager */
+    DELTA_TIME pdelay;			/* time before queue manager */
-    struct timeval adelay;		/* queue manager latency */
+    DELTA_TIME adelay;			/* queue manager latency */
-    struct timeval sdelay;		/* connection set-up latency */
+    DELTA_TIME sdelay;			/* connection set-up latency */
-    struct timeval xdelay;		/* transmission 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).dt_sec = (y).tv_sec - (z).tv_sec; \
-	(x).tv_usec = (y).tv_usec - (z).tv_usec; \
+	(x).dt_usec = (y).tv_usec - (z).tv_usec; \
-	if ((x).tv_usec < 0) { \
+	if ((x).dt_usec < 0) { \
-	    (x).tv_usec += 1000000; \
+	    (x).dt_usec += 1000000; \
-	    (x).tv_sec -= 1; \
+	    (x).dt_sec -= 1; \
 	} \
-	if ((x).tv_sec < 0) \
+	if ((x).dt_sec < 0) \
-	    (x).tv_sec = (x).tv_usec = 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 =
+    DELTA_ZERO(adelay);
-	sdelay.tv_sec = sdelay.tv_usec =
+    DELTA_ZERO(sdelay);
-	xdelay.tv_sec = xdelay.tv_usec = 0;
+    DELTA_ZERO(xdelay);
-    if (stats->active_arrival.tv_sec) {
+    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 \
+	if ((x).dt_sec > 9 \
-	    || ((x).tv_sec == 0 && (x).tv_usec < var_delay_resolution)) { \
+	    || ((x).dt_sec == 0 && (x).dt_usec < var_delay_resolution)) { \
-	    vstring_sprintf_append((b), slash "%ld", \
+	    vstring_sprintf_append((b), text "%ld", \
-		(long) (x).tv_sec + ((x).tv_usec > (MILLION / 2))); \
+		(long) (x).dt_sec + ((x).dt_usec > (MILLION / 2))); \
 	} else { \
-	    vstring_sprintf_append((b), slash "%.2g", (x).tv_sec \
+	    vstring_sprintf_append((b), text "%.2g", (x).dt_sec \
-		+ ((x).tv_usec - (x).tv_usec % var_delay_resolution) \
+		+ ((x).dt_usec - (x).dt_usec % var_delay_resolution) \
 		    / DMILLION); \
 	} \
     } while (0)
 
-    vstring_sprintf_append(buf, ", delay=");
+    PRETTY_FORMAT(buf, ", delay=", delay);
-    PRETTY_FORMAT(buf, "", delay);
+    PRETTY_FORMAT(buf, ", delays=", pdelay);
-    vstring_sprintf_append(buf, ", delays=");
-    PRETTY_FORMAT(buf, "", pdelay);
     PRETTY_FORMAT(buf, "/", adelay);
     PRETTY_FORMAT(buf, "/", sdelay);
     PRETTY_FORMAT(buf, "/", xdelay);

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

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",
+    rec_fprintf(stream, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
-		(long) now.tv_sec, (long) now.tv_usec);
+		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",

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.

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",
+    rec_fprintf(cleanup, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
-		(long) info->posting_time.tv_sec,
+		REC_TYPE_TIME_ARG(info->posting_time));
-		(long) info->posting_time.tv_usec);
     rec_fputs(cleanup, REC_TYPE_FROM, sender);
 
     /*

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);
+		REC_TYPE_TIME_SCAN(start, message->arrival_time);
-	    while(ISDIGIT(*start))
-		start++;
-	    message->arrival_time.tv_usec = atol(start);
 	    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);

postfix/src/postcat/postcat.c

@@ -65,6 +65,7 @@
 
 #include <sys_defs.h>
 #include <sys/stat.h>
+#include <sys/time.h>
 #include <stdlib.h>
 #include <unistd.h>
 #include <time.h>
@@ -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;

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",
+    rec_fprintf(dst->stream, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
-		(long) start.tv_sec, (long) start.tv_usec);
+		REC_TYPE_TIME_ARG(start));
     for (;;) {
 	rec_type = rec_get(VSTREAM_IN, buf, var_line_limit);
 	if (rec_type == REC_TYPE_EOF) {		/* request cancelled */

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);
+		REC_TYPE_TIME_SCAN(start, message->arrival_time);
-	    while(ISDIGIT(*start))
-		start++;
-	    message->arrival_time.tv_usec = atol(start);
 	    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);

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",
+    rec_fprintf(state->cleanup, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
-		(long) state->arrival_time.tv_sec,
+		REC_TYPE_TIME_ARG(state->arrival_time));
-		(long) state->arrival_time.tv_usec);
     if (*var_filter_xport)
 	rec_fprintf(state->cleanup, REC_TYPE_FILT, "%s", var_filter_xport);
 }

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 */

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 <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 */
 	    }

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);

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);
 

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);

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",
+	rec_fprintf(state->cleanup, REC_TYPE_TIME, REC_TYPE_TIME_FORMAT,
-		    (long) state->arrival_time.tv_sec,
+		    REC_TYPE_TIME_ARG(state->arrival_time));
-		    (long) state->arrival_time.tv_usec);
 	if (*var_filter_xport)
 	    rec_fprintf(state->cleanup, REC_TYPE_FILT, "%s", var_filter_xport);
 	rec_fprintf(state->cleanup, REC_TYPE_ATTR, "%s=%s",