From: Wietse Venema Date: Sat, 5 Nov 2005 05:00:00 +0000 (-0500) Subject: postfix-2.3-20051105 X-Git-Tag: v2.3-RC1~52 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=efa5bc08d1a160b264fe2f60a31971be738db41c;p=thirdparty%2Fpostfix.git postfix-2.3-20051105 --- diff --git a/postfix/HISTORY b/postfix/HISTORY index b40bd193e..9aab3391e 100644 --- a/postfix/HISTORY +++ b/postfix/HISTORY @@ -11276,9 +11276,9 @@ 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 HELO and - TLS, d=message transmission time. Unlike Victor's example + "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 @@ -11302,8 +11302,25 @@ Apologies for any names omitted. the new "delays=a/b/c/d" logging. Specify a power of 10 in the range from 1 to 100000. File: global/log_adhoc.c. +20051105 + + All delay logging now has sub-second resolution. This means + updating all code that reads or updates the records that + specify when mail arrived, and ensuring that mail submitted + with older Postfix versions produces sensible results. + Files: global/post_mail.c, global/mail_timeofday.[hc], + global/log_adhoc.c, postdrop/postdrop.c, pickup/pickup.c, + cleanup/cleanup_envelope.c, cleanup/cleanup_message.c, + smtpd/smtpd.c, qmqpd/qmqpd.c, *qmgr/qmgr_message.c, + *qmgr/qmgr_active.c, local/forward.c. + Open problems: + "postsuper -r" no longer resets the message arrival time, + because pickup(8) no longer overrides queue file time stamp + information. This can be a problem when mail "on hold" is + released after a long time. + Is it safe to cache a connection after it has been used for more than some number of address verification probes? diff --git a/postfix/RELEASE_NOTES b/postfix/RELEASE_NOTES index cdc3fa4eb..41c376b06 100644 --- a/postfix/RELEASE_NOTES +++ b/postfix/RELEASE_NOTES @@ -17,6 +17,19 @@ 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 20051105 +====================================== + +All delay logging now has sub-second resolution, including the +over-all "delay=nnn" logging. +At this point the Postfix logging for a recipient looks like this: + + Nov 3 16:04:31 myname postfix/smtp[30840]: 19B6B2900FE: + to=, orig_to=, + relay=mail.example.com[1.2.3.4], conn_use=2, delay=0.22, + delays=0.04/0.01/0.05/0.1, dsn=2.0.0, status=sent (250 2.0.0 Ok) + + Incompatibility with snapshot 20051103 ====================================== @@ -41,8 +54,8 @@ 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 HELO and TLS, d=message transmission time. +a=time before queue manager; 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 4533c2c5a..bfbe472e4 100644 --- a/postfix/html/postconf.5.html +++ b/postfix/html/postconf.5.html @@ -1917,7 +1917,7 @@ Specify a power of 10 in the range from 1 to 100000.

  • b = time in queue manager -
  • c = time in connection setup, including EHLO and TLS +
  • c = time in connection setup, including DNS, EHLO and TLS
  • d = time in message transfer diff --git a/postfix/man/man5/postconf.5 b/postfix/man/man5/postconf.5 index 5768d998b..c0be00d98 100644 --- a/postfix/man/man5/postconf.5 +++ b/postfix/man/man5/postconf.5 @@ -1045,7 +1045,7 @@ a = time before the queue manager selected the queue file .IP \(bu b = time in queue manager .IP \(bu -c = time in connection setup, including EHLO and TLS +c = time in connection setup, including DNS, EHLO and TLS .IP \(bu d = time in message transfer .PP diff --git a/postfix/proto/postconf.proto b/postfix/proto/postconf.proto index e5169dbba..cb499c97f 100644 --- a/postfix/proto/postconf.proto +++ b/postfix/proto/postconf.proto @@ -8664,7 +8664,7 @@ Specify a power of 10 in the range from 1 to 100000.

  • b = time in queue manager -
  • c = time in connection setup, including EHLO and TLS +
  • c = time in connection setup, including DNS, EHLO and TLS
  • d = time in message transfer diff --git a/postfix/src/cleanup/cleanup.h b/postfix/src/cleanup/cleanup.h index 57750a849..f701d3571 100644 --- a/postfix/src/cleanup/cleanup.h +++ b/postfix/src/cleanup/cleanup.h @@ -8,6 +8,11 @@ /* DESCRIPTION /* .nf + /* + * System library. + */ +#include + /* * Utility library. */ @@ -40,7 +45,7 @@ typedef struct CLEANUP_STATE { MAIL_STREAM *handle; /* mail stream handle */ char *queue_name; /* queue name */ char *queue_id; /* queue file basename */ - time_t time; /* posting time */ + struct timeval arrival_time; /* arrival time */ char *fullname; /* envelope sender full name */ char *sender; /* envelope sender address */ char *recip; /* envelope recipient address */ @@ -234,7 +239,7 @@ extern int cleanup_bounce(CLEANUP_STATE *); * MSG_STATS compatibility. */ #define CLEANUP_MSG_STATS(stats, state) \ - MSG_STATS_INIT1(stats, incoming_arrival, state->time) + MSG_STATS_INIT1(stats, incoming_arrival, state->arrival_time) /* LICENSE /* .ad diff --git a/postfix/src/cleanup/cleanup_envelope.c b/postfix/src/cleanup/cleanup_envelope.c index 7320bb331..ca0149310 100644 --- a/postfix/src/cleanup/cleanup_envelope.c +++ b/postfix/src/cleanup/cleanup_envelope.c @@ -44,6 +44,7 @@ #include #include #include +#include #ifdef STRCASECMP_IN_STRINGS_H #include @@ -200,7 +201,7 @@ static void cleanup_envelope_process(CLEANUP_STATE *state, int type, state->errs |= CLEANUP_STAT_BAD; return; } - if (state->time == 0) { + if (state->arrival_time.tv_sec == 0) { msg_warn("%s: message rejected: missing time envelope record", state->queue_id); state->errs |= CLEANUP_STAT_BAD; @@ -209,7 +210,7 @@ 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->time + var_delay_warn_time); + (long) state->arrival_time.tv_sec + var_delay_warn_time); } state->flags |= CLEANUP_FLAG_INRCPT; } @@ -298,9 +299,12 @@ static void cleanup_envelope_process(CLEANUP_STATE *state, int type, return; if (type == REC_TYPE_TIME) { /* First instance wins. */ - if (state->time == 0) { - state->time = atol(buf); + if (state->arrival_time.tv_sec == 0) { + state->arrival_time.tv_sec = atol(buf); cleanup_out(state, type, buf, len); + while (ISDIGIT(*buf)) + buf++; + state->arrival_time.tv_usec = atol(buf); } return; } diff --git a/postfix/src/cleanup/cleanup_message.c b/postfix/src/cleanup/cleanup_message.c index a9a010685..644eb94bd 100644 --- a/postfix/src/cleanup/cleanup_message.c +++ b/postfix/src/cleanup/cleanup_message.c @@ -580,6 +580,7 @@ static void cleanup_header_done_callback(void *context) char time_stamp[1024]; /* XXX locale dependent? */ struct tm *tp; TOK822 *token; + time_t tv; /* * Add a missing (Resent-)Message-Id: header. The message ID gives the @@ -592,7 +593,8 @@ static void cleanup_header_done_callback(void *context) */ if ((state->headers_seen & (1 << (state->resent[0] ? HDR_RESENT_MESSAGE_ID : HDR_MESSAGE_ID))) == 0) { - tp = gmtime(&state->time); + tv = state->arrival_time.tv_sec; + tp = gmtime(&tv); strftime(time_stamp, sizeof(time_stamp), "%Y%m%d%H%M%S", tp); cleanup_out_format(state, REC_TYPE_NORM, "%sMessage-Id: <%s.%s@%s>", state->resent, time_stamp, state->queue_id, var_myhostname); @@ -608,7 +610,7 @@ static void cleanup_header_done_callback(void *context) if ((state->headers_seen & (1 << (state->resent[0] ? HDR_RESENT_DATE : HDR_DATE))) == 0) { cleanup_out_format(state, REC_TYPE_NORM, "%sDate: %s", - state->resent, mail_date(state->time)); + state->resent, mail_date(state->arrival_time.tv_sec)); } /* @@ -707,7 +709,7 @@ static void cleanup_message_headerbody(CLEANUP_STATE *state, int type, const char *myname = "cleanup_message_headerbody"; MIME_STATE_DETAIL *detail; const char *cp; - char *dst; + char *dst; /* * Reject unwanted characters. diff --git a/postfix/src/cleanup/cleanup_state.c b/postfix/src/cleanup/cleanup_state.c index 6d5c73036..bc5d68eba 100644 --- a/postfix/src/cleanup/cleanup_state.c +++ b/postfix/src/cleanup/cleanup_state.c @@ -65,7 +65,7 @@ CLEANUP_STATE *cleanup_state_alloc(void) state->handle = 0; state->queue_name = 0; state->queue_id = 0; - state->time = 0; + state->arrival_time.tv_sec = state->arrival_time.tv_usec = 0; state->fullname = 0; state->sender = 0; state->recip = 0; diff --git a/postfix/src/global/Makefile.in b/postfix/src/global/Makefile.in index a03f2a014..5d9c5de30 100644 --- a/postfix/src/global/Makefile.in +++ b/postfix/src/global/Makefile.in @@ -654,61 +654,12 @@ deliver_request.o: mail_proto.h deliver_request.o: mail_queue.h deliver_request.o: msg_stats.h deliver_request.o: recipient_list.h -dict_ldap.o: ../../include/argv.h -dict_ldap.o: ../../include/binhash.h -dict_ldap.o: ../../include/dict.h -dict_ldap.o: ../../include/match_list.h -dict_ldap.o: ../../include/match_ops.h -dict_ldap.o: ../../include/msg.h -dict_ldap.o: ../../include/mymalloc.h -dict_ldap.o: ../../include/stringops.h dict_ldap.o: ../../include/sys_defs.h -dict_ldap.o: ../../include/vbuf.h -dict_ldap.o: ../../include/vstream.h -dict_ldap.o: ../../include/vstring.h -dict_ldap.o: cfg_parser.h -dict_ldap.o: db_common.h dict_ldap.o: dict_ldap.c -dict_ldap.o: dict_ldap.h -dict_ldap.o: string_list.h -dict_mysql.o: ../../include/argv.h -dict_mysql.o: ../../include/dict.h -dict_mysql.o: ../../include/events.h -dict_mysql.o: ../../include/find_inet.h -dict_mysql.o: ../../include/match_list.h -dict_mysql.o: ../../include/match_ops.h -dict_mysql.o: ../../include/msg.h -dict_mysql.o: ../../include/mymalloc.h -dict_mysql.o: ../../include/myrand.h -dict_mysql.o: ../../include/split_at.h dict_mysql.o: ../../include/sys_defs.h -dict_mysql.o: ../../include/vbuf.h -dict_mysql.o: ../../include/vstream.h -dict_mysql.o: ../../include/vstring.h -dict_mysql.o: cfg_parser.h -dict_mysql.o: db_common.h dict_mysql.o: dict_mysql.c -dict_mysql.o: dict_mysql.h -dict_mysql.o: string_list.h -dict_pgsql.o: ../../include/argv.h -dict_pgsql.o: ../../include/dict.h -dict_pgsql.o: ../../include/events.h -dict_pgsql.o: ../../include/find_inet.h -dict_pgsql.o: ../../include/match_list.h -dict_pgsql.o: ../../include/match_ops.h -dict_pgsql.o: ../../include/msg.h -dict_pgsql.o: ../../include/mymalloc.h -dict_pgsql.o: ../../include/myrand.h -dict_pgsql.o: ../../include/split_at.h dict_pgsql.o: ../../include/sys_defs.h -dict_pgsql.o: ../../include/vbuf.h -dict_pgsql.o: ../../include/vstream.h -dict_pgsql.o: ../../include/vstring.h -dict_pgsql.o: cfg_parser.h -dict_pgsql.o: db_common.h dict_pgsql.o: dict_pgsql.c -dict_pgsql.o: dict_pgsql.h -dict_pgsql.o: string_list.h dict_proxy.o: ../../include/argv.h dict_proxy.o: ../../include/attr.h dict_proxy.o: ../../include/dict.h diff --git a/postfix/src/global/log_adhoc.c b/postfix/src/global/log_adhoc.c index 7eb9d3648..1237bce7e 100644 --- a/postfix/src/global/log_adhoc.c +++ b/postfix/src/global/log_adhoc.c @@ -76,8 +76,8 @@ void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, const char *status) { static VSTRING *buf; - int delay; - int pdelay; /* time before queue manager */ + 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 */ @@ -138,12 +138,13 @@ void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, now = stats->deliver_done; else GETTIMEOFDAY(&now); - delay = now.tv_sec - stats->incoming_arrival; + + 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) { - pdelay = stats->active_arrival.tv_sec - stats->incoming_arrival; + DELTA(pdelay, stats->active_arrival, stats->incoming_arrival); if (stats->agent_handoff.tv_sec) { DELTA(adelay, stats->agent_handoff, stats->active_arrival); if (stats->conn_setup_done.tv_sec) { @@ -159,31 +160,41 @@ void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, } } else { /* No queue manager. */ - pdelay = now.tv_sec - stats->incoming_arrival; + 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. + */ #define MILLION 1000000 #define DMILLION ((double) MILLION) -#define PRETTY_FORMAT(b, x) \ +#define PRETTY_FORMAT(b, slash, x) \ do { \ if ((x).tv_sec > 9 \ || ((x).tv_sec == 0 && (x).tv_usec < var_delay_resolution)) { \ - vstring_sprintf_append((b), "/%ld", \ + vstring_sprintf_append((b), slash "%ld", \ (long) (x).tv_sec + ((x).tv_usec > (MILLION / 2))); \ } else { \ - vstring_sprintf_append((b), "/%.2g", \ - (x).tv_sec + ((x).tv_usec / var_delay_resolution) \ - * (var_delay_resolution / DMILLION)); \ + vstring_sprintf_append((b), slash "%.2g", (x).tv_sec \ + + ((x).tv_usec - (x).tv_usec % var_delay_resolution) \ + / DMILLION); \ } \ } while (0) - vstring_sprintf_append(buf, ", delay=%d, delays=%d", delay, pdelay); - PRETTY_FORMAT(buf, adelay); - PRETTY_FORMAT(buf, sdelay); - PRETTY_FORMAT(buf, xdelay); + vstring_sprintf_append(buf, ", delay="); + PRETTY_FORMAT(buf, "", delay); + vstring_sprintf_append(buf, ", delays="); + PRETTY_FORMAT(buf, "", pdelay); + PRETTY_FORMAT(buf, "/", adelay); + PRETTY_FORMAT(buf, "/", sdelay); + PRETTY_FORMAT(buf, "/", xdelay); /* * Finally, the delivery status. diff --git a/postfix/src/global/mail_version.h b/postfix/src/global/mail_version.h index 16ea26f21..6ce77da97 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 "20051104" +#define MAIL_RELEASE_DATE "20051105" #define MAIL_VERSION_NUMBER "2.3" #ifdef SNAPSHOT diff --git a/postfix/src/global/msg_stats.h b/postfix/src/global/msg_stats.h index ea24921f0..f71406cd6 100644 --- a/postfix/src/global/msg_stats.h +++ b/postfix/src/global/msg_stats.h @@ -53,7 +53,7 @@ * values. */ typedef struct { - time_t incoming_arrival; /* incoming queue entry */ + struct timeval incoming_arrival; /* incoming queue entry */ struct timeval active_arrival; /* active queue entry */ struct timeval agent_handoff; /* delivery agent hand-off */ struct timeval conn_setup_done; /* connection set-up done */ diff --git a/postfix/src/global/post_mail.c b/postfix/src/global/post_mail.c index 93850d934..09cd26829 100644 --- a/postfix/src/global/post_mail.c +++ b/postfix/src/global/post_mail.c @@ -135,7 +135,7 @@ /* System library. */ #include -#include +#include #include /* 44BSD stdarg.h uses abort() */ #include #include @@ -178,8 +178,11 @@ static void post_mail_init(VSTREAM *stream, const char *sender, int cleanup_flags, int trace_flags) { VSTRING *id = vstring_alloc(100); - long now = time((time_t *) 0); - const char *date = mail_date(now); + struct timeval now; + const char *date; + + GETTIMEOFDAY(&now); + date = mail_date(now.tv_sec); /* * Negotiate with the cleanup service. Give up if we can't agree. @@ -196,7 +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", (long) now); + rec_fprintf(stream, REC_TYPE_TIME, "%ld %ld", + (long) now.tv_sec, (long) now.tv_usec); 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/local/forward.c b/postfix/src/local/forward.c index de15ef213..28326c536 100644 --- a/postfix/src/local/forward.c +++ b/postfix/src/local/forward.c @@ -53,8 +53,8 @@ /* System library. */ #include +#include #include -#include /* Utility library. */ @@ -92,7 +92,7 @@ static HTABLE *forward_dt; typedef struct FORWARD_INFO { VSTREAM *cleanup; /* clean up service handle */ char *queue_id; /* forwarded message queue id */ - time_t posting_time; /* posting time */ + struct timeval posting_time; /* posting time */ } FORWARD_INFO; /* forward_init - prepare for forwarding */ @@ -140,7 +140,7 @@ static FORWARD_INFO *forward_open(DELIVER_REQUEST *request, const char *sender) info = (FORWARD_INFO *) mymalloc(sizeof(FORWARD_INFO)); info->cleanup = cleanup; info->queue_id = mystrdup(STR(buffer)); - info->posting_time = time((time_t *) 0); + GETTIMEOFDAY(&info->posting_time); #define FORWARD_CLEANUP_FLAGS (CLEANUP_FLAG_BOUNCE | CLEANUP_FLAG_MASK_INTERNAL) @@ -152,7 +152,9 @@ 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", (long) info->posting_time); + rec_fprintf(cleanup, REC_TYPE_TIME, "%ld %ld", + (long) info->posting_time.tv_sec, + (long) info->posting_time.tv_usec); rec_fputs(cleanup, REC_TYPE_FROM, sender); /* @@ -257,7 +259,7 @@ static int forward_send(FORWARD_INFO *info, DELIVER_REQUEST *request, rec_fprintf(info->cleanup, REC_TYPE_NORM, "Received: by %s (%s)", var_myhostname, var_mail_name); rec_fprintf(info->cleanup, REC_TYPE_NORM, "\tid %s; %s", - info->queue_id, mail_date(info->posting_time)); + info->queue_id, mail_date(info->posting_time.tv_sec)); if (local_deliver_hdr_mask & DELIVER_HDR_FWD) rec_fprintf(info->cleanup, REC_TYPE_NORM, "Delivered-To: %s", lowercase(STR(buffer))); @@ -364,4 +366,3 @@ int forward_finish(DELIVER_REQUEST *request, DELIVER_ATTR attr, int cancel) forward_dt = 0; return (status); } - diff --git a/postfix/src/oqmgr/qmgr.h b/postfix/src/oqmgr/qmgr.h index 1ce8bc377..5966b8df8 100644 --- a/postfix/src/oqmgr/qmgr.h +++ b/postfix/src/oqmgr/qmgr.h @@ -209,7 +209,7 @@ struct QMGR_MESSAGE { VSTREAM *fp; /* open queue file or null */ int refcount; /* queue entries */ int single_rcpt; /* send one rcpt at a time */ - long arrival_time; /* time when queued */ + struct timeval arrival_time; /* time when queued */ struct timeval active_time; /* time of entry into active queue */ long warn_offset; /* warning bounce flag offset */ time_t warn_time; /* time next warning to be sent */ diff --git a/postfix/src/oqmgr/qmgr_active.c b/postfix/src/oqmgr/qmgr_active.c index 152665343..b2136b1e9 100644 --- a/postfix/src/oqmgr/qmgr_active.c +++ b/postfix/src/oqmgr/qmgr_active.c @@ -403,7 +403,7 @@ static void qmgr_active_done_2_generic(QMGR_MESSAGE *message) * daemon waits for the qmgr to accept the "new mail" trigger. */ if (message->flags) { - if (event_time() >= message->arrival_time + + if (event_time() >= message->arrival_time.tv_sec + (*message->sender ? var_max_queue_time : var_dsn_queue_time)) { msg_info("%s: from=<%s>, status=expired, returned to sender", message->queue_id, message->sender); @@ -498,8 +498,8 @@ static void qmgr_active_done_3_generic(QMGR_MESSAGE *message) * queue scans is finite. */ if (message->flags) { - if (message->arrival_time > 0) { - delay = event_time() - message->arrival_time; + if (message->arrival_time.tv_sec > 0) { + delay = event_time() - message->arrival_time.tv_sec; if (delay > var_max_backoff_time) delay = var_max_backoff_time; if (delay < var_min_backoff_time) diff --git a/postfix/src/oqmgr/qmgr_message.c b/postfix/src/oqmgr/qmgr_message.c index cae8af502..d437a160c 100644 --- a/postfix/src/oqmgr/qmgr_message.c +++ b/postfix/src/oqmgr/qmgr_message.c @@ -91,6 +91,7 @@ #include #include #include +#include #ifdef STRCASECMP_IN_STRINGS_H #include @@ -155,7 +156,7 @@ static QMGR_MESSAGE *qmgr_message_create(const char *queue_name, message->fp = 0; message->refcount = 0; message->single_rcpt = 0; - message->arrival_time = 0; + message->arrival_time.tv_sec = message->arrival_time.tv_usec = 0; GETTIMEOFDAY(&message->active_time); message->data_offset = 0; message->queue_id = mystrdup(queue_id); @@ -532,8 +533,11 @@ static int qmgr_message_read(QMGR_MESSAGE *message) continue; } if (rec_type == REC_TYPE_TIME) { - if (message->arrival_time == 0) - message->arrival_time = atol(start); + 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); continue; } if (rec_type == REC_TYPE_FILT) { @@ -717,7 +721,7 @@ static int qmgr_message_read(QMGR_MESSAGE *message) */ if (rec_type <= 0) { /* Already logged warning. */ - } else if (message->arrival_time == 0) { + } else if (message->arrival_time.tv_sec == 0) { msg_warn("%s: message rejected: missing arrival time record", message->queue_id); } else if (message->sender == 0) { diff --git a/postfix/src/pickup/pickup.c b/postfix/src/pickup/pickup.c index 2272a3c74..fa352280b 100644 --- a/postfix/src/pickup/pickup.c +++ b/postfix/src/pickup/pickup.c @@ -198,6 +198,7 @@ static int copy_segment(VSTREAM *qfile, VSTREAM *cleanup, PICKUP_INFO *info, { int type; int check_first = (*expected == REC_TYPE_CONTENT[0]); + int time_seen = 0; /* * Limit the input record size. All front-end programs should protect the @@ -219,12 +220,16 @@ static int copy_segment(VSTREAM *qfile, VSTREAM *cleanup, PICKUP_INFO *info, msg_info("%s: read %c %s", info->id, type, vstring_str(buf)); if (type == *expected) break; - if (type == REC_TYPE_FROM) + if (type == REC_TYPE_FROM) { if (info->sender == 0) info->sender = mystrdup(vstring_str(buf)); + /* Compatibility with Postfix < 2.3. */ + if (time_seen == 0) + rec_fprintf(cleanup, REC_TYPE_TIME, "%ld", + (long) info->st.st_mtime); + } if (type == REC_TYPE_TIME) - /* Use our own arrival time record instead. */ - continue; + time_seen = 1; /* * XXX Workaround: REC_TYPE_FILT (used in envelopes) == REC_TYPE_CONT @@ -278,11 +283,6 @@ static int pickup_copy(VSTREAM *qfile, VSTREAM *cleanup, info->id, (int) (now - info->st.st_mtime) / DAY_SECONDS); } - /* - * Make sure the message has a posting-time record. - */ - rec_fprintf(cleanup, REC_TYPE_TIME, "%ld", (long) info->st.st_mtime); - /* * Add content inspection transport. */ diff --git a/postfix/src/postdrop/postdrop.c b/postfix/src/postdrop/postdrop.c index 222756224..5bfa810d1 100644 --- a/postfix/src/postdrop/postdrop.c +++ b/postfix/src/postdrop/postdrop.c @@ -228,6 +228,7 @@ int main(int argc, char **argv) char *attr_value; const char *errstr; char *junk; + struct timeval start; /* * Be consistent with file permissions. @@ -335,6 +336,11 @@ int main(int argc, char **argv) /* End of initializations. */ + /* + * Don't trust the caller's time information. + */ + GETTIMEOFDAY(&start); + /* * Create queue file. mail_stream_file() never fails. Send the queue ID * to the caller. Stash away a copy of the queue file name so we can @@ -365,6 +371,9 @@ int main(int argc, char **argv) vstream_control(VSTREAM_IN, VSTREAM_CTL_PATH, "stdin", VSTREAM_CTL_END); 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); for (;;) { rec_type = rec_get(VSTREAM_IN, buf, var_line_limit); if (rec_type == REC_TYPE_EOF) { /* request cancelled */ @@ -383,6 +392,9 @@ int main(int argc, char **argv) msg_fatal("uid=%ld: unexpected record type: %d", (long) uid, rec_type); if (rec_type == **expected) expected++; + /* Override time information from the untrusted caller. */ + if (rec_type == REC_TYPE_TIME) + continue; if (rec_type == REC_TYPE_ATTR) { if ((error_text = split_nameval(vstring_str(buf), &attr_name, &attr_value)) != 0) { diff --git a/postfix/src/qmgr/qmgr.h b/postfix/src/qmgr/qmgr.h index 7225920eb..83be8073e 100644 --- a/postfix/src/qmgr/qmgr.h +++ b/postfix/src/qmgr/qmgr.h @@ -247,7 +247,7 @@ struct QMGR_MESSAGE { VSTREAM *fp; /* open queue file or null */ int refcount; /* queue entries */ int single_rcpt; /* send one rcpt at a time */ - long arrival_time; /* time when queued */ + struct timeval arrival_time; /* time when queued */ struct timeval active_time; /* time of entry into active queue */ time_t queued_time; /* sanitized time when moved to the * active queue */ diff --git a/postfix/src/qmgr/qmgr_active.c b/postfix/src/qmgr/qmgr_active.c index 152665343..b2136b1e9 100644 --- a/postfix/src/qmgr/qmgr_active.c +++ b/postfix/src/qmgr/qmgr_active.c @@ -403,7 +403,7 @@ static void qmgr_active_done_2_generic(QMGR_MESSAGE *message) * daemon waits for the qmgr to accept the "new mail" trigger. */ if (message->flags) { - if (event_time() >= message->arrival_time + + if (event_time() >= message->arrival_time.tv_sec + (*message->sender ? var_max_queue_time : var_dsn_queue_time)) { msg_info("%s: from=<%s>, status=expired, returned to sender", message->queue_id, message->sender); @@ -498,8 +498,8 @@ static void qmgr_active_done_3_generic(QMGR_MESSAGE *message) * queue scans is finite. */ if (message->flags) { - if (message->arrival_time > 0) { - delay = event_time() - message->arrival_time; + if (message->arrival_time.tv_sec > 0) { + delay = event_time() - message->arrival_time.tv_sec; if (delay > var_max_backoff_time) delay = var_max_backoff_time; if (delay < var_min_backoff_time) diff --git a/postfix/src/qmgr/qmgr_message.c b/postfix/src/qmgr/qmgr_message.c index da481b847..0bf8d221f 100644 --- a/postfix/src/qmgr/qmgr_message.c +++ b/postfix/src/qmgr/qmgr_message.c @@ -99,6 +99,7 @@ #include #include #include +#include #ifdef STRCASECMP_IN_STRINGS_H #include @@ -164,7 +165,7 @@ static QMGR_MESSAGE *qmgr_message_create(const char *queue_name, message->fp = 0; message->refcount = 0; message->single_rcpt = 0; - message->arrival_time = 0; + message->arrival_time.tv_sec = message->arrival_time.tv_usec = 0; GETTIMEOFDAY(&message->active_time); message->queued_time = sane_time(); message->data_offset = 0; @@ -565,8 +566,11 @@ static int qmgr_message_read(QMGR_MESSAGE *message) continue; } if (rec_type == REC_TYPE_TIME) { - if (message->arrival_time == 0) - message->arrival_time = atol(start); + 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); continue; } if (rec_type == REC_TYPE_FILT) { @@ -756,7 +760,7 @@ static int qmgr_message_read(QMGR_MESSAGE *message) } if (rec_type <= 0) { /* Already logged warning. */ - } else if (message->arrival_time == 0) { + } else if (message->arrival_time.tv_sec == 0) { msg_warn("%s: message rejected: missing arrival time record", message->queue_id); } else if (message->sender == 0) { diff --git a/postfix/src/qmqpd/qmqpd.c b/postfix/src/qmqpd/qmqpd.c index 4ff79341c..236cafa3f 100644 --- a/postfix/src/qmqpd/qmqpd.c +++ b/postfix/src/qmqpd/qmqpd.c @@ -252,7 +252,9 @@ 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", (long) state->time); + rec_fprintf(state->cleanup, REC_TYPE_TIME, "%ld %ld", + (long) state->arrival_time.tv_sec, + (long) state->arrival_time.tv_usec); if (*var_filter_xport) rec_fprintf(state->cleanup, REC_TYPE_FILT, "%s", var_filter_xport); } @@ -406,13 +408,15 @@ static void qmqpd_write_content(QMQPD_STATE *state) state->protocol, state->queue_id); quote_822_local(state->buf, state->recipient); rec_fprintf(state->cleanup, REC_TYPE_NORM, - "\tfor <%s>; %s", STR(state->buf), mail_date(state->time)); + "\tfor <%s>; %s", STR(state->buf), + mail_date(state->arrival_time.tv_sec)); } else { rec_fprintf(state->cleanup, REC_TYPE_NORM, "\tby %s (%s) with %s", var_myhostname, var_mail_name, state->protocol); rec_fprintf(state->cleanup, REC_TYPE_NORM, - "\tid %s; %s", state->queue_id, mail_date(state->time)); + "\tid %s; %s", state->queue_id, + mail_date(state->arrival_time.tv_sec)); } #ifdef RECEIVED_ENVELOPE_FROM quote_822_local(state->buf, state->sender); diff --git a/postfix/src/qmqpd/qmqpd.h b/postfix/src/qmqpd/qmqpd.h index c782359b2..01d89f710 100644 --- a/postfix/src/qmqpd/qmqpd.h +++ b/postfix/src/qmqpd/qmqpd.h @@ -11,7 +11,7 @@ /* * System library. */ -#include +#include /* * Utility library. @@ -32,7 +32,7 @@ typedef struct { VSTREAM *client; /* client connection */ VSTRING *message; /* message buffer */ VSTRING *buf; /* line buffer */ - time_t time; /* start of session */ + struct timeval arrival_time; /* start of session */ char *name; /* client name */ char *addr; /* client IP address */ char *namaddr; /* name[addr] */ diff --git a/postfix/src/qmqpd/qmqpd_state.c b/postfix/src/qmqpd/qmqpd_state.c index 6f0240d9e..1062f4873 100644 --- a/postfix/src/qmqpd/qmqpd_state.c +++ b/postfix/src/qmqpd/qmqpd_state.c @@ -64,7 +64,7 @@ QMQPD_STATE *qmqpd_state_alloc(VSTREAM *stream) state->client = stream; state->message = vstring_alloc(1000); state->buf = vstring_alloc(100); - state->time = time((time_t *) 0); + GETTIMEOFDAY(&state->arrival_time); qmqpd_peer_init(state); state->queue_id = 0; state->cleanup = 0; diff --git a/postfix/src/smtp/smtp_proto.c b/postfix/src/smtp/smtp_proto.c index 21a1189e1..ee415bd71 100644 --- a/postfix/src/smtp/smtp_proto.c +++ b/postfix/src/smtp/smtp_proto.c @@ -1508,8 +1508,8 @@ static int smtp_loop(SMTP_STATE *state, NOCLOBBER int send_state, } else if (prev_type == REC_TYPE_CONT) /* missing newline */ smtp_fputs("", 0, session->stream); if ((session->features & SMTP_FEATURE_MAYBEPIX) != 0 - && request->msg_stats.incoming_arrival < vstream_ftime(session->stream) - - var_smtp_pix_thresh) { + && 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); smtp_flush(session->stream); /* hurts performance */ diff --git a/postfix/src/smtpd/smtpd.c b/postfix/src/smtpd/smtpd.c index 8728e6752..9ff30cde1 100644 --- a/postfix/src/smtpd/smtpd.c +++ b/postfix/src/smtpd/smtpd.c @@ -757,7 +757,6 @@ #include /* remove() */ #include #include -#include #include #include #include @@ -1318,7 +1317,9 @@ static void mail_open_stream(SMTPD_STATE *state) * attributes. */ if (SMTPD_STAND_ALONE(state) == 0) { - rec_fprintf(state->cleanup, REC_TYPE_TIME, "%ld", (long) state->time); + rec_fprintf(state->cleanup, REC_TYPE_TIME, "%ld %ld", + (long) state->arrival_time.tv_sec, + (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", @@ -1685,10 +1686,11 @@ static int mail_cmd(SMTPD_STATE *state, int argc, SMTPD_TOKEN *argv) /* * No more early returns. The mail transaction is in progress. */ - state->time = time((time_t *) 0); + GETTIMEOFDAY(&state->arrival_time); state->sender = mystrdup(STR(state->addr_buf)); - vstring_sprintf(state->instance, "%x.%lx.%x", - var_pid, (unsigned long) state->time, state->seqno++); + vstring_sprintf(state->instance, "%x.%lx.%lx.%x", + var_pid, (unsigned long) state->arrival_time.tv_sec, + (unsigned long) state->arrival_time.tv_usec, state->seqno++); if (verp_delims) state->verp_delims = mystrdup(verp_delims); if (dsn_envid) @@ -2203,7 +2205,8 @@ static int data_cmd(SMTPD_STATE *state, int argc, SMTPD_TOKEN *unused_argv) state->protocol, state->queue_id); quote_822_local(state->buffer, state->recipient); out_fprintf(out_stream, REC_TYPE_NORM, - "\tfor <%s>; %s", STR(state->buffer), mail_date(state->time)); + "\tfor <%s>; %s", STR(state->buffer), + mail_date(state->arrival_time.tv_sec)); } else { out_fprintf(out_stream, REC_TYPE_NORM, state->cleanup ? "\tby %s (%s) with %s id %s;" : @@ -2211,7 +2214,7 @@ static int data_cmd(SMTPD_STATE *state, int argc, SMTPD_TOKEN *unused_argv) var_myhostname, var_mail_name, state->protocol, state->queue_id); out_fprintf(out_stream, REC_TYPE_NORM, - "\t%s", mail_date(state->time)); + "\t%s", mail_date(state->arrival_time.tv_sec)); } #ifdef RECEIVED_ENVELOPE_FROM quote_822_local(state->buffer, state->sender); diff --git a/postfix/src/smtpd/smtpd.h b/postfix/src/smtpd/smtpd.h index 80a0a5de4..461cfb374 100644 --- a/postfix/src/smtpd/smtpd.h +++ b/postfix/src/smtpd/smtpd.h @@ -11,6 +11,7 @@ /* * System library. */ +#include #include /* @@ -73,7 +74,7 @@ typedef struct SMTPD_STATE { VSTRING *buffer; /* SMTP client buffer */ VSTRING *addr_buf; /* internalized address buffer */ char *service; /* for event rate control */ - time_t time; /* start of MAIL FROM transaction */ + struct timeval arrival_time; /* start of MAIL FROM transaction */ char *name; /* verified client hostname */ char *reverse_name; /* unverified client hostname */ #ifdef FORWARD_CLIENT_NAME