From: Jeremy Harris Date: Sun, 11 Apr 2021 15:39:06 +0000 (+0100) Subject: Log queue_time and queue_time_overall exclusive of receive time. Bug 2672 X-Git-Tag: exim-4.95-RC0~72 X-Git-Url: https://git.exim.org/exim.git/commitdiff_plain/f870028fd26f8ac1a2fcb6e43e0d7d1c76c110ec Log queue_time and queue_time_overall exclusive of receive time. Bug 2672 --- diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index 437b13df0..36be62f7a 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -38672,6 +38672,7 @@ selection marked by asterisks: &` outgoing_port `& add remote port to => lines &`*queue_run `& start and end queue runs &` queue_time `& time on queue for one recipient +&`*queue_time_exclusive `& exclude recieve time from QT times &` queue_time_overall `& time on queue for whole message &` pid `& Exim process id &` pipelining `& PIPELINING use, on <= and => lines @@ -38913,18 +38914,13 @@ Delivery "L" fields have an asterisk appended if used. .cindex "log" "queue time" &%queue_time%&: The amount of time the message has been in the queue on the local host is logged as QT=<&'time'&> on delivery (&`=>`&) lines, for example, -&`QT=3m45s`&. The clock starts when Exim starts to receive the message, so it -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. +&`QT=3m45s`&. 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 -example, &`QT=3m45s`&. The clock starts when Exim starts to receive the -message, so it includes reception time as well as the total delivery time. +example, &`QT=3m45s`&. .next .cindex "log" "receive duration" &%receive_time%&: For each message, the amount of real time it has taken to diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog index db4735f8f..916a4c470 100644 --- a/doc/doc-txt/ChangeLog +++ b/doc/doc-txt/ChangeLog @@ -236,6 +236,11 @@ JH/49 Bug 2710: when using SOCKS for additional messages after the first (a transport executions. This also mean that the log lines for the messages can show the proxy information. +JH/50 Bug 2672: QT elements in log lines, unless disabled, now exclude the + receive time. With modern systems the difference is significant. + The historical behaviour can be restored by disabling (a new) log_selector + "queue_time_exclusive". + Exim version 4.94 diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff index 50f7b4357..0ac271eaf 100644 --- a/doc/doc-txt/NewStuff +++ b/doc/doc-txt/NewStuff @@ -48,6 +48,9 @@ Version 4.95 13. Option "smtp_accept_msx_per_connection" is now expanded. +14. Log selector "queue_size_exclusive", enabled by default, to exclude the + time taken for reception from QT log elements. + Version 4.94 ------------ diff --git a/src/exim_monitor/em_globals.c b/src/exim_monitor/em_globals.c index 30d22b5eb..88d5103fc 100644 --- a/src/exim_monitor/em_globals.c +++ b/src/exim_monitor/em_globals.c @@ -196,6 +196,7 @@ uschar *queue_name = US""; int received_count = 0; uschar *received_protocol = NULL; struct timeval received_time = { 0, 0 }; +struct timeval received_time_complete = { 0, 0 }; int recipients_count = 0; recipient_item *recipients_list = NULL; int recipients_list_max = 0; diff --git a/src/src/deliver.c b/src/src/deliver.c index ef6eb22e2..0cddec758 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -1269,8 +1269,8 @@ if ( LOGGING(smtp_confirmation) /* Time on queue and actual time taken to deliver */ if (LOGGING(queue_time)) - g = string_append(g, 2, US" QT=", - string_timesince(&received_time)); + g = string_append(g, 2, US" QT=", string_timesince( + LOGGING(queue_time_exclusive) ? &received_time_complete : &received_time)); if (LOGGING(deliver_time)) g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time)); diff --git a/src/src/functions.h b/src/src/functions.h index f1e5b466e..0f962b313 100644 --- a/src/src/functions.h +++ b/src/src/functions.h @@ -1059,18 +1059,25 @@ subdir_str[1] = '\0'; /******************************************************************************/ /* Time calculations */ +/* Diff two times (later, earlier) returning diff in 1st arg */ static inline void -timesince(struct timeval * diff, const struct timeval * then) +timediff(struct timeval * later, const struct timeval * earlier) { -gettimeofday(diff, NULL); -diff->tv_sec -= then->tv_sec; -if ((diff->tv_usec -= then->tv_usec) < 0) +later->tv_sec -= earlier->tv_sec; +if ((later->tv_usec -= earlier->tv_usec) < 0) { - diff->tv_sec--; - diff->tv_usec += 1000*1000; + later->tv_sec--; + later->tv_usec += 1000*1000; } } +static inline void +timesince(struct timeval * diff, const struct timeval * then) +{ +gettimeofday(diff, NULL); +timediff(diff, then); +} + static inline uschar * string_timediff(const struct timeval * diff) { diff --git a/src/src/globals.c b/src/src/globals.c index 04e47050e..7ee7c38b5 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -1034,6 +1034,7 @@ int log_default[] = { /* for initializing log_selector */ Li_outgoing_interface, /* see d_log_interface in deliver.c */ Li_msg_id, Li_queue_run, + Li_queue_time_exclusive, Li_rejected_header, Li_retry_defer, Li_sender_verify_fail, @@ -1088,6 +1089,7 @@ bit_table log_options[] = { /* must be in alphabetical order, #endif BIT_TABLE(L, queue_run), BIT_TABLE(L, queue_time), + BIT_TABLE(L, queue_time_exclusive), BIT_TABLE(L, queue_time_overall), BIT_TABLE(L, receive_time), BIT_TABLE(L, received_recipients), @@ -1274,7 +1276,7 @@ uschar *received_header_text = US int received_headers_max = 30; uschar *received_protocol = NULL; struct timeval received_time = { 0, 0 }; -struct timeval received_time_taken = { 0, 0 }; +struct timeval received_time_complete = { 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 652518ade..58bf3c428 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -841,8 +841,8 @@ 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 struct timeval received_time; /* Time the message was received */ -extern struct timeval received_time_taken; /* Interval the message took to be received */ +extern struct timeval received_time; /* Time the message started to be received */ +extern struct timeval received_time_complete; /* Time the message completed reception */ 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/macros.h b/src/src/macros.h index 0b647569b..43217807f 100644 --- a/src/src/macros.h +++ b/src/src/macros.h @@ -480,6 +480,7 @@ enum logbit { Li_protocol_detail, Li_proxy, Li_queue_time, + Li_queue_time_exclusive, Li_queue_time_overall, Li_receive_time, Li_received_sender, diff --git a/src/src/receive.c b/src/src/receive.c index 3e950ffc6..ce7da5719 100644 --- a/src/src/receive.c +++ b/src/src/receive.c @@ -3272,7 +3272,7 @@ if (fflush(spool_data_file) == EOF || ferror(spool_data_file) || /* No I/O errors were encountered while writing the data file. */ DEBUG(D_receive) debug_printf("Data file written for message %s\n", message_id); -if (LOGGING(receive_time)) timesince(&received_time_taken, &received_time); +gettimeofday(&received_time_complete, NULL); /* If there were any bad addresses extracted by -t, or there were no recipients @@ -4050,7 +4050,11 @@ if (LOGGING(dkim) && arc_state && Ustrcmp(arc_state, "pass") == 0) #endif if (LOGGING(receive_time)) - g = string_append(g, 2, US" RT=", string_timediff(&received_time_taken)); + { + struct timeval diff = received_time_complete; + timediff(&diff, &received_time); + g = string_append(g, 2, US" RT=", string_timediff(&diff)); + } if (*queue_name) g = string_append(g, 2, US" Q=", queue_name); diff --git a/src/src/spool_in.c b/src/src/spool_in.c index 9794e93d1..f64c52c5a 100644 --- a/src/src/spool_in.c +++ b/src/src/spool_in.c @@ -422,6 +422,8 @@ if (Ufgets(big_buffer, big_buffer_size, fp) == NULL) goto SPOOL_READ_ERROR; 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; +received_time_complete = received_time; + message_age = time(NULL) - received_time.tv_sec; #ifndef COMPILE_UTILITY @@ -639,7 +641,19 @@ for (;;) { unsigned usec; if (sscanf(CS var + 20, "%u", &usec) == 1) + { received_time.tv_usec = usec; + if (!received_time_complete.tv_sec) received_time_complete.tv_usec = usec; + } + } + else if (Ustrncmp(p, "eceived_time_complete", 21) == 0) + { + unsigned sec, usec; + if (sscanf(CS var + 23, "%u.%u", &sec, &usec) == 2) + { + received_time_complete.tv_sec = sec; + received_time_complete.tv_usec = usec; + } } break; diff --git a/src/src/spool_out.c b/src/src/spool_out.c index 113765bab..bbc798fb4 100644 --- a/src/src/spool_out.c +++ b/src/src/spool_out.c @@ -162,6 +162,8 @@ fprintf(fp, "<%s>\n", sender_address); fprintf(fp, "%d %d\n", (int)received_time.tv_sec, warning_count); fprintf(fp, "-received_time_usec .%06d\n", (int)received_time.tv_usec); +fprintf(fp, "-received_time_complete %d.%06d\n", + (int)received_time_complete.tv_sec, (int)received_time_complete.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. */ diff --git a/test/runtest b/test/runtest index 6050411ed..8ebba5023 100755 --- a/test/runtest +++ b/test/runtest @@ -1007,7 +1007,8 @@ RESET_AFTER_EXTRA_LINE_READ: s/conversion: german.xn--strae-oqa.de/conversion: german.straße.de/; # subsecond timstamp info in reported header-files - s/^(-received_time_usec \.)\d{6}$/$1uuuuuu/; + s/^-received_time_usec \.\K\d{6}$/uuuuuu/; + s/^-received_time_complete \K\d+\.\d{6}$/tttt.uuuuuu/; # Postgres server takes varible time to shut down; lives in various places s/^waiting for server to shut down\.+ done$/waiting for server to shut down.... done/; diff --git a/test/stdout/0035 b/test/stdout/0035 index 09b5df4e9..94b08fcd6 100644 --- a/test/stdout/0035 +++ b/test/stdout/0035 @@ -145,6 +145,7 @@ EXIMUSER EXIM_UID EXIM_GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -interface_address 127.0.0.1.1225 @@ -166,6 +167,7 @@ EXIMUSER EXIM_UID EXIM_GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -interface_address 127.0.0.1.1225 @@ -190,6 +192,7 @@ EXIMUSER EXIM_UID EXIM_GID <> ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -interface_address 127.0.0.1.1225 @@ -212,6 +215,7 @@ EXIMUSER EXIM_UID EXIM_GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -interface_address 127.0.0.1.1225 @@ -234,6 +238,7 @@ EXIMUSER EXIM_UID EXIM_GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -interface_address 127.0.0.1.1225 @@ -259,6 +264,7 @@ EXIMUSER EXIM_UID EXIM_GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -interface_address 127.0.0.1.1225 @@ -284,6 +290,7 @@ EXIMUSER EXIM_UID EXIM_GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -interface_address 127.0.0.1.1225 diff --git a/test/stdout/0245 b/test/stdout/0245 index 5d0f2df34..da28e7e94 100644 --- a/test/stdout/0245 +++ b/test/stdout/0245 @@ -8,6 +8,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 1 diff --git a/test/stdout/0250 b/test/stdout/0250 index c19185e84..d4d723725 100644 --- a/test/stdout/0250 +++ b/test/stdout/0250 @@ -3,6 +3,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 @@ -34,6 +35,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 @@ -65,6 +67,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 diff --git a/test/stdout/0254 b/test/stdout/0254 index 69b80a192..1fcd3fd45 100644 --- a/test/stdout/0254 +++ b/test/stdout/0254 @@ -3,6 +3,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 @@ -40,6 +41,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 @@ -70,6 +72,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 diff --git a/test/stdout/0311 b/test/stdout/0311 index 960e8e0b7..a26b24c55 100644 --- a/test/stdout/0311 +++ b/test/stdout/0311 @@ -3,6 +3,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 @@ -32,6 +33,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 diff --git a/test/stdout/0338 b/test/stdout/0338 index fbbbc69c5..06aab63cf 100644 --- a/test/stdout/0338 +++ b/test/stdout/0338 @@ -7,6 +7,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 diff --git a/test/stdout/0377 b/test/stdout/0377 index de1e5e305..f6d8fc6f6 100644 --- a/test/stdout/0377 +++ b/test/stdout/0377 @@ -3,6 +3,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 diff --git a/test/stdout/0378 b/test/stdout/0378 index c60701cbc..e163ed170 100644 --- a/test/stdout/0378 +++ b/test/stdout/0378 @@ -3,6 +3,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 diff --git a/test/stdout/0379 b/test/stdout/0379 index d26d23523..d3bd25e7b 100644 --- a/test/stdout/0379 +++ b/test/stdout/0379 @@ -3,6 +3,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local -body_linecount 0 diff --git a/test/stdout/0389 b/test/stdout/0389 index bb5977af7..758f2614d 100644 --- a/test/stdout/0389 +++ b/test/stdout/0389 @@ -9,6 +9,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local-smtp -aclm 0 22 diff --git a/test/stdout/0488 b/test/stdout/0488 index d6d3b4b18..680def49c 100644 --- a/test/stdout/0488 +++ b/test/stdout/0488 @@ -9,6 +9,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local-smtp -body_linecount 0 diff --git a/test/stdout/0490 b/test/stdout/0490 index ee77a71e6..cc71d26e1 100644 --- a/test/stdout/0490 +++ b/test/stdout/0490 @@ -13,6 +13,7 @@ CALLER UID GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident CALLER -received_protocol local-smtp -body_linecount 2 diff --git a/test/stdout/0514 b/test/stdout/0514 index 5b8677c65..913378aef 100644 --- a/test/stdout/0514 +++ b/test/stdout/0514 @@ -6,6 +6,7 @@ CALLER UID GID <"spaced user"@myhost.test.ex> ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu -ident spaced user -received_protocol local -body_linecount 1 diff --git a/test/stdout/3415 b/test/stdout/3415 index d806fa66c..7c6e90bdb 100644 --- a/test/stdout/3415 +++ b/test/stdout/3415 @@ -156,6 +156,7 @@ EXIMUSER EXIM_UID EXIM_GID ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -host_auth au1 @@ -184,6 +185,7 @@ EXIMUSER EXIM_UID EXIM_GID <> ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -host_auth au1 @@ -210,6 +212,7 @@ EXIMUSER EXIM_UID EXIM_GID <> ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -host_auth au1 @@ -236,6 +239,7 @@ EXIMUSER EXIM_UID EXIM_GID <> ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -host_auth au1 @@ -262,6 +266,7 @@ EXIMUSER EXIM_UID EXIM_GID <> ddddddddd 0 -received_time_usec .uuuuuu +-received_time_complete tttt.uuuuuu --helo_name rhu.barb -host_address 127.0.0.1.9999 -host_auth au1