Logging: Receive duration on <= lines. Bug 353

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index b6d283b95f48264e19cb74eaf7117bce0d3dff12..40de5b9b1b2baf22e70f674a252558ce7ad52d05 100644 (file)
--- 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
 &`    `&        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
 &`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)
 &` 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
 &` 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
 &%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"
 .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.
 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
 .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 15722e114d96d3605a3329865bc6f924547cb395..560e15ef50b5aa80b210d639eab9d8260aec50f0 100644 (file)
--- 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.
 
  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.
 
     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
 ------------
 
 Version 4.90
 ------------

diff --git a/src/src/deliver.c b/src/src/deliver.c
index de552f4cc0931642af59e2c227b878aa51111714..05fd3ce6d3b6a47083b446779bdceab272db8446 100644 (file)
--- 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. */
   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
   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")];
 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 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");
 
   else
     log_write(0, LOG_MAIN, "Completed");
 

diff --git a/src/src/functions.h b/src/src/functions.h
index 1e8698b7809928e9a60844fe3387f96dea914cf0..d2105a7b413ddfe66d95824f91e83ba377e48d66 100644 (file)
--- 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_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
 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 303c8025cb1e8dcf4e238547f18d2f115be21b5b..8ec62466fdf76b61066be03848b8f6438c42d353 100644 (file)
--- 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, 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),
   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 };
 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;
 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 1715a3df5d72bdcd7d7ac65bec727253a4e26596..ed5aee839c3a88f8be4d8821cfff22712aab0bfa 100644 (file)
--- 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 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 */
 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 20e3455739ee611aa4eab02eeea4ef4e3312780d..65a1a172a3878adcb79261230f9601e5c26a7b3e 100644 (file)
--- 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_proxy,
   Li_queue_time,
   Li_queue_time_overall,

+  Li_receive_time,

   Li_received_sender,
   Li_received_recipients,
   Li_rejected_header,
   Li_received_sender,
   Li_received_recipients,
   Li_rejected_header,

diff --git a/src/src/receive.c b/src/src/receive.c
index d79b282fbc855d56c34fb599ac08f07c14af32b0..8c7e2b5256c27b052e3ab4f21ef2b8dc168c0807 100644 (file)
--- 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
 
 /* 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;
 
 
 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). */
 
 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",
   {
   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. */
 
 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"";
   {
   uschar *p;
   uschar *id_text = US"";


@@ -2665,20 +2664,20 @@ if (msgid_header == NULL &&
 
   /* Permit only letters, digits, dots, and hyphens in the domain */
 
 
   /* 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);
     {
     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);
       }
       {
       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;
       {
       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 '-' ! */
       }
     }
         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. */
 
   /* 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);
     {
     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);
       }
       {
       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;
       {
       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. */
 
 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"";
 
   {
   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. */
 
   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))
     {
     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. */
 
   /* 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 */
 
 
   /* Envelope sender is empty */
 

-  if (sender_address[0] == 0)
+  if (!*sender_address)

     {
     uschar *fromstart, *fromend;
 
     {
     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)
 
     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);
       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);
         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);
         header_add(htype_from, "%s%s%s\n", fromstart, authenticated_id,
           fromend);

-        }
+

       else
       else

-        {

         header_add(htype_from, "%s%s@%s%s\n", fromstart,
         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: */
       }
     }
       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,
     {
     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: */
     }
 
     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. */
 
 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;
   {
   BOOL make_sender = TRUE;
   int start, end, domain;


@@ -2850,37 +2838,26 @@ if (from_header != NULL &&
       &start, &end, &domain, FALSE);
   uschar *generated_sender_address;
 
       &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. */
 
 
   /* 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;
     {
     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)
     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;
       }
       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;
     }
 
         make_sender = FALSE;
     }
 


@@ -2899,8 +2876,7 @@ if (from_header != NULL &&
   appropriate rewriting rules. */
 
   if (make_sender)
   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
       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);
         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. */
 
 
   /* 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)
       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 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);
   {
   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.
 */
 
 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));
 
   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");
 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");
   }
     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);
 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;
   {
   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,
       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);
 
        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,
   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 */
 
   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);
 /* 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
 
 
 /* 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.) */
 
 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");
   {
   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");
       {
       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
     {
     }
   else
     {

-    if (bad_addresses == NULL)
+    if (!bad_addresses)

       {
       if (extracted_ignored)
         fprintf(stderr, "exim: all -t recipients overridden by command line\n");
       {
       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 */
 
 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();
 
   {
   received_header_gen();
 


@@ -3989,6 +3963,9 @@ if (LOGGING(dkim) && dkim_verify_overall)
   g = string_append(g, 2, US" DKIM=", dkim_verify_overall);
 #endif
 
   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);
 
 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 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;
   {
   int i;
   uschar *p = big_buffer;

diff --git a/test/log/0551 b/test/log/0551
index 5baae67cb60a7976dd4b5667e8f32a0163ad9d6b..caa5d9406b5ccef7f6982fd14c43d917a39cb766 100644 (file)
--- 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
 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
 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 1b6e0d62849830fc83e85ec9e6039ed7ab2828b4..a6844bebbbd65c10cb43bf684340843247e0bb7c 100755 (executable)
--- 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{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
 
   # 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 1565275eacc4ede9408e16c01e36999d52d53464..35b6862461097c2b8b428171646b8e40a828ac03 100644 (file)
--- 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
 #
 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 -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
 Message 3
 ****
 exigrep userx

diff --git a/test/stdout/0551 b/test/stdout/0551
index 9b99fcc5486e1ffc2ae209b394f5e5d8e1e24980..b1b17c4788d7e4e9fc145b981dd653d4ebd8173d 100644 (file)
--- 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
 
 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
 
 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