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
 &`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
 &`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
 &` 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
 &` 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.
 
       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
 -----------------
 
 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->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;
   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))
     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. */
 
 /* 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);
 
 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 (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,
 (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->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 *)
       || (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->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 *));
     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 */
 
 
     /* 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
     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);
          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;
          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);
       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);
 
       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
 
 /******************************************************************************/
 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;
 {
 gettimeofday(diff, NULL);
 diff->tv_sec -= then->tv_sec;


@@ -943,7 +943,7 @@ if ((diff->tv_usec -= then->tv_usec) < 0)
 }
 
 static inline uschar *
 }
 
 static inline uschar *

-string_timediff(struct timeval * diff)
+string_timediff(const struct timeval * diff)

 {
 static uschar buf[sizeof("0.000s")];
 
 {
 static uschar buf[sizeof("0.000s")];
 


@@ -956,7 +956,7 @@ return buf;
 
 
 static inline uschar *
 
 
 static inline uschar *

-string_timesince(struct timeval * then)
+string_timesince(const struct timeval * then)

 {
 struct timeval diff;
 timesince(&diff, then);
 {
 struct timeval diff;
 timesince(&diff, then);


@@ -964,7 +964,7 @@ return string_timediff(&diff);
 }
 
 static inline void
 }
 
 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;
 {
 # 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,
   .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,
   .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 */
   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 */
 
   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)
         != 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);
      )
     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));
         {
        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;
         }
        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
   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
 
 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,
 
 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
 #ifdef EXPERIMENTAL_DSN_INFO

-  , const uschar * smtp_greeting, const uschar * helo_response
+  const uschar * smtp_greeting, const uschar * helo_response,

 #endif
 #endif

+  struct timeval * start

   )
 {
 int orvalue = 0;
   )
 {
 int orvalue = 0;

+struct timeval deliver_time;
+

 if (errno_value == ERRNO_CONNECTTIMEOUT)
   {
   errno_value = ETIMEDOUT;
   orvalue = RTEF_CTOUT;
   }
 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;
 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;
     if (msg)
       {
       addr->message = msg;


@@ -587,14 +594,14 @@ for (address_item * addr = addrlist; addr; addr = addr->next)
 }
 
 static void
 }
 
 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
 #ifdef EXPERIMENTAL_DSN_INFO

-         , NULL, NULL
+         NULL, NULL,

 #endif
 #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));
     {
     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;
     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),
 
   case ERROR:
     set_errno_nohost(sx->addrlist, ERRNO_AUTHPROB, string_copy(sx->buffer),

-             DEFER, FALSE);
+             DEFER, FALSE, &sx->delivery_start);

     return ERROR;
   }
 return OK;
     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,
   {
   set_errno_nohost(sx->addrlist, ERRNO_AUTHFAIL,
     string_sprintf("authentication required but %s", fail_reason), DEFER,

-    FALSE);
+    FALSE, &sx->delivery_start);

   return DEFER;
   }
 
   return DEFER;
   }
 


@@ -1625,9 +1632,9 @@ return OK;
 /* Construct AUTH appendix string for MAIL TO */
 /*
 Arguments
 /* 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
   addrlist      chain of potential addresses to deliver

-  ob           transport options

 
 Globals                f.smtp_authenticated
                client_authenticated_sender
 
 Globals                f.smtp_authenticated
                client_authenticated_sender


@@ -1635,29 +1642,31 @@ Return  True on error, otherwise buffer has (possibly empty) terminated string
 */
 
 static BOOL
 */
 
 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
 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)
   {
 #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);
   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;
       }
     }
       return TRUE;
       }
     }

-  else if (*new) local_authenticated_sender = new;
+  else if (*new)
+    local_authenticated_sender = new;

   }
 
 /* Add the authenticated sender address if present */
   }
 
 /* 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)
   {
 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
     auth_xtextencode(local_authenticated_sender,
       Ustrlen(local_authenticated_sender)));
   client_authenticated_sender = string_copy(local_authenticated_sender);
   }
 else

-  *buffer= 0;
+  *p = 0;

 
 return FALSE;
 }
 
 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",
 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
   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)),
          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
 # 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),
       {
       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");
 # 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,
       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;
       }
       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),
        {
        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;
        }
        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);
       {
       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;
       }
       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);
     {
     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;
     }
     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);
       {
       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;
       }
       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,
       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;
       }
       sx->send_quit = FALSE;
       return DEFER;
       }


@@ -2943,11 +2952,11 @@ FAILED:
 #endif
            ? FAIL : DEFER,
            pass_message,
 #endif
            ? FAIL : DEFER,
            pass_message,

-           errno == ECONNREFUSED ? NULL : sx->conn_args.host
+           errno == ECONNREFUSED ? NULL : sx->conn_args.host,

 #ifdef EXPERIMENTAL_DSN_INFO
 #ifdef EXPERIMENTAL_DSN_INFO

-           , sx->smtp_greeting, sx->helo_response
+           sx->smtp_greeting, sx->helo_response,

 #endif
 #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. */
 
 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)
       {
     {
     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;
       }
       *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
                           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
 */
 
 static int


@@ -3483,14 +3492,12 @@ smtp_transport_options_block * ob = SOB tblock->options_block;
 int yield = OK;
 int save_errno;
 int rc;
 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 */
 
 
 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;
 
 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; */
 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)
 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;
   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. */
 
 /* 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,
        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;
     }
     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,
        {
        /*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;
        }
        sx->ok = FALSE;
        break;
        }


@@ -3858,7 +3869,7 @@ else
     int len;
     uschar * conf = NULL;
 
     int len;
     uschar * conf = NULL;
 

-    timesince(&delivery_time, &start_delivery_time);
+    timesince(&delivery_time, &sx->delivery_start);

     sx->send_rset = FALSE;
     pipelining_active = FALSE;
 
     sx->send_rset = FALSE;
     pipelining_active = FALSE;
 


@@ -3933,9 +3944,8 @@ else
       actual host that was used. */
 
       addr->transport_return = OK;
       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->host_used = host;

+      addr->delivery_time = delivery_time;

       addr->special_action = flag;
       addr->message = conf;
 
       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
 #ifdef EXPERIMENTAL_DSN_INFO

-           , sx->smtp_greeting, sx->helo_response
+           sx->smtp_greeting, sx->helo_response,

 #endif
 #endif

-           );
+           &sx->delivery_start);

   }
 
 /* If all has gone well, send_quit will be set TRUE, implying we can end the
   }
 
 /* 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",
            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
 # ifdef EXPERIMENTAL_DSN_INFO

-                   , sx->smtp_greeting, sx->helo_response
+                   sx->smtp_greeting, sx->helo_response,

 # endif
 # endif

-                   );
+                   &sx->delivery_start);

          }
       else
 #endif
          }
       else
 #endif


@@ -4365,11 +4375,11 @@ propagate it from the initial
 
     /* If RSET failed and there are addresses left, they get deferred. */
     else
 
     /* 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
 #ifdef EXPERIMENTAL_DSN_INFO

-                 , sx->smtp_greeting, sx->helo_response
+                 sx->smtp_greeting, sx->helo_response,

 #endif
 #endif

-                 );
+                 &sx->delivery_start);

     }
   }
 
     }
   }
 


@@ -5094,7 +5104,9 @@ retry_non_continued:
 
     if (f.dont_deliver)
       {
 
     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;
       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
 
   ehlo_resp_precis     ehlo_resp;
 #endif
 

+  struct timeval       delivery_start;

   address_item *       first_addr;
   address_item *       next_addr;
   address_item *       sync_addr;
   address_item *       first_addr;
   address_item *       next_addr;
   address_item *       sync_addr;