From 306c6c7751cf6953dc544a607b584a9ca58623ad Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Tue, 16 Jan 2018 21:31:28 +0000 Subject: [PATCH] Logging: Receive duration on <= lines. Bug 353 --- doc/doc-docbook/spec.xfpt | 13 ++- doc/doc-txt/NewStuff | 4 +- src/src/deliver.c | 9 +- src/src/functions.h | 1 + src/src/globals.c | 2 + src/src/globals.h | 1 + src/src/macros.h | 1 + src/src/receive.c | 171 +++++++++++++++-------------------- test/log/0551 | 2 +- test/runtest | 4 +- test/scripts/0000-Basic/0551 | 4 +- test/stdout/0551 | 2 +- 12 files changed, 102 insertions(+), 112 deletions(-) diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt index b6d283b95..40de5b9b1 100644 --- a/doc/doc-docbook/spec.xfpt +++ b/doc/doc-docbook/spec.xfpt @@ -36077,6 +36077,7 @@ the following table: &` `& on &"Completed"& lines: time spent on queue &`R `& on &`<=`& lines: reference for local bounce &` `& on &`=>`& &`>>`& &`**`& and &`==`& lines: router name +&`RT `& on &`<=`& lines: time taken for reception &`S `& size of message in bytes &`SNI `& server name indication from TLS client hello &`ST `& shadow transport name @@ -36171,7 +36172,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 and QT,DT,D times +&` millisec `& millisecond timestamps and RT,QT,DT,D times &` outgoing_interface `& local interface on => lines &` outgoing_port `& add remote port to => lines &`*queue_run `& start and end queue runs @@ -36262,7 +36263,7 @@ process is started because &%queue_only%& is set or &%-odq%& was used. &%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`&. +precision, eg. &`DT=0.304s`&. .next .cindex "log" "message size on delivery" .cindex "size" "of message" @@ -36400,6 +36401,14 @@ precision, eg. &`QT=1.578s`&. 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. +.new +.next +.cindex "log" "receive duration" +&%receive_time%&: For each message, the amount of real time it has taken to +perform the reception is logged as RT=<&'time'&>, for example, &`RT=1s`&. +If millisecond logging is enabled, short times will be shown with greater +precision, eg. &`RT=0.204s`&. +.wen .next .cindex "log" "recipients" &%received_recipients%&: The recipients of a message are listed in the main log diff --git a/doc/doc-txt/NewStuff b/doc/doc-txt/NewStuff index 15722e114..560e15ef5 100644 --- a/doc/doc-txt/NewStuff +++ b/doc/doc-txt/NewStuff @@ -20,11 +20,13 @@ Version 4.91 4. SPF support is promoted from Experimental to mainline status. The template src/EDITME makefile does not enable its inclusion. - 5 Logging control for DKIM verification. The existing DKIM log line is + 5. Logging control for DKIM verification. The existing DKIM log line is controlled by a "dkim_verbose" selector which is _not_ enabled by default. A new tag "DKIM=" is added to <= lines by default, controlled by a "dkim" log_selector. + 6. Receive duration on <= lines, under a new log_selector "receive_time". + Version 4.90 ------------ diff --git a/src/src/deliver.c b/src/src/deliver.c index de552f4cc..05fd3ce6d 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -1030,10 +1030,8 @@ else and all parents are not being included, don't add on the top address. First of all, do a caseless comparison; if this succeeds, do a caseful comparison on the local parts. */ - /*XXX dodgy coding. the string at "cmp" might not be nul-terminated if - we had to extend the allocation! */ - g->s[g->ptr] = '\0'; + string_from_gstring(g); /* ensure nul-terminated */ if ( strcmpic(cmp, topaddr->address) == 0 && Ustrncmp(cmp, topaddr->address, Ustrchr(cmp, '@') - cmp) == 0 && !addr->onetime_parent @@ -1089,7 +1087,7 @@ if ((diff->tv_usec -= then->tv_usec) < 0) -static uschar * +uschar * string_timediff(struct timeval * diff) { static uschar buf[sizeof("0.000s")]; @@ -7934,8 +7932,7 @@ if (!addr_defer) /* Log the end of this message, with queue time if requested. */ if (LOGGING(queue_time_overall)) - log_write(0, LOG_MAIN, "Completed QT=%s", - string_timesince(&received_time)); + log_write(0, LOG_MAIN, "Completed QT=%s", string_timesince(&received_time)); else log_write(0, LOG_MAIN, "Completed"); diff --git a/src/src/functions.h b/src/src/functions.h index 1e8698b78..d2105a7b4 100644 --- a/src/src/functions.h +++ b/src/src/functions.h @@ -467,6 +467,7 @@ extern uschar *string_nextinlist(const uschar **, int *, uschar *, int); extern uschar *string_open_failed(int, const char *, ...) PRINTF_FUNCTION(2,3); extern const uschar *string_printing2(const uschar *, BOOL); extern uschar *string_split_message(uschar *); +extern uschar *string_timediff(struct timeval *); extern uschar *string_timesince(struct timeval *); extern uschar *string_unprinting(uschar *); #ifdef SUPPORT_I18N diff --git a/src/src/globals.c b/src/src/globals.c index 303c8025c..8ec62466f 100644 --- a/src/src/globals.c +++ b/src/src/globals.c @@ -916,6 +916,7 @@ bit_table log_options[] = { /* must be in alphabetical order */ BIT_TABLE(L, queue_run), BIT_TABLE(L, queue_time), BIT_TABLE(L, queue_time_overall), + BIT_TABLE(L, receive_time), BIT_TABLE(L, received_recipients), BIT_TABLE(L, received_sender), BIT_TABLE(L, rejected_header), @@ -1121,6 +1122,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 }; 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 1715a3df5..ed5aee839 100644 --- a/src/src/globals.h +++ b/src/src/globals.h @@ -725,6 +725,7 @@ 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 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 20e345573..65a1a172a 100644 --- a/src/src/macros.h +++ b/src/src/macros.h @@ -472,6 +472,7 @@ enum { Li_proxy, Li_queue_time, Li_queue_time_overall, + Li_receive_time, Li_received_sender, Li_received_recipients, Li_rejected_header, diff --git a/src/src/receive.c b/src/src/receive.c index d79b282fb..8c7e2b525 100644 --- a/src/src/receive.c +++ b/src/src/receive.c @@ -1742,7 +1742,7 @@ 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.XXX */ +things like ultimate message timeouts. */ received_time = message_id_tv; @@ -2619,7 +2619,7 @@ checked when it was read, to ensure it isn't too big. The timing granularity is left in id_resolution so that an appropriate wait can be done after receiving the message, if necessary (we hope it won't be). */ -if (host_number_string != NULL) +if (host_number_string) { id_resolution = (BASE_62 == 62)? 5000 : 10000; sprintf(CS(message_id + MESSAGE_ID_LENGTH - 3), "-%2s", @@ -2655,9 +2655,8 @@ one, but only for local (without suppress_local_fixups) or submission mode messages. This can be user-configured if required, but we had better flatten any illegal characters therein. */ -if (msgid_header == NULL && - ((sender_host_address == NULL && !suppress_local_fixups) - || submission_mode)) +if ( !msgid_header + && ((!sender_host_address && !suppress_local_fixups) || submission_mode)) { uschar *p; uschar *id_text = US""; @@ -2665,20 +2664,20 @@ if (msgid_header == NULL && /* Permit only letters, digits, dots, and hyphens in the domain */ - if (message_id_domain != NULL) + if (message_id_domain) { uschar *new_id_domain = expand_string(message_id_domain); - if (new_id_domain == NULL) + if (!new_id_domain) { if (!expand_string_forcedfail) log_write(0, LOG_MAIN|LOG_PANIC, "expansion of \"%s\" (message_id_header_domain) " "failed: %s", message_id_domain, expand_string_message); } - else if (*new_id_domain != 0) + else if (*new_id_domain) { id_domain = new_id_domain; - for (p = id_domain; *p != 0; p++) + for (p = id_domain; *p; p++) if (!isalnum(*p) && *p != '.') *p = '-'; /* No need to test '-' ! */ } } @@ -2686,21 +2685,20 @@ if (msgid_header == NULL && /* Permit all characters except controls and RFC 2822 specials in the additional text part. */ - if (message_id_text != NULL) + if (message_id_text) { uschar *new_id_text = expand_string(message_id_text); - if (new_id_text == NULL) + if (!new_id_text) { if (!expand_string_forcedfail) log_write(0, LOG_MAIN|LOG_PANIC, "expansion of \"%s\" (message_id_header_text) " "failed: %s", message_id_text, expand_string_message); } - else if (*new_id_text != 0) + else if (*new_id_text) { id_text = new_id_text; - for (p = id_text; *p != 0; p++) - if (mac_iscntrl_or_special(*p)) *p = '-'; + for (p = id_text; *p; p++) if (mac_iscntrl_or_special(*p)) *p = '-'; } } @@ -2743,9 +2741,8 @@ possible addition of a Sender: header, because untrusted_set_sender allows an untrusted user to set anything in the envelope (which might then get info From:) but we still want to ensure a valid Sender: if it is required. */ -if (from_header == NULL && - ((sender_host_address == NULL && !suppress_local_fixups) - || submission_mode)) +if ( !from_header + && ((!sender_host_address && !suppress_local_fixups) || submission_mode)) { uschar *oname = US""; @@ -2754,7 +2751,7 @@ if (from_header == NULL && force its value or if we have a non-SMTP message for which -f was not used to set the sender. */ - if (sender_host_address == NULL) + if (!sender_host_address) { if (!trusted_caller || sender_name_forced || (!smtp_input && !sender_address_forced)) @@ -2764,46 +2761,38 @@ if (from_header == NULL && /* For non-locally submitted messages, the only time we use the originator name is when it was forced by the /name= option on control=submission. */ - else - { - if (submission_name != NULL) oname = submission_name; - } + else if (submission_name) oname = submission_name; /* Envelope sender is empty */ - if (sender_address[0] == 0) + if (!*sender_address) { uschar *fromstart, *fromend; - fromstart = string_sprintf("%sFrom: %s%s", resent_prefix, - oname, (oname[0] == 0)? "" : " <"); - fromend = (oname[0] == 0)? US"" : US">"; + fromstart = string_sprintf("%sFrom: %s%s", + resent_prefix, oname, *oname ? " <" : ""); + fromend = *oname ? US">" : US""; if (sender_local || local_error_message) - { header_add(htype_from, "%s%s@%s%s\n", fromstart, local_part_quote(originator_login), qualify_domain_sender, fromend); - } - else if (submission_mode && authenticated_id != NULL) + + else if (submission_mode && authenticated_id) { - if (submission_domain == NULL) - { + if (!submission_domain) header_add(htype_from, "%s%s@%s%s\n", fromstart, local_part_quote(authenticated_id), qualify_domain_sender, fromend); - } - else if (submission_domain[0] == 0) /* empty => whole address set */ - { + + else if (!*submission_domain) /* empty => whole address set */ header_add(htype_from, "%s%s%s\n", fromstart, authenticated_id, fromend); - } + else - { header_add(htype_from, "%s%s@%s%s\n", fromstart, - local_part_quote(authenticated_id), submission_domain, - fromend); - } + local_part_quote(authenticated_id), submission_domain, fromend); + from_header = header_last; /* To get it checked for Sender: */ } } @@ -2816,10 +2805,9 @@ if (from_header == NULL && { header_add(htype_from, "%sFrom: %s%s%s%s\n", resent_prefix, oname, - (oname[0] == 0)? "" : " <", - (sender_address_unrewritten == NULL)? - sender_address : sender_address_unrewritten, - (oname[0] == 0)? "" : ">"); + *oname ? " <" : "", + sender_address_unrewritten ? sender_address_unrewritten : sender_address, + *oname ? ">" : ""); from_header = header_last; /* To get it checked for Sender: */ } @@ -2836,11 +2824,11 @@ trusted callers to forge From: without supplying -f, we have to test explicitly here. If the From: header contains more than one address, then the call to parse_extract_address fails, and a Sender: header is inserted, as required. */ -if (from_header != NULL && - (active_local_from_check && - ((sender_local && !trusted_caller && !suppress_local_fixups) || - (submission_mode && authenticated_id != NULL)) - )) +if ( from_header + && ( active_local_from_check + && ( sender_local && !trusted_caller && !suppress_local_fixups + || submission_mode && authenticated_id + ) ) ) { BOOL make_sender = TRUE; int start, end, domain; @@ -2850,37 +2838,26 @@ if (from_header != NULL && &start, &end, &domain, FALSE); uschar *generated_sender_address; - if (submission_mode) - { - if (submission_domain == NULL) - { - generated_sender_address = string_sprintf("%s@%s", - local_part_quote(authenticated_id), qualify_domain_sender); - } - else if (submission_domain[0] == 0) /* empty => full address */ - { - generated_sender_address = string_sprintf("%s", - authenticated_id); - } - else - { - generated_sender_address = string_sprintf("%s@%s", - local_part_quote(authenticated_id), submission_domain); - } - } - else - generated_sender_address = string_sprintf("%s@%s", - local_part_quote(originator_login), qualify_domain_sender); + generated_sender_address = submission_mode + ? !submission_domain + ? string_sprintf("%s@%s", + local_part_quote(authenticated_id), qualify_domain_sender) + : !*submission_domain /* empty => full address */ + ? string_sprintf("%s", authenticated_id) + : string_sprintf("%s@%s", + local_part_quote(authenticated_id), submission_domain) + : string_sprintf("%s@%s", + local_part_quote(originator_login), qualify_domain_sender); /* Remove permitted prefixes and suffixes from the local part of the From: address before doing the comparison with the generated sender. */ - if (from_address != NULL) + if (from_address) { int slen; - uschar *at = (domain == 0)? NULL : from_address + domain - 1; + uschar *at = domain ? from_address + domain - 1 : NULL; - if (at != NULL) *at = 0; + if (at) *at = 0; from_address += route_check_prefix(from_address, local_from_prefix); slen = route_check_suffix(from_address, local_from_suffix); if (slen > 0) @@ -2888,10 +2865,10 @@ if (from_header != NULL && memmove(from_address+slen, from_address, Ustrlen(from_address)-slen); from_address += slen; } - if (at != NULL) *at = '@'; + if (at) *at = '@'; - if (strcmpic(generated_sender_address, from_address) == 0 || - (domain == 0 && strcmpic(from_address, originator_login) == 0)) + if ( strcmpic(generated_sender_address, from_address) == 0 + || (!domain && strcmpic(from_address, originator_login) == 0)) make_sender = FALSE; } @@ -2899,8 +2876,7 @@ if (from_header != NULL && appropriate rewriting rules. */ if (make_sender) - { - if (submission_mode && submission_name == NULL) + if (submission_mode && !submission_name) header_add(htype_sender, "%sSender: %s\n", resent_prefix, generated_sender_address); else @@ -2908,14 +2884,13 @@ if (from_header != NULL && resent_prefix, submission_mode? submission_name : originator_name, generated_sender_address); - } /* Ensure that a non-null envelope sender address corresponds to the submission mode sender address. */ - if (submission_mode && sender_address[0] != 0) + if (submission_mode && *sender_address) { - if (sender_address_unrewritten == NULL) + if (!sender_address_unrewritten) sender_address_unrewritten = sender_address; sender_address = generated_sender_address; if (Ustrcmp(sender_address_unrewritten, generated_sender_address) != 0) @@ -2928,8 +2903,7 @@ if (from_header != NULL && /* If there are any rewriting rules, apply them to the sender address, unless it has already been rewritten as part of verification for SMTP input. */ -if (global_rewrite_rules != NULL && sender_address_unrewritten == NULL && - sender_address[0] != 0) +if (global_rewrite_rules && !sender_address_unrewritten && *sender_address) { sender_address = rewrite_address(sender_address, FALSE, TRUE, global_rewrite_rules, rewrite_existflags); @@ -2978,9 +2952,8 @@ to be more confusing if Exim adds one to all remotely-originated messages. As per Message-Id, we prepend if resending, else append. */ -if (!date_header_exists && - ((sender_host_address == NULL && !suppress_local_fixups) - || submission_mode)) +if ( !date_header_exists + && ((!sender_host_address && !suppress_local_fixups) || submission_mode)) header_add_at_position(!resents_exist, NULL, FALSE, htype_other, "%sDate: %s\n", resent_prefix, tod_stamp(tod_full)); @@ -2992,7 +2965,7 @@ new Received:) has not yet been set. */ DEBUG(D_receive) { debug_printf(">>Headers after rewriting and local additions:\n"); - for (h = header_list->next; h != NULL; h = h->next) + for (h = header_list->next; h; h = h->next) debug_printf("%c %s", h->type, h->text); debug_printf("\n"); } @@ -3094,7 +3067,7 @@ format); write it (remembering that it might contain binary zeros). The result of fwrite() isn't inspected; instead we call ferror() below. */ fprintf(data_file, "%s-D\n", message_id); -if (next != NULL) +if (next) { uschar *s = next->text; int len = next->slen; @@ -3149,10 +3122,10 @@ if (!ferror(data_file) && !(receive_feof)() && message_ended != END_DOT) log_write(L_size_reject, LOG_MAIN|LOG_REJECT, "rejected from <%s>%s%s%s%s: " "message too big: read=%d max=%d", sender_address, - (sender_fullhost == NULL)? "" : " H=", - (sender_fullhost == NULL)? US"" : sender_fullhost, - (sender_ident == NULL)? "" : " U=", - (sender_ident == NULL)? US"" : sender_ident, + sender_fullhost ? " H=" : "", + sender_fullhost ? sender_fullhost : US"", + sender_ident ? " U=" : "", + sender_ident ? sender_ident : US"", message_size, thismessage_size_limit); @@ -3205,7 +3178,7 @@ if (fflush(data_file) == EOF || ferror(data_file) || uschar *msg = string_sprintf("%s error (%s) while receiving message from %s", input_error? "Input read" : "Spool write", msg_errno, - (sender_fullhost != NULL)? sender_fullhost : sender_ident); + sender_fullhost ? sender_fullhost : sender_ident); log_write(0, LOG_MAIN, "Message abandoned: %s", msg); Uunlink(spool_name); /* Lose the data file */ @@ -3237,6 +3210,7 @@ if (fflush(data_file) == EOF || ferror(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); /* If there were any bad addresses extracted by -t, or there were no recipients @@ -3250,12 +3224,12 @@ recipients or stderr error writing, throw the data file away afterwards, and exit. (This can't be SMTP, which always ensures there's at least one syntactically good recipient address.) */ -if (extract_recip && (bad_addresses != NULL || recipients_count == 0)) +if (extract_recip && (bad_addresses || recipients_count == 0)) { DEBUG(D_receive) { if (recipients_count == 0) debug_printf("*** No recipients\n"); - if (bad_addresses != NULL) + if (bad_addresses) { error_block *eblock = bad_addresses; debug_printf("*** Bad address(es)\n"); @@ -3286,7 +3260,7 @@ if (extract_recip && (bad_addresses != NULL || recipients_count == 0)) } else { - if (bad_addresses == NULL) + if (!bad_addresses) { if (extracted_ignored) fprintf(stderr, "exim: all -t recipients overridden by command line\n"); @@ -3331,7 +3305,7 @@ Note: the checking for too many Received: headers is handled by the delivery code. */ /*XXX eventually add excess Received: check for cutthrough case back when classifying them */ -if (received_header->text == NULL) /* Non-cutthrough case */ +if (!received_header->text) /* Non-cutthrough case */ { received_header_gen(); @@ -3989,6 +3963,9 @@ if (LOGGING(dkim) && dkim_verify_overall) g = string_append(g, 2, US" DKIM=", dkim_verify_overall); #endif +if (LOGGING(receive_time)) + g = string_append(g, 2, US" RT=", string_timediff(&received_time_taken)); + if (*queue_name) g = string_append(g, 2, US" Q=", queue_name); @@ -4012,7 +3989,7 @@ if (msgid_header) /* If subject logging is turned on, create suitable printing-character text. By expanding $h_subject: we make use of the MIME decoding. */ -if (LOGGING(subject) && subject_header != NULL) +if (LOGGING(subject) && subject_header) { int i; uschar *p = big_buffer; diff --git a/test/log/0551 b/test/log/0551 index 5baae67cb..caa5d9406 100644 --- a/test/log/0551 +++ b/test/log/0551 @@ -6,6 +6,6 @@ 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 <= CALLER@myhost.test.ex U=CALLER P=local S=sss RT=q.qqqs 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 1b6e0d628..a6844bebb 100755 --- a/test/runtest +++ b/test/runtest @@ -491,8 +491,8 @@ 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/((D|[QD]T)=)\d+s/$1qqs/g; - s/((D|[QD]T)=)\d\.\d{3}s/$1q.qqqs/g; + s/((D|[RQD]T)=)\d+s/$1qqs/g; + s/((D|[RQD]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 diff --git a/test/scripts/0000-Basic/0551 b/test/scripts/0000-Basic/0551 index 1565275ea..35b686246 100644 --- a/test/scripts/0000-Basic/0551 +++ b/test/scripts/0000-Basic/0551 @@ -1,4 +1,4 @@ -# log_selector = +pid , +millisec +# log_selector = +pid , +millisec, +receive_time # exim -odi userx@test.ex usery@test.ex Message 1 @@ -6,7 +6,7 @@ Message 1 exim -DLOG_SELECTOR=+pid+queue_time -odi userx@test.ex userz@test.ex Message 2 **** -exim -d+all -DLOG_SELECTOR=+queue_time+queue_time_overall+deliver_time+millisec -odi userx@test.ex +exim -d+all -DLOG_SELECTOR=+receive_time+queue_time+queue_time_overall+deliver_time+millisec -odi userx@test.ex Message 3 **** exigrep userx diff --git a/test/stdout/0551 b/test/stdout/0551 index 9b99fcc54..b1b17c478 100644 --- a/test/stdout/0551 +++ b/test/stdout/0551 @@ -8,7 +8,7 @@ 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 <= CALLER@myhost.test.ex U=CALLER P=local S=sss RT=q.qqqs 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 -- 2.30.2