summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorJeremy Harris <jgh146exb@wizmail.org>2018-01-16 21:31:28 +0000
committerJeremy Harris <jgh146exb@wizmail.org>2018-01-16 21:31:28 +0000
commit306c6c7751cf6953dc544a607b584a9ca58623ad (patch)
tree0758225ef33652437874e2d2a2be7105ef5b982f
parentbf0f389a2904ec7a86781561d866af3a1ae2d040 (diff)
Logging: Receive duration on <= lines. Bug 353
-rw-r--r--doc/doc-docbook/spec.xfpt13
-rw-r--r--doc/doc-txt/NewStuff4
-rw-r--r--src/src/deliver.c9
-rw-r--r--src/src/functions.h1
-rw-r--r--src/src/globals.c2
-rw-r--r--src/src/globals.h1
-rw-r--r--src/src/macros.h1
-rw-r--r--src/src/receive.c171
-rw-r--r--test/log/05512
-rwxr-xr-xtest/runtest4
-rw-r--r--test/scripts/0000-Basic/05514
-rw-r--r--test/stdout/05512
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=<domain>" 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 <userx@test.ex> R=r1 T=t1 QT=qqs
1999-03-02 09:44:33 [1237] 10HmaY-0005vi-00 => userz <userz@test.ex> 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 <userx@test.ex> 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 <userz@test.ex> 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 <userx@test.ex> R=r1 T=t1 QT=q.qqqs DT=q.qqqs
2017-07-30 18:51:05.712 10HmaZ-0005vi-00 Completed QT=q.qqqs