Logging: Add DT= to defer & fail message lines. Bug 322

diff --git a/doc/doc-docbook/spec.xfpt b/doc/doc-docbook/spec.xfpt
index 1d4c39c6d6a898b9e71ea616826b45c028fbdc55..19888e96d052b06df3f11f9a7b4ad02935cc283a 100644 (file)
--- a/doc/doc-docbook/spec.xfpt
+++ b/doc/doc-docbook/spec.xfpt
@@ -37355,7 +37355,7 @@ the following table:
 &`DKIM`&        domain verified in incoming message
 &`DN  `&        distinguished name from peer certificate
 &`DS  `&        DNSSEC secured lookups
-&`DT  `&        on &`=>`& lines: time taken for a delivery
+&`DT  `&        on &`=>`&, &'=='& and &'**'& lines: time taken for, or to attempt, a delivery
 &`F   `&        sender address (on delivery lines)
 &`H   `&        host name and IP address
 &`I   `&        local interface used
@@ -37453,7 +37453,7 @@ selection marked by asterisks:
 &` arguments                  `&  command line arguments
 &`*connection_reject          `&  connection rejections
 &`*delay_delivery             `&  immediate delivery delayed
-&` deliver_time               `&  time taken to perform delivery
+&` deliver_time               `&  time taken to attempt delivery
 &` delivery_size              `&  add &`S=`&&'nnn'& to => lines
 &`*dkim                       `&  DKIM verified domain on <= lines
 &` dkim_verbose               `&  separate full DKIM verification result line, per signature

diff --git a/doc/doc-txt/ChangeLog b/doc/doc-txt/ChangeLog
index f1db06451049f7f8f0a1c49dc3a00b5078b60619..491ff5208e46f5131783bcba833f9d003ec51e55 100644 (file)
--- a/doc/doc-txt/ChangeLog
+++ b/doc/doc-txt/ChangeLog
@@ -70,6 +70,10 @@ JH/16 Fix the variables set by the gsasl authenticator.  Previously a pointer to
       library live data was being used, so the results became garbage.  Make
       copies while it is still usable.
 
+JH/17 Logging: when the deliver_time selector ise set, include the DT= field
+      on delivery deferred (==) and failed (**) lines (if a delivery was
+      attemtped).  Previously it was only on completion (=>) lines.
+
 
 Exim version 4.93
 -----------------

diff --git a/src/src/deliver.c b/src/src/deliver.c
index 28a1174af6864fc50125f4a0395a3b5163763002..c4160a50c380a635e7ecb2ad0770851304da1a1e 100644 (file)
--- a/src/src/deliver.c
+++ b/src/src/deliver.c
@@ -429,7 +429,7 @@ for (address_item * addr2 = addr->next; addr2; addr2 = addr2->next)
   addr2->transport_return = addr->transport_return;
   addr2->basic_errno =     addr->basic_errno;
   addr2->more_errno =      addr->more_errno;
-  addr2->delivery_usec =    addr->delivery_usec;
+  addr2->delivery_time =    addr->delivery_time;
   addr2->special_action =   addr->special_action;
   addr2->message =         addr->message;
   addr2->user_message =            addr->user_message;
@@ -1264,10 +1264,7 @@ if (LOGGING(queue_time))
     string_timesince(&received_time));
 
 if (LOGGING(deliver_time))
-  {
-  struct timeval diff = {.tv_sec = addr->more_errno, .tv_usec = addr->delivery_usec};
-  g = string_append(g, 2, US" DT=", string_timediff(&diff));
-  }
+  g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time));
 
 /* string_cat() always leaves room for the terminator. Release the
 store we used to build the line after writing it. */
@@ -1335,6 +1332,9 @@ if (addr->host_used)
     }
   }
 
+if (LOGGING(deliver_time))
+  g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time));
+
 if (addr->message)
   g = string_append(g, 2, US": ", addr->message);
 
@@ -1414,6 +1414,9 @@ if (addr->basic_errno > 0)
 if (addr->message)
   g = string_append(g, 2, US": ", addr->message);
 
+if (LOGGING(deliver_time))
+  g = string_append(g, 2, US" DT=", string_timediff(&addr->delivery_time));
+
 (void) string_from_gstring(g);
 
 /* Do the logging. For the message log, "routing failed" for those cases,
@@ -2407,7 +2410,7 @@ if ((pid = fork()) == 0)
       || (ret = write(pfd[pipe_write], &addr2->flags, sizeof(addr2->flags))) != sizeof(addr2->flags)
       || (ret = write(pfd[pipe_write], &addr2->basic_errno,    sizeof(int))) != sizeof(int)
       || (ret = write(pfd[pipe_write], &addr2->more_errno,     sizeof(int))) != sizeof(int)
-      || (ret = write(pfd[pipe_write], &addr2->delivery_usec,  sizeof(int))) != sizeof(int)
+      || (ret = write(pfd[pipe_write], &addr2->delivery_time,  sizeof(struct timeval))) != sizeof(struct timeval)
       || (ret = write(pfd[pipe_write], &addr2->special_action, sizeof(int))) != sizeof(int)
       || (ret = write(pfd[pipe_write], &addr2->transport,
         sizeof(transport_instance *))) != sizeof(transport_instance *)
@@ -2475,7 +2478,7 @@ for (addr2 = addr; addr2; addr2 = addr2->next)
     len = read(pfd[pipe_read], &addr2->flags, sizeof(addr2->flags));
     len = read(pfd[pipe_read], &addr2->basic_errno,    sizeof(int));
     len = read(pfd[pipe_read], &addr2->more_errno,     sizeof(int));
-    len = read(pfd[pipe_read], &addr2->delivery_usec,  sizeof(int));
+    len = read(pfd[pipe_read], &addr2->delivery_time,  sizeof(struct timeval));
     len = read(pfd[pipe_read], &addr2->special_action, sizeof(int));
     len = read(pfd[pipe_read], &addr2->transport,
       sizeof(transport_instance *));
@@ -3129,11 +3132,7 @@ while (addr_local)
 
     /* Done with this address */
 
-    if (result == OK)
-      {
-      addr2->more_errno = deliver_time.tv_sec;
-      addr2->delivery_usec = deliver_time.tv_usec;
-      }
+    addr2->delivery_time = deliver_time;
     post_process_one(addr2, result, logflags, EXIM_DTYPE_TRANSPORT, logchar);
 
     /* If a pipe delivery generated text to be sent back, the result may be
@@ -3607,8 +3606,8 @@ while (!done)
          ptr += sizeof(addr->basic_errno);
          memcpy(&addr->more_errno, ptr, sizeof(addr->more_errno));
          ptr += sizeof(addr->more_errno);
-         memcpy(&addr->delivery_usec, ptr, sizeof(addr->delivery_usec));
-         ptr += sizeof(addr->delivery_usec);
+         memcpy(&addr->delivery_time, ptr, sizeof(addr->delivery_time));
+         ptr += sizeof(addr->delivery_time);
          memcpy(&addr->flags, ptr, sizeof(addr->flags));
          ptr += sizeof(addr->flags);
          addr->message = *ptr ? string_copy(ptr) : NULL;
@@ -4924,8 +4923,8 @@ all pipes, so I do not see a reason to use non-blocking IO here
       ptr += sizeof(addr->basic_errno);
       memcpy(ptr, &addr->more_errno, sizeof(addr->more_errno));
       ptr += sizeof(addr->more_errno);
-      memcpy(ptr, &addr->delivery_usec, sizeof(addr->delivery_usec));
-      ptr += sizeof(addr->delivery_usec);
+      memcpy(ptr, &addr->delivery_time, sizeof(addr->delivery_time));
+      ptr += sizeof(addr->delivery_time);
       memcpy(ptr, &addr->flags, sizeof(addr->flags));
       ptr += sizeof(addr->flags);
 

diff --git a/src/src/functions.h b/src/src/functions.h
index 475f2c496890c75ece60f89716bf69af7f4a2b47..d5df987966220dda2f1e30d6ee98f3dafbe51a4f 100644 (file)
--- a/src/src/functions.h
+++ b/src/src/functions.h
@@ -931,7 +931,7 @@ subdir_str[1] = '\0';
 
 /******************************************************************************/
 static inline void
-timesince(struct timeval * diff, struct timeval * then)
+timesince(struct timeval * diff, const struct timeval * then)
 {
 gettimeofday(diff, NULL);
 diff->tv_sec -= then->tv_sec;
@@ -943,7 +943,7 @@ if ((diff->tv_usec -= then->tv_usec) < 0)
 }
 
 static inline uschar *
-string_timediff(struct timeval * diff)
+string_timediff(const struct timeval * diff)
 {
 static uschar buf[sizeof("0.000s")];
 
@@ -956,7 +956,7 @@ return buf;
 
 
 static inline uschar *
-string_timesince(struct timeval * then)
+string_timesince(const struct timeval * then)
 {
 struct timeval diff;
 timesince(&diff, then);
@@ -964,7 +964,7 @@ return string_timediff(&diff);
 }
 
 static inline void
-report_time_since(struct timeval * t0, uschar * where)
+report_time_since(const struct timeval * t0, const uschar * where)
 {
 # ifdef MEASURE_TIMING
 struct timeval diff;

diff --git a/src/src/globals.c b/src/src/globals.c
index ff50cce313cf95cbe012a6ed8d41094d7a63ecab..15ad4e9328988cfe17b3dfd8e3b4a2c641ea1d7d 100644 (file)
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -573,7 +573,7 @@ address_item address_defaults = {
   .localpart_cache =   { 0 },                /* localpart_cache - ditto */
   .mode =              -1,
   .more_errno =                0,
-  .delivery_usec =     0,
+  .delivery_time =     {.tv_sec = 0, .tv_usec = 0},
   .basic_errno =       ERRNO_UNKNOWNERROR,
   .child_count =       0,
   .return_file =       -1,

diff --git a/src/src/structs.h b/src/src/structs.h
index 9927bc527296b95c7acfb8f822373e840f045a82..060eccf41aa5da5717706df8f82d1868c8dc8c8d 100644 (file)
--- a/src/src/structs.h
+++ b/src/src/structs.h
@@ -650,8 +650,7 @@ typedef struct address_item {
   int     mode;                   /* mode for local transporting to a file */
   int    basic_errno;            /* status after failure */
   int     more_errno;             /* additional error information */
-                                  /* (may need to hold a timestamp) */
-  unsigned int delivery_usec;    /* subsecond part of delivery time */
+  struct timeval delivery_time;   /* time taken to do delivery/attempt */
 
   unsigned short child_count;     /* number of child addresses */
   short int return_file;          /* fileno of return data file */

diff --git a/src/src/transport.c b/src/src/transport.c
index 14bd91cdb3e2160c0ee47f65a2c2a8e302e07cc0..b2a65ed3b09511a47c777f867b161b5cfcfe2c28 100644 (file)
--- a/src/src/transport.c
+++ b/src/src/transport.c
@@ -1260,8 +1260,8 @@ if ((write_pid = fork()) == 0)
         != sizeof(int)
      || write(pfd[pipe_write], (void *)&tctx->addr->more_errno, sizeof(int))
         != sizeof(int)
-     || write(pfd[pipe_write], (void *)&tctx->addr->delivery_usec, sizeof(int))
-        != sizeof(int)
+     || write(pfd[pipe_write], (void *)&tctx->addr->delivery_time, sizeof(struct timeval))
+        != sizeof(struct timeval)
      )
     rc = FALSE;        /* compiler quietening */
   exim_underbar_exit(0);
@@ -1387,7 +1387,7 @@ if (write_pid > 0)
         {
        int dummy = read(pfd[pipe_read], (void *)&save_errno, sizeof(int));
         dummy = read(pfd[pipe_read], (void *)&tctx->addr->more_errno, sizeof(int));
-        dummy = read(pfd[pipe_read], (void *)&tctx->addr->delivery_usec, sizeof(int));
+        dummy = read(pfd[pipe_read], (void *)&tctx->addr->delivery_time, sizeof(struct timeval));
        dummy = dummy;          /* compiler quietening */
         yield = FALSE;
         }

diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index 7428134d403cba9d9947c41805b6c07329f39aac..d7147b2f932d540a71b120a372bc90383da503c7 100644 (file)
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -537,6 +537,7 @@ Arguments:
   host           if set, mark addrs as having used this host
   smtp_greeting  from peer
   helo_response  from peer
+  start                 points to timestamp of delivery start
 
 If errno_value has the special value ERRNO_CONNECTTIMEOUT, ETIMEDOUT is put in
 the errno field, and RTEF_CTOUT is ORed into the more_errno field, to indicate
@@ -547,23 +548,29 @@ Returns:       nothing
 
 static void
 set_errno(address_item *addrlist, int errno_value, uschar *msg, int rc,
-  BOOL pass_message, host_item * host
+  BOOL pass_message, host_item * host,
 #ifdef EXPERIMENTAL_DSN_INFO
-  , const uschar * smtp_greeting, const uschar * helo_response
+  const uschar * smtp_greeting, const uschar * helo_response,
 #endif
+  struct timeval * start
   )
 {
 int orvalue = 0;
+struct timeval deliver_time;
+
 if (errno_value == ERRNO_CONNECTTIMEOUT)
   {
   errno_value = ETIMEDOUT;
   orvalue = RTEF_CTOUT;
   }
+timesince(&deliver_time, start);
+
 for (address_item * addr = addrlist; addr; addr = addr->next)
   if (addr->transport_return >= PENDING)
     {
     addr->basic_errno = errno_value;
     addr->more_errno |= orvalue;
+    addr->delivery_time = deliver_time;
     if (msg)
       {
       addr->message = msg;
@@ -587,14 +594,14 @@ for (address_item * addr = addrlist; addr; addr = addr->next)
 }
 
 static void
-set_errno_nohost(address_item *addrlist, int errno_value, uschar *msg, int rc,
-  BOOL pass_message)
+set_errno_nohost(address_item * addrlist, int errno_value, uschar * msg, int rc,
+  BOOL pass_message, struct timeval * start)
 {
-set_errno(addrlist, errno_value, msg, rc, pass_message, NULL
+set_errno(addrlist, errno_value, msg, rc, pass_message, NULL,
 #ifdef EXPERIMENTAL_DSN_INFO
-         , NULL, NULL
+         NULL, NULL,
 #endif
-         );
+         start);
 }
 
 
@@ -1227,7 +1234,7 @@ while (count-- > 0)
     {
     uschar *message = string_sprintf("SMTP timeout after RCPT TO:<%s>",
                transport_rcpt_address(addr, sx->conn_args.tblock->rcpt_include_affixes));
-    set_errno_nohost(sx->first_addr, ETIMEDOUT, message, DEFER, FALSE);
+    set_errno_nohost(sx->first_addr, ETIMEDOUT, message, DEFER, FALSE, &sx->delivery_start);
     retry_add_item(addr, addr->address_retry_key, 0);
     update_waiting = FALSE;
     return -1;
@@ -1445,7 +1452,7 @@ switch(rc)
 
   case ERROR:
     set_errno_nohost(sx->addrlist, ERRNO_AUTHPROB, string_copy(sx->buffer),
-             DEFER, FALSE);
+             DEFER, FALSE, &sx->delivery_start);
     return ERROR;
   }
 return OK;
@@ -1614,7 +1621,7 @@ if (require_auth == OK && !f.smtp_authenticated)
   {
   set_errno_nohost(sx->addrlist, ERRNO_AUTHFAIL,
     string_sprintf("authentication required but %s", fail_reason), DEFER,
-    FALSE);
+    FALSE, &sx->delivery_start);
   return DEFER;
   }
 
@@ -1625,9 +1632,9 @@ return OK;
 /* Construct AUTH appendix string for MAIL TO */
 /*
 Arguments
-  buffer       to build string
+  sx           context for smtp connection
+  p            point in sx->buffer to build string
   addrlist      chain of potential addresses to deliver
-  ob           transport options
 
 Globals                f.smtp_authenticated
                client_authenticated_sender
@@ -1635,29 +1642,31 @@ Return  True on error, otherwise buffer has (possibly empty) terminated string
 */
 
 static BOOL
-smtp_mail_auth_str(uschar *buffer, unsigned bufsize, address_item *addrlist,
-                   smtp_transport_options_block *ob)
+smtp_mail_auth_str(smtp_context * sx, uschar * p, address_item * addrlist)
 {
+smtp_transport_options_block * ob = sx->conn_args.ob;
 uschar * local_authenticated_sender = authenticated_sender;
 
 #ifdef notdef
-  debug_printf("smtp_mail_auth_str: as<%s> os<%s> SA<%s>\n", authenticated_sender, ob->authenticated_sender, f.smtp_authenticated?"Y":"N");
+  debug_printf("smtp_mail_auth_str: as<%s> os<%s> SA<%s>\n",
+    authenticated_sender, ob->authenticated_sender, f.smtp_authenticated?"Y":"N");
 #endif
 
 if (ob->authenticated_sender)
   {
-  uschar *new = expand_string(ob->authenticated_sender);
+  uschar * new = expand_string(ob->authenticated_sender);
   if (!new)
     {
     if (!f.expand_string_forcedfail)
       {
       uschar *message = string_sprintf("failed to expand "
         "authenticated_sender: %s", expand_string_message);
-      set_errno_nohost(addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE);
+      set_errno_nohost(addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE, &sx->delivery_start);
       return TRUE;
       }
     }
-  else if (*new) local_authenticated_sender = new;
+  else if (*new)
+    local_authenticated_sender = new;
   }
 
 /* Add the authenticated sender address if present */
@@ -1665,13 +1674,13 @@ if (ob->authenticated_sender)
 if (  (f.smtp_authenticated || ob->authenticated_sender_force)
    && local_authenticated_sender)
   {
-  string_format_nt(buffer, bufsize, " AUTH=%s",
+  string_format_nt(p, sizeof(sx->buffer) - (p-sx->buffer), " AUTH=%s",
     auth_xtextencode(local_authenticated_sender,
       Ustrlen(local_authenticated_sender)));
   client_authenticated_sender = string_copy(local_authenticated_sender);
   }
 else
-  *buffer= 0;
+  *p = 0;
 
 return FALSE;
 }
@@ -2046,7 +2055,7 @@ tls_modify_variables(&tls_out);
 if (sx->smtps)
   {
   set_errno_nohost(sx->addrlist, ERRNO_TLSFAILURE, US"TLS support not available",
-           DEFER, FALSE);
+           DEFER, FALSE, &sx->delivery_start);
   return ERROR;
   }
 #endif
@@ -2085,7 +2094,7 @@ if (!continue_hostname)
          default:              set_errno_nohost(sx->addrlist, ERRNO_DNSDEFER,
                                  string_sprintf("DANE error: tlsa lookup %s",
                                    rc_to_string(rc)),
-                                 rc, FALSE);
+                                 rc, FALSE, &sx->delivery_start);
 # ifndef DISABLE_EVENT
                                (void) event_raise(sx->conn_args.tblock->event_action,
                                  US"dane:fail", sx->dane_required
@@ -2098,7 +2107,7 @@ if (!continue_hostname)
       {
       set_errno_nohost(sx->addrlist, ERRNO_DNSDEFER,
        string_sprintf("DANE error: %s lookup not DNSSEC", sx->conn_args.host->name),
-       FAIL, FALSE);
+       FAIL, FALSE, &sx->delivery_start);
 # ifndef DISABLE_EVENT
       (void) event_raise(sx->conn_args.tblock->event_action,
        US"dane:fail", US"dane-required");
@@ -2149,7 +2158,7 @@ if (!continue_hostname)
       set_errno_nohost(sx->addrlist,
        errno == ETIMEDOUT ? ERRNO_CONNECTTIMEOUT : errno,
        sx->verify ? US strerror(errno) : NULL,
-       DEFER, FALSE);
+       DEFER, FALSE, &sx->delivery_start);
       sx->send_quit = FALSE;
       return DEFER;
       }
@@ -2216,7 +2225,7 @@ will be?  Somehow I doubt it. */
        {
        set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL,
          string_sprintf("deferred by smtp:connect event expansion: %s", s),
-         DEFER, FALSE);
+         DEFER, FALSE, &sx->delivery_start);
        yield = DEFER;
        goto SEND_QUIT;
        }
@@ -2230,7 +2239,7 @@ will be?  Somehow I doubt it. */
       {
       message = string_sprintf("failed to expand helo_data: %s",
         expand_string_message);
-      set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE);
+      set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE, &sx->delivery_start);
       yield = DEFER;
       goto SEND_QUIT;
       }
@@ -2577,7 +2586,7 @@ if (tls_out.active.sock >= 0)
     {
     uschar *message = string_sprintf("failed to expand helo_data: %s",
       expand_string_message);
-    set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE);
+    set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE, &sx->delivery_start);
     yield = DEFER;
     goto SEND_QUIT;
     }
@@ -2819,7 +2828,7 @@ if (sx->addrlist->prop.utf8_msg)
       {
       message = string_sprintf("failed to expand utf8_downconvert: %s",
         expand_string_message);
-      set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE);
+      set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, message, DEFER, FALSE, &sx->delivery_start);
       yield = DEFER;
       goto SEND_QUIT;
       }
@@ -2879,7 +2888,7 @@ return OK;
       set_errno_nohost(sx->addrlist,
        errno == ETIMEDOUT ? ERRNO_CONNECTTIMEOUT : errno,
        sx->verify ? US strerror(errno) : NULL,
-       DEFER, FALSE);
+       DEFER, FALSE, &sx->delivery_start);
       sx->send_quit = FALSE;
       return DEFER;
       }
@@ -2943,11 +2952,11 @@ FAILED:
 #endif
            ? FAIL : DEFER,
            pass_message,
-           errno == ECONNREFUSED ? NULL : sx->conn_args.host
+           errno == ECONNREFUSED ? NULL : sx->conn_args.host,
 #ifdef EXPERIMENTAL_DSN_INFO
-           , sx->smtp_greeting, sx->helo_response
+           sx->smtp_greeting, sx->helo_response,
 #endif
-           );
+           &sx->delivery_start);
   }
 
 
@@ -3089,10 +3098,7 @@ Other expansion failures are serious. An empty result is ignored, but there is
 otherwise no check - this feature is expected to be used with LMTP and other
 cases where non-standard addresses (e.g. without domains) might be required. */
 
-if (smtp_mail_auth_str(p, sizeof(sx->buffer) - (p-sx->buffer), addrlist, sx->conn_args.ob))
-  return ERROR;
-
-return OK;
+return smtp_mail_auth_str(sx, p, addrlist) ? ERROR : OK;
 }
 
 
@@ -3178,7 +3184,7 @@ sx->pending_MAIL = TRUE;     /* The block starts with MAIL */
     {
     if (s = string_address_utf8_to_alabel(s, &errstr), errstr)
       {
-      set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, errstr, DEFER, FALSE);
+      set_errno_nohost(sx->addrlist, ERRNO_EXPANDFAIL, errstr, DEFER, FALSE, &sx->delivery_start);
       *yield = ERROR;
       return -4;
       }
@@ -3472,6 +3478,9 @@ Returns:          OK    - the connection was made and the delivery attempted;
                           and there was a problem setting it up; OR helo_data
                           or add_headers or authenticated_sender is specified
                           for this transport, and the string failed to expand
+
+               For all non-OK returns the first addr of the list carries the
+               time taken for the attempt.
 */
 
 static int
@@ -3483,14 +3492,12 @@ smtp_transport_options_block * ob = SOB tblock->options_block;
 int yield = OK;
 int save_errno;
 int rc;
-struct timeval start_delivery_time;
 
 BOOL pass_message = FALSE;
 uschar *message = NULL;
 uschar new_message_id[MESSAGE_ID_LENGTH + 1];
 smtp_context * sx = store_get(sizeof(*sx), TRUE);      /* tainted, for the data buffers */
 
-gettimeofday(&start_delivery_time, NULL);
 suppress_tls = suppress_tls;  /* stop compiler warning when no TLS support */
 *message_defer = FALSE;
 
@@ -3503,13 +3510,17 @@ sx->conn_args.interface = interface;
 sx->helo_data = NULL;
 sx->conn_args.tblock = tblock;
 /* sx->verify = FALSE; */
+gettimeofday(&sx->delivery_start, NULL);
 sx->sync_addr = sx->first_addr = addrlist;
 
 /* Get the channel set up ready for a message (MAIL FROM being the next
 SMTP command to send */
 
 if ((rc = smtp_setup_conn(sx, suppress_tls)) != OK)
+  {
+  timesince(&addrlist->delivery_time, &sx->delivery_start);
   return rc;
+  }
 
 /* If there is a filter command specified for this transport, we can now
 set it up. This cannot be done until the identify of the host is known. */
@@ -3526,7 +3537,7 @@ if (tblock->filter_command)
        string_sprintf("%.50s transport", tblock->name), NULL))
     {
     set_errno_nohost(addrlist->next, addrlist->basic_errno, addrlist->message, DEFER,
-      FALSE);
+      FALSE, &sx->delivery_start);
     yield = ERROR;
     goto SEND_QUIT;
     }
@@ -3605,7 +3616,7 @@ else
        {
        /*XXX could we find a better errno than 0 here? */
        set_errno_nohost(addrlist, 0, a->message, FAIL,
-         testflag(a, af_pass_message));
+         testflag(a, af_pass_message), &sx->delivery_start);
        sx->ok = FALSE;
        break;
        }
@@ -3858,7 +3869,7 @@ else
     int len;
     uschar * conf = NULL;
 
-    timesince(&delivery_time, &start_delivery_time);
+    timesince(&delivery_time, &sx->delivery_start);
     sx->send_rset = FALSE;
     pipelining_active = FALSE;
 
@@ -3933,9 +3944,8 @@ else
       actual host that was used. */
 
       addr->transport_return = OK;
-      addr->more_errno = delivery_time.tv_sec;
-      addr->delivery_usec = delivery_time.tv_usec;
       addr->host_used = host;
+      addr->delivery_time = delivery_time;
       addr->special_action = flag;
       addr->message = conf;
 
@@ -4165,11 +4175,11 @@ if (!sx->ok)
       }
     }
 
-  set_errno(addrlist, save_errno, set_message, set_rc, pass_message, host
+  set_errno(addrlist, save_errno, set_message, set_rc, pass_message, host,
 #ifdef EXPERIMENTAL_DSN_INFO
-           , sx->smtp_greeting, sx->helo_response
+           sx->smtp_greeting, sx->helo_response,
 #endif
-           );
+           &sx->delivery_start);
   }
 
 /* If all has gone well, send_quit will be set TRUE, implying we can end the
@@ -4304,11 +4314,11 @@ if (sx->completed_addr && sx->ok && sx->send_quit)
            socket_fd = pfd[1];
          else
            set_errno(sx->first_addr, errno, US"internal allocation problem",
-                   DEFER, FALSE, host
+                   DEFER, FALSE, host,
 # ifdef EXPERIMENTAL_DSN_INFO
-                   , sx->smtp_greeting, sx->helo_response
+                   sx->smtp_greeting, sx->helo_response,
 # endif
-                   );
+                   &sx->delivery_start);
          }
       else
 #endif
@@ -4365,11 +4375,11 @@ propagate it from the initial
 
     /* If RSET failed and there are addresses left, they get deferred. */
     else
-      set_errno(sx->first_addr, errno, msg, DEFER, FALSE, host
+      set_errno(sx->first_addr, errno, msg, DEFER, FALSE, host,
 #ifdef EXPERIMENTAL_DSN_INFO
-                 , sx->smtp_greeting, sx->helo_response
+                 sx->smtp_greeting, sx->helo_response,
 #endif
-                 );
+                 &sx->delivery_start);
     }
   }
 
@@ -5094,7 +5104,9 @@ retry_non_continued:
 
     if (f.dont_deliver)
       {
-      set_errno_nohost(addrlist, 0, NULL, OK, FALSE);
+      struct timeval now;
+      gettimeofday(&now, NULL);
+      set_errno_nohost(addrlist, 0, NULL, OK, FALSE, &now);
       for (address_item * addr = addrlist; addr; addr = addr->next)
         {
         addr->host_used = host;

diff --git a/src/src/transports/smtp.h b/src/src/transports/smtp.h
index 46b1b041cca006a52822bc6333ea01d36a88de07..0ddb6276025e74f4a8ac718deabc46bea9d463e1 100644 (file)
--- a/src/src/transports/smtp.h
+++ b/src/src/transports/smtp.h
@@ -165,6 +165,7 @@ typedef struct {
   ehlo_resp_precis     ehlo_resp;
 #endif
 
+  struct timeval       delivery_start;
   address_item *       first_addr;
   address_item *       next_addr;
   address_item *       sync_addr;