From 32dfdf8baa8ccf091a0d5d4d75e8627424898756 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Fri, 4 Aug 2017 15:13:17 +0100 Subject: [PATCH] Logging: millisecond QT and DT. Bug 2102 --- doc/doc-docbook/spec.xfpt | 6 +- src/exim_monitor/em_globals.c | 2 +- src/exim_monitor/em_queue.c | 2 +- src/src/deliver.c | 102 +++++++++++++++++++++++++--------- src/src/exim.c | 9 +-- src/src/expand.c | 4 +- src/src/functions.h | 4 +- src/src/globals.c | 3 +- src/src/globals.h | 2 +- src/src/queue.c | 2 +- src/src/readconf.c | 8 +-- src/src/receive.c | 4 +- src/src/retry.c | 8 +-- src/src/spool_in.c | 14 ++++- src/src/spool_out.c | 26 +++++---- src/src/structs.h | 1 + src/src/transport.c | 5 +- src/src/transports/smtp.c | 15 +++-- test/log/0506 | 2 +- test/log/0551 | 8 +-- test/runtest | 9 ++- test/scripts/0000-Basic/0551 | 4 +- test/stdout/0035 | 7 +++ test/stdout/0245 | 1 + test/stdout/0250 | 3 + test/stdout/0254 | 3 + test/stdout/0311 | 2 + test/stdout/0338 | 1 + test/stdout/0377 | 1 + test/stdout/0378 | 1 + test/stdout/0379 | 1 + test/stdout/0389 | 1 + test/stdout/0488 | 1 + test/stdout/0490 | 1 + test/stdout/0514 | 1 + test/stdout/0551 | 8 +-- test/stdout/3415 | 5 ++ 37 files changed, 191 insertions(+), 86 deletions(-) diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index a4b1926ec..0d03c2f9c 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -36118,7 +36118,7 @@ selection marked by asterisks: &` incoming_interface `& local interface on <= and => lines &` incoming_port `& remote port on <= lines &`*lost_incoming_connection `& as it says (includes timeouts) -&` millisec `& millisecond timestamps +&` millisec `& millisecond timestamps and QT/DT times &` outgoing_interface `& local interface on => lines &` outgoing_port `& add remote port to => lines &`*queue_run `& start and end queue runs @@ -36208,6 +36208,8 @@ process is started because &%queue_only%& is set or &%-odq%& was used. .cindex "log" "delivery duration" &%deliver_time%&: For each delivery, the amount of real time it has taken to perform the actual delivery is logged as DT=<&'time'&>, for example, &`DT=1s`&. +If millisecond logging is enabled, short times will be shown with greater +precision, eg. &`DT=0.304`&. .next .cindex "log" "message size on delivery" .cindex "size" "of message" @@ -36329,6 +36331,8 @@ includes reception time as well as the delivery time for the current address. This means that it may be longer than the difference between the arrival and delivery log line times, because the arrival log line is not written until the message has been successfully received. +If millisecond logging is enabled, short times will be shown with greater +precision, eg. &`QT=1.578s`&. .next &%queue_time_overall%&: The amount of time the message has been in the queue on the local host is logged as QT=<&'time'&> on &"Completed"& lines, for diff --git a/src/exim_monitor/em_globals.c b/src/exim_monitor/em_globals.c index 54032362c..46ad834da 100644 --- a/src/exim_monitor/em_globals.c +++ b/src/exim_monitor/em_globals.c @@ -191,7 +191,7 @@ uschar *queue_name = US""; int received_count = 0; uschar *received_protocol = NULL; -int received_time = 0; +struct timeval received_time = { 0, 0 }; int recipients_count = 0; recipient_item *recipients_list = NULL; int recipients_list_max = 0; diff --git a/src/exim_monitor/em_queue.c b/src/exim_monitor/em_queue.c index cb284eb48..e6b1e91d9 100644 --- a/src/exim_monitor/em_queue.c +++ b/src/exim_monitor/em_queue.c @@ -204,7 +204,7 @@ if it's there. */ else { - q->update_time = q->input_time = received_time; + q->update_time = q->input_time = received_time.tv_sec; if ((p = strstric(sender_address+1, qualify_domain, FALSE)) != NULL && *(--p) == '@') *p = 0; } diff --git a/src/src/deliver.c b/src/src/deliver.c index 49281f93d..2713cc56f 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -382,6 +382,7 @@ for (addr2 = addr->next; addr2; addr2 = addr2->next) addr2->transport_return = addr->transport_return; addr2->basic_errno = addr->basic_errno; addr2->more_errno = addr->more_errno; + addr2->delivery_usec = addr->delivery_usec; addr2->special_action = addr->special_action; addr2->message = addr->message; addr2->user_message = addr->user_message; @@ -1029,6 +1030,43 @@ return str; } + +void +timesince(struct timeval * diff, struct timeval * then) +{ +gettimeofday(diff, NULL); +diff->tv_sec -= then->tv_sec; +if ((diff->tv_usec -= then->tv_usec) < 0) + { + diff->tv_sec--; + diff->tv_usec += 1000*1000; + } +} + + + +static uschar * +string_timediff(struct timeval * diff) +{ +static uschar buf[sizeof("0.000s")]; + +if (diff->tv_sec >= 5 || !LOGGING(millisec)) + return readconf_printtime((int)diff->tv_sec); + +sprintf(CS buf, "%d.%03ds", (int)diff->tv_sec, (int)diff->tv_usec/1000); +return buf; +} + + +static uschar * +string_timesince(struct timeval * then) +{ +struct timeval diff; + +timesince(&diff, then); +return string_timediff(&diff); +} + /******************************************************************************/ @@ -1191,11 +1229,13 @@ if ( LOGGING(smtp_confirmation) if (LOGGING(queue_time)) s = string_append(s, &size, &ptr, 2, US" QT=", - readconf_printtime( (int) ((long)time(NULL) - (long)received_time)) ); + string_timesince(&received_time)); if (LOGGING(deliver_time)) - s = string_append(s, &size, &ptr, 2, US" DT=", - readconf_printtime(addr->more_errno)); + { + struct timeval diff = {addr->more_errno, addr->delivery_usec}; + s = string_append(s, &size, &ptr, 2, US" DT=", string_timediff(&diff)); + } /* string_cat() always leaves room for the terminator. Release the store we used to build the line after writing it. */ @@ -2347,6 +2387,7 @@ if ((pid = fork()) == 0) || (ret = write(pfd[pipe_write], &addr2->flags, sizeof(addr2->flags))) != sizeof(addr2->flags) || (ret = write(pfd[pipe_write], &addr2->basic_errno, sizeof(int))) != sizeof(int) || (ret = write(pfd[pipe_write], &addr2->more_errno, sizeof(int))) != sizeof(int) + || (ret = write(pfd[pipe_write], &addr2->delivery_usec, sizeof(int))) != sizeof(int) || (ret = write(pfd[pipe_write], &addr2->special_action, sizeof(int))) != sizeof(int) || (ret = write(pfd[pipe_write], &addr2->transport, sizeof(transport_instance *))) != sizeof(transport_instance *) @@ -2414,6 +2455,7 @@ for (addr2 = addr; addr2; addr2 = addr2->next) len = read(pfd[pipe_read], &addr2->flags, sizeof(addr2->flags)); len = read(pfd[pipe_read], &addr2->basic_errno, sizeof(int)); len = read(pfd[pipe_read], &addr2->more_errno, sizeof(int)); + len = read(pfd[pipe_read], &addr2->delivery_usec, sizeof(int)); len = read(pfd[pipe_read], &addr2->special_action, sizeof(int)); len = read(pfd[pipe_read], &addr2->transport, sizeof(transport_instance *)); @@ -2639,8 +2681,8 @@ time_t now = time(NULL); while (addr_local) { - time_t delivery_start; - int deliver_time; + struct timeval delivery_start; + struct timeval deliver_time; address_item *addr2, *addr3, *nextaddr; int logflags = LOG_MAIN; int logchar = dont_deliver? '*' : '='; @@ -2936,9 +2978,10 @@ while (addr_local) single delivery. */ deliver_set_expansions(addr); - delivery_start = time(NULL); + + gettimeofday(&delivery_start, NULL); deliver_local(addr, FALSE); - deliver_time = (int)(time(NULL) - delivery_start); + timesince(&deliver_time, &delivery_start); /* If a shadow transport (which must perforce be another local transport), is defined, and its condition is met, we must pass the message to the shadow @@ -3075,7 +3118,11 @@ while (addr_local) /* Done with this address */ - if (result == OK) addr2->more_errno = deliver_time; + if (result == OK) + { + addr2->more_errno = deliver_time.tv_sec; + addr2->delivery_usec = deliver_time.tv_usec; + } post_process_one(addr2, result, logflags, DTYPE_TRANSPORT, logchar); /* If a pipe delivery generated text to be sent back, the result may be @@ -3417,9 +3464,9 @@ while (!done) r->flags = *ptr++; r->key = string_copy(ptr); while (*ptr++); - memcpy(&(r->basic_errno), ptr, sizeof(r->basic_errno)); + memcpy(&r->basic_errno, ptr, sizeof(r->basic_errno)); ptr += sizeof(r->basic_errno); - memcpy(&(r->more_errno), ptr, sizeof(r->more_errno)); + memcpy(&r->more_errno, ptr, sizeof(r->more_errno)); ptr += sizeof(r->more_errno); r->message = *ptr ? string_copy(ptr) : NULL; DEBUG(D_deliver|D_retry) debug_printf(" added %s item\n", @@ -3561,11 +3608,13 @@ while (!done) DEBUG(D_deliver) debug_printf("A0 %s tret %d\n", addr->address, *ptr); addr->transport_return = *ptr++; addr->special_action = *ptr++; - memcpy(&(addr->basic_errno), ptr, sizeof(addr->basic_errno)); + memcpy(&addr->basic_errno, ptr, sizeof(addr->basic_errno)); ptr += sizeof(addr->basic_errno); - memcpy(&(addr->more_errno), ptr, sizeof(addr->more_errno)); + memcpy(&addr->more_errno, ptr, sizeof(addr->more_errno)); ptr += sizeof(addr->more_errno); - memcpy(&(addr->flags), ptr, sizeof(addr->flags)); + memcpy(&addr->delivery_usec, ptr, sizeof(addr->delivery_usec)); + ptr += sizeof(addr->delivery_usec); + memcpy(&addr->flags, ptr, sizeof(addr->flags)); ptr += sizeof(addr->flags); addr->message = *ptr ? string_copy(ptr) : NULL; while(*ptr++); @@ -4815,9 +4864,9 @@ for (delivery_count = 0; addr_remote; delivery_count++) { sprintf(CS big_buffer, "%c%.500s", r->flags, r->key); ptr = big_buffer + Ustrlen(big_buffer+2) + 3; - memcpy(ptr, &(r->basic_errno), sizeof(r->basic_errno)); + memcpy(ptr, &r->basic_errno, sizeof(r->basic_errno)); ptr += sizeof(r->basic_errno); - memcpy(ptr, &(r->more_errno), sizeof(r->more_errno)); + memcpy(ptr, &r->more_errno, sizeof(r->more_errno)); ptr += sizeof(r->more_errno); if (!r->message) *ptr++ = 0; else { @@ -4866,11 +4915,13 @@ for (delivery_count = 0; addr_remote; delivery_count++) sprintf(CS big_buffer, "%c%c", addr->transport_return, addr->special_action); ptr = big_buffer + 2; - memcpy(ptr, &(addr->basic_errno), sizeof(addr->basic_errno)); + memcpy(ptr, &addr->basic_errno, sizeof(addr->basic_errno)); ptr += sizeof(addr->basic_errno); - memcpy(ptr, &(addr->more_errno), sizeof(addr->more_errno)); + memcpy(ptr, &addr->more_errno, sizeof(addr->more_errno)); ptr += sizeof(addr->more_errno); - memcpy(ptr, &(addr->flags), sizeof(addr->flags)); + memcpy(ptr, &addr->delivery_usec, sizeof(addr->delivery_usec)); + ptr += sizeof(addr->delivery_usec); + memcpy(ptr, &addr->flags, sizeof(addr->flags)); ptr += sizeof(addr->flags); if (!addr->message) *ptr++ = 0; else @@ -4883,7 +4934,7 @@ for (delivery_count = 0; addr_remote; delivery_count++) { ptr += sprintf(CS ptr, "%.256s", addr->host_used->name) + 1; ptr += sprintf(CS ptr, "%.64s", addr->host_used->address) + 1; - memcpy(ptr, &(addr->host_used->port), sizeof(addr->host_used->port)); + memcpy(ptr, &addr->host_used->port, sizeof(addr->host_used->port)); ptr += sizeof(addr->host_used->port); /* DNS lookup status */ @@ -5559,14 +5610,15 @@ give up; if the message has been around for sufficiently long, remove it. */ if (rc != spool_read_hdrerror) { - received_time = 0; + received_time.tv_sec = received_time.tv_usec = 0; + /*XXX subsec precision?*/ for (i = 0; i < 6; i++) - received_time = received_time * BASE_62 + tab62[id[i] - '0']; + received_time.tv_sec = received_time.tv_sec * BASE_62 + tab62[id[i] - '0']; } /* If we've had this malformed message too long, sling it. */ - if (now - received_time > keep_malformed) + if (now - received_time.tv_sec > keep_malformed) { Uunlink(spool_fname(US"msglog", message_subdir, id, US"")); Uunlink(spool_fname(US"input", message_subdir, id, US"-D")); @@ -7792,7 +7844,7 @@ wording. */ if (rc != 0) { uschar *s = US""; - if (now - received_time < retry_maximum_timeout && !addr_defer) + if (now - received_time.tv_sec < retry_maximum_timeout && !addr_defer) { addr_defer = (address_item *)(+1); deliver_freeze = TRUE; @@ -7878,7 +7930,7 @@ if (!addr_defer) if (LOGGING(queue_time_overall)) log_write(0, LOG_MAIN, "Completed QT=%s", - readconf_printtime( (int) ((long)time(NULL) - (long)received_time)) ); + string_timesince(&received_time)); else log_write(0, LOG_MAIN, "Completed"); @@ -8016,7 +8068,7 @@ else if (addr_defer != (address_item *)(+1)) { int count; int show_time; - int queue_time = time(NULL) - received_time; + int queue_time = time(NULL) - received_time.tv_sec; /* When running in the test harness, there's an option that allows us to fudge this time so as to get repeatability of the tests. Take the first diff --git a/src/src/exim.c b/src/src/exim.c index 581b16190..c990bc08c 100644 --- a/src/src/exim.c +++ b/src/src/exim.c @@ -345,7 +345,7 @@ Arguments: Returns: -1, 0, or +1 */ -int +static int exim_tvcmp(struct timeval *t1, struct timeval *t2) { if (t1->tv_sec > t2->tv_sec) return +1; @@ -4537,8 +4537,9 @@ if (test_retry_arg >= 0) } } - yield = retry_find_config(s1, s2, basic_errno, more_errno); - if (yield == NULL) printf("No retry information found\n"); else + if (!(yield = retry_find_config(s1, s2, basic_errno, more_errno))) + printf("No retry information found\n"); + else { retry_rule *r; more_errno = yield->more_errno; @@ -4570,7 +4571,7 @@ if (test_retry_arg >= 0) printf("auth_failed "); else printf("* "); - for (r = yield->rules; r != NULL; r = r->next) + for (r = yield->rules; r; r = r->next) { printf("%c,%s", r->rule, readconf_printtime(r->timeout)); /* Do not */ printf(",%s", readconf_printtime(r->p1)); /* amalgamate */ diff --git a/src/src/expand.c b/src/src/expand.c index 4eb1818f1..d8d36a3b5 100644 --- a/src/src/expand.c +++ b/src/src/expand.c @@ -642,7 +642,7 @@ static var_entry var_table[] = { { "received_ip_address", vtype_stringptr, &interface_address }, { "received_port", vtype_int, &interface_port }, { "received_protocol", vtype_stringptr, &received_protocol }, - { "received_time", vtype_int, &received_time }, + { "received_time", vtype_int, &received_time.tv_sec }, { "recipient_data", vtype_stringptr, &recipient_data }, { "recipient_verify_failure",vtype_stringptr,&recipient_verify_failure }, { "recipients", vtype_string_func, &fn_recipients }, @@ -1484,9 +1484,7 @@ while (*s != 0) /* If value2 is unset, just compute one number */ if (value2 < 0) - { s = string_sprintf("%d", total % value1); - } /* Otherwise do a div/mod hash */ diff --git a/src/src/functions.h b/src/src/functions.h index 9c9caaf97..5b2a683b8 100644 --- a/src/src/functions.h +++ b/src/src/functions.h @@ -184,7 +184,6 @@ extern const uschar * exim_errstr(int); extern void exim_exit(int); extern void exim_nullstd(void); extern void exim_setugid(uid_t, gid_t, BOOL, uschar *); -extern int exim_tvcmp(struct timeval *, struct timeval *); extern void exim_wait_tick(struct timeval *, int); extern int exp_bool(address_item *addr, uschar *mtype, uschar *mname, unsigned dgb_opt, uschar *oname, BOOL bvalue, @@ -474,9 +473,10 @@ extern int strcmpic(const uschar *, const uschar *); extern int strncmpic(const uschar *, const uschar *, int); extern uschar *strstric(uschar *, uschar *, BOOL); +extern void timesince(struct timeval * diff, struct timeval * then); +extern void tls_modify_variables(tls_support *); extern uschar *tod_stamp(int); -extern void tls_modify_variables(tls_support *); extern BOOL transport_check_waiting(const uschar *, const uschar *, int, uschar *, BOOL *, oicf, void*); extern void transport_init(void); diff --git a/src/src/globals.c b/src/src/globals.c index 8c35c6fe2..894b59967 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -383,6 +383,7 @@ address_item address_defaults = { { 0 }, /* localpart_cache - ditto */ -1, /* mode */ 0, /* more_errno */ + 0, /* delivery_usec */ ERRNO_UNKNOWNERROR, /* basic_errno */ 0, /* child_count */ -1, /* return_file */ @@ -1107,7 +1108,7 @@ uschar *received_header_text = US int received_headers_max = 30; uschar *received_protocol = NULL; -int received_time = 0; +struct timeval received_time = { 0, 0 }; uschar *recipient_data = NULL; uschar *recipient_unqualified_hosts = NULL; uschar *recipient_verify_failure = NULL; diff --git a/src/src/globals.h b/src/src/globals.h index 4a54c3c73..2d26bd0d7 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -721,7 +721,7 @@ extern int received_count; /* Count of Received: headers */ extern uschar *received_for; /* For "for" field */ extern uschar *received_header_text; /* Definition of Received: header */ extern int received_headers_max; /* Max count of Received: headers */ -extern int received_time; /* Time the message was received */ +extern struct timeval received_time; /* Time the message was received */ extern uschar *recipient_data; /* lookup data for recipients */ extern uschar *recipient_unqualified_hosts; /* Permitted unqualified recipients */ extern uschar *recipient_verify_failure; /* What went wrong */ diff --git a/src/src/queue.c b/src/src/queue.c index 5d8d610c6..60bf2ce77 100644 --- a/src/src/queue.c +++ b/src/src/queue.c @@ -880,7 +880,7 @@ for (reset_point = store_get(0); f; f = f->next) if (Ustat(fname, &statbuf) == 0) size = message_size + statbuf.st_size - SPOOL_DATA_START_OFFSET + 1; - i = (now - received_time)/60; /* minutes on queue */ + i = (now - received_time.tv_sec)/60; /* minutes on queue */ if (i > 90) { i = (i + 30)/60; diff --git a/src/src/readconf.c b/src/src/readconf.c index df3fe823c..1ed93eb64 100644 --- a/src/src/readconf.c +++ b/src/src/readconf.c @@ -2298,10 +2298,10 @@ t /= 24; d = t % 7; w = t/7; -if (w > 0) { sprintf(CS p, "%dw", w); while (*p) p++; } -if (d > 0) { sprintf(CS p, "%dd", d); while (*p) p++; } -if (h > 0) { sprintf(CS p, "%dh", h); while (*p) p++; } -if (m > 0) { sprintf(CS p, "%dm", m); while (*p) p++; } +if (w > 0) p += sprintf(CS p, "%dw", w); +if (d > 0) p += sprintf(CS p, "%dd", d); +if (h > 0) p += sprintf(CS p, "%dh", h); +if (m > 0) p += sprintf(CS p, "%dm", m); if (s > 0 || p == time_buffer) sprintf(CS p, "%ds", s); return time_buffer; diff --git a/src/src/receive.c b/src/src/receive.c index 9561a4baf..71026ff4a 100644 --- a/src/src/receive.c +++ b/src/src/receive.c @@ -1743,9 +1743,9 @@ message id creation below. */ /* For other uses of the received time we can operate with granularity of one second, and for that we use the global variable received_time. This is for -things like ultimate message timeouts. */ +things like ultimate message timeouts.XXX */ -received_time = message_id_tv.tv_sec; +received_time = message_id_tv; /* If SMTP input, set the special handler for timeouts. The alarm() calls happen in the smtp_getc() function when it refills its buffer. */ diff --git a/src/src/retry.c b/src/src/retry.c index abfeeb4fb..0bb33a053 100644 --- a/src/src/retry.c +++ b/src/src/retry.c @@ -54,8 +54,8 @@ if (retry != NULL && retry->rules != NULL) last_rule = last_rule->next); DEBUG(D_retry) debug_printf(" received_time=%d diff=%d timeout=%d\n", - received_time, (int)(now - received_time), last_rule->timeout); - address_timeout = (now - received_time > last_rule->timeout); + received_time.tv_sec, (int)(now - received_time.tv_sec), last_rule->timeout); + address_timeout = (now - received_time.tv_sec > last_rule->timeout); } else { @@ -754,7 +754,7 @@ for (i = 0; i < 3; i++) this is a small bit of code, and it does no harm to leave it in place, just in case. */ - if ( received_time <= retry_record->first_failed + if ( received_time.tv_sec <= retry_record->first_failed && addr == endaddr && !retry_record->expired && rule) @@ -762,7 +762,7 @@ for (i = 0; i < 3; i++) retry_rule *last_rule; for (last_rule = rule; last_rule->next; last_rule = last_rule->next) ; - if (now - received_time > last_rule->timeout) + if (now - received_time.tv_sec > last_rule->timeout) { DEBUG(D_retry) debug_printf("on queue longer than maximum retry\n"); timedout_count++; diff --git a/src/src/spool_in.c b/src/src/spool_in.c index 0bdf92e3b..a5b14959f 100644 --- a/src/src/spool_in.c +++ b/src/src/spool_in.c @@ -397,10 +397,11 @@ sender_address[n-3] = 0; /* time */ if (Ufgets(big_buffer, big_buffer_size, f) == NULL) goto SPOOL_READ_ERROR; -if (sscanf(CS big_buffer, "%d %d", &received_time, &warning_count) != 2) +if (sscanf(CS big_buffer, TIME_T_FMT " %d", &received_time.tv_sec, &warning_count) != 2) goto SPOOL_FORMAT_ERROR; +received_time.tv_usec = 0; -message_age = time(NULL) - received_time; +message_age = time(NULL) - received_time.tv_sec; #ifndef COMPILE_UTILITY DEBUG(D_deliver) debug_printf("user=%s uid=%ld gid=%ld sender=%s\n", @@ -573,7 +574,8 @@ for (;;) break; case 'l': - if (Ustrcmp(p, "ocal") == 0) sender_local = TRUE; + if (Ustrcmp(p, "ocal") == 0) + sender_local = TRUE; else if (Ustrcmp(big_buffer, "-localerror") == 0) local_error_message = TRUE; else if (Ustrncmp(p, "ocal_scan ", 10) == 0) @@ -593,6 +595,12 @@ for (;;) case 'r': if (Ustrncmp(p, "eceived_protocol", 16) == 0) received_protocol = string_copy(big_buffer + 19); + else if (Ustrncmp(p, "eceived_time_usec", 17) == 0) + { + unsigned usec; + if (sscanf(CS big_buffer + 21, "%u", &usec) == 1) + received_time.tv_usec = usec; + } break; case 's': diff --git a/src/src/spool_out.c b/src/src/spool_out.c index ebe089d4f..ac3927910 100644 --- a/src/src/spool_out.c +++ b/src/src/spool_out.c @@ -154,26 +154,28 @@ fprintf(f, "%s-H\n", message_id); fprintf(f, "%.63s %ld %ld\n", originator_login, (long int)originator_uid, (long int)originator_gid); fprintf(f, "<%s>\n", sender_address); -fprintf(f, "%d %d\n", received_time, warning_count); +fprintf(f, "%d %d\n", received_time.tv_sec, warning_count); + +fprintf(f, "-received_time_usec .%06d\n", received_time.tv_usec); /* If there is information about a sending host, remember it. The HELO data can be set for local SMTP as well as remote. */ -if (sender_helo_name != NULL) +if (sender_helo_name) fprintf(f, "-helo_name %s\n", sender_helo_name); -if (sender_host_address != NULL) +if (sender_host_address) { fprintf(f, "-host_address %s.%d\n", sender_host_address, sender_host_port); - if (sender_host_name != NULL) + if (sender_host_name) fprintf(f, "-host_name %s\n", sender_host_name); - if (sender_host_authenticated != NULL) + if (sender_host_authenticated) fprintf(f, "-host_auth %s\n", sender_host_authenticated); } /* Also about the interface a message came in on */ -if (interface_address != NULL) +if (interface_address) fprintf(f, "-interface_address %s.%d\n", interface_address, interface_port); if (smtp_active_hostname != primary_hostname) @@ -183,11 +185,11 @@ if (smtp_active_hostname != primary_hostname) likely to be the same as originator_login, but will be different if the originator was root, forcing a different ident. */ -if (sender_ident != NULL) fprintf(f, "-ident %s\n", sender_ident); +if (sender_ident) fprintf(f, "-ident %s\n", sender_ident); /* Ditto for the received protocol */ -if (received_protocol != NULL) +if (received_protocol) fprintf(f, "-received_protocol %s\n", received_protocol); /* Preserve any ACL variables that are set. */ @@ -205,9 +207,9 @@ fprintf(f, "-max_received_linelength %d\n", max_received_linelength); if (body_zerocount > 0) fprintf(f, "-body_zerocount %d\n", body_zerocount); -if (authenticated_id != NULL) +if (authenticated_id) fprintf(f, "-auth_id %s\n", authenticated_id); -if (authenticated_sender != NULL) +if (authenticated_sender) fprintf(f, "-auth_sender %s\n", authenticated_sender); if (allow_unqualified_recipient) fprintf(f, "-allow_unqualified_recipient\n"); @@ -261,7 +263,7 @@ if (message_smtputf8) /* Write the dsn flags to the spool header file */ DEBUG(D_deliver) debug_printf("DSN: Write SPOOL :-dsn_envid %s\n", dsn_envid); -if (dsn_envid != NULL) fprintf(f, "-dsn_envid %s\n", dsn_envid); +if (dsn_envid) fprintf(f, "-dsn_envid %s\n", dsn_envid); DEBUG(D_deliver) debug_printf("DSN: Write SPOOL :-dsn_ret %d\n", dsn_ret); if (dsn_ret != 0) fprintf(f, "-dsn_ret %d\n", dsn_ret); @@ -316,7 +318,7 @@ various other headers, or an asterisk for old headers that have been rewritten. These are saved as a record for debugging. Don't included them in the message's size. */ -for (h = header_list; h != NULL; h = h->next) +for (h = header_list; h; h = h->next) { fprintf(f, "%03d%c %s", h->slen, h->type, h->text); size_correction += 5; diff --git a/src/src/structs.h b/src/src/structs.h index 885c1b500..3de8f3d41 100644 --- a/src/src/structs.h +++ b/src/src/structs.h @@ -631,6 +631,7 @@ typedef struct address_item { int mode; /* mode for local transporting to a file */ int more_errno; /* additional error information */ /* (may need to hold a timestamp) */ + unsigned int delivery_usec; /* subsecond part of delivery time */ short int basic_errno; /* status after failure */ unsigned short child_count; /* number of child addresses */ diff --git a/src/src/transport.c b/src/src/transport.c index b26251c88..c6b4c77ef 100644 --- a/src/src/transport.c +++ b/src/src/transport.c @@ -1253,6 +1253,8 @@ if ((write_pid = fork()) == 0) != sizeof(int) || write(pfd[pipe_write], (void *)&tctx->addr->more_errno, sizeof(int)) != sizeof(int) + || write(pfd[pipe_write], (void *)&tctx->addr->delivery_usec, sizeof(int)) + != sizeof(int) ) rc = FALSE; /* compiler quietening */ _exit(0); @@ -1377,7 +1379,8 @@ if (write_pid > 0) else if (!ok) { int dummy = read(pfd[pipe_read], (void *)&save_errno, sizeof(int)); - dummy = read(pfd[pipe_read], (void *)&(tctx->addr->more_errno), sizeof(int)); + dummy = read(pfd[pipe_read], (void *)&tctx->addr->more_errno, sizeof(int)); + dummy = read(pfd[pipe_read], (void *)&tctx->addr->delivery_usec, sizeof(int)); yield = FALSE; } } diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c index 11a996c65..d424c182c 100644 --- a/src/src/transports/smtp.c +++ b/src/src/transports/smtp.c @@ -2714,7 +2714,7 @@ address_item *addr; int yield = OK; int save_errno; int rc; -time_t start_delivery_time = time(NULL); +struct timeval start_delivery_time; BOOL pass_message = FALSE; uschar *message = NULL; @@ -2723,6 +2723,7 @@ uschar *p; smtp_context sx; +gettimeofday(&start_delivery_time, NULL); suppress_tls = suppress_tls; /* stop compiler warning when no TLS support */ *message_defer = FALSE; @@ -3036,10 +3037,11 @@ else if (sx.ok) { int flag = '='; - int delivery_time = (int)(time(NULL) - start_delivery_time); + struct timeval delivery_time; int len; - uschar *conf = NULL; + uschar * conf = NULL; + timesince(&delivery_time, &start_delivery_time); sx.send_rset = FALSE; pipelining_active = FALSE; @@ -3114,7 +3116,8 @@ else actual host that was used. */ addr->transport_return = OK; - addr->more_errno = delivery_time; + addr->more_errno = delivery_time.tv_sec; + addr->delivery_usec = delivery_time.tv_usec; addr->host_used = host; addr->special_action = flag; addr->message = conf; @@ -4160,7 +4163,7 @@ for (cutoff_retry = 0; { if ( !host->address || host->status != hstatus_unusable_expired - || host->last_try > received_time) + || host->last_try > received_time.tv_sec) continue; DEBUG(D_transport) debug_printf("trying expired host %s [%s]%s\n", host->name, host->address, pistring); @@ -4480,7 +4483,7 @@ for (cutoff_retry = 0; for (last_rule = retry->rules; last_rule->next; last_rule = last_rule->next); - timedout = time(NULL) - received_time > last_rule->timeout; + timedout = time(NULL) - received_time.tv_sec > last_rule->timeout; } else timedout = TRUE; /* No rule => timed out */ diff --git a/test/log/0506 b/test/log/0506 index d74b21dab..e0140f58b 100644 --- a/test/log/0506 +++ b/test/log/0506 @@ -1,7 +1,7 @@ 1999-03-02 09:44:33 10HmaX-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss 1999-03-02 09:44:33 10HmaX-0005vi-00 => discarded R=r1 1999-03-02 09:44:33 10HmaX-0005vi-00 => discarded R=r1 -1999-03-02 09:44:33 10HmaX-0005vi-00 Completed QT=0s +1999-03-02 09:44:33 10HmaX-0005vi-00 Completed QT=qqs 1999-03-02 09:44:33 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss 1999-03-02 09:44:33 10HmaY-0005vi-00 => discarded R=r1 1999-03-02 09:44:33 10HmaY-0005vi-00 == sieve-filter@test.ex R=r1 defer (-17): error in filter file: Sieve filtering not enabled diff --git a/test/log/0551 b/test/log/0551 index 189bd380d..5baae67cb 100644 --- a/test/log/0551 +++ b/test/log/0551 @@ -3,9 +3,9 @@ 1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 => usery R=r1 T=t1 1999-03-02 09:44:33 [1235] 10HmaX-0005vi-00 Completed 1999-03-02 09:44:33 [1236] 10HmaY-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss -1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx R=r1 T=t1 -1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz R=r1 T=t1 +1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userx R=r1 T=t1 QT=qqs +1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz R=r1 T=t1 QT=qqs 1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 Completed 2017-07-30 18:51:05.712 10HmaZ-0005vi-00 <= CALLER@myhost.test.ex U=CALLER P=local S=sss -2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx R=r1 T=t1 -2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed +2017-07-30 18:51:05.712 10HmaZ-0005vi-00 => userx R=r1 T=t1 QT=q.qqqs DT=q.qqqs +2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed QT=q.qqqs diff --git a/test/runtest b/test/runtest index b7339f5d0..90c1758ca 100755 --- a/test/runtest +++ b/test/runtest @@ -491,6 +491,9 @@ RESET_AFTER_EXTRA_LINE_READ: s/^\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\.\d{3}(\s[+-]\d\d\d\d)?\s/2017-07-30 18:51:05.712 /gx; s/^Logwrite\s"\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Logwrite "1999-03-02 09:44:33/gx; + s/([QD]T=)\d+s/$1qqs/g; + s/([QD]T=)\d\.\d{3}s/$1q.qqqs/g; + # Date/time in message separators s/(?:[A-Z][a-z]{2}\s){2}\d\d\s\d\d:\d\d:\d\d\s\d\d\d\d /Tue Mar 02 09:44:33 1999/gx; @@ -518,9 +521,6 @@ RESET_AFTER_EXTRA_LINE_READ: # Date/time in exim -bV output s/\d\d-[A-Z][a-z]{2}-\d{4}\s\d\d:\d\d:\d\d/07-Mar-2000 12:21:52/g; - # Time on queue tolerance - s/(QT|D)=1s/$1=0s/; - # Eximstats heading s/Exim\sstatistics\sfrom\s\d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d\sto\s \d{4}-\d\d-\d\d\s\d\d:\d\d:\d\d/Exim statistics from