external/ibm-public/postfix/dist/src/global/log_adhoc.c

   1 /*      $NetBSD$        */
   2
   3 /*++
   4 /* NAME
   5 /*      log_adhoc 3
   6 /* SUMMARY
   7 /*      ad-hoc delivery event logging
   8 /* SYNOPSIS
   9 /*      #include <log_adhoc.h>
  10 /*
  11 /*      void    log_adhoc(id, stats, recipient, relay, dsn, status)
  12 /*      const char *id;
  13 /*      MSG_STATS *stats;
  14 /*      RECIPIENT *recipient;
  15 /*      const char *relay;
  16 /*      DSN *dsn;
  17 /*      const char *status;
  18 /* DESCRIPTION
  19 /*      This module logs delivery events in an ad-hoc manner.
  20 /*
  21 /*      log_adhoc() appends a record to the mail logfile
  22 /*
  23 /*      Arguments:
  24 /* .IP queue
  25 /*      The message queue name of the original message file.
  26 /* .IP id
  27 /*      The queue id of the original message file.
  28 /* .IP stats
  29 /*      Time stamps from different message delivery stages
  30 /*      and session reuse count.
  31 /* .IP recipient
  32 /*      Recipient information. See recipient_list(3).
  33 /* .IP sender
  34 /*      The sender envelope address.
  35 /* .IP relay
  36 /*      Host we could (not) talk to.
  37 /* .IP status
  38 /*      bounced, deferred, sent, and so on.
  39 /* .IP dsn
  40 /*      Delivery status information. See dsn(3).
  41 /* BUGS
  42 /*      Should be replaced by routines with an attribute-value based
  43 /*      interface instead of an interface that uses a rigid argument list.
  44 /* LICENSE
  45 /* .ad
  46 /* .fi
  47 /*      The Secure Mailer license must be distributed with this software.
  48 /* AUTHOR(S)
  49 /*      Wietse Venema
  50 /*      IBM T.J. Watson Research
  51 /*      P.O. Box 704
  52 /*      Yorktown Heights, NY 10598, USA
  53 /*--*/
  54
  55 /* System library. */
  56
  57 #include <sys_defs.h>
  58 #include <string.h>
  59
  60 #ifdef STRCASECMP_IN_STRINGS_H
  61 #include <strings.h>
  62 #endif
  63
  64 /* Utility library. */
  65
  66 #include <msg.h>
  67 #include <vstring.h>
  68 #include <format_tv.h>
  69
  70 /* Global library. */
  71
  72 #include <log_adhoc.h>
  73 #include <mail_params.h>
  74
  75  /*
  76   * Don't use "struct timeval" for time differences; use explicit signed
  77   * types instead. The code below relies on signed values to detect clocks
  78   * jumping back.
  79   */
  80 typedef struct {
  81     int     dt_sec;                     /* make sure it's signed */
  82     int     dt_usec;                    /* make sure it's signed */
  83 } DELTA_TIME;
  84
  85 /* log_adhoc - ad-hoc logging */
  86
  87 void    log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient,
  88                           const char *relay, DSN *dsn,
  89                           const char *status)
  90 {
  91     static VSTRING *buf;
  92     DELTA_TIME delay;                   /* end-to-end delay */
  93     DELTA_TIME pdelay;                  /* time before queue manager */
  94     DELTA_TIME adelay;                  /* queue manager latency */
  95     DELTA_TIME sdelay;                  /* connection set-up latency */
  96     DELTA_TIME xdelay;                  /* transmission latency */
  97     struct timeval now;
  98
  99     /*
 100      * Alas, we need an intermediate buffer for the pre-formatted result.
 101      * There are several optional fields, and the delay fields are formatted
 102      * in a manner that is not supported by vstring_sprintf().
 103      */
 104     if (buf == 0)
 105         buf = vstring_alloc(100);
 106
 107     /*
 108      * First, critical information that identifies the nature of the
 109      * transaction.
 110      */
 111     vstring_sprintf(buf, "%s: to=<%s>", id, recipient->address);
 112     if (recipient->orig_addr && *recipient->orig_addr
 113         && strcasecmp(recipient->address, recipient->orig_addr) != 0)
 114         vstring_sprintf_append(buf, ", orig_to=<%s>", recipient->orig_addr);
 115     vstring_sprintf_append(buf, ", relay=%s", relay);
 116     if (stats->reuse_count > 0)
 117         vstring_sprintf_append(buf, ", conn_use=%d", stats->reuse_count + 1);
 118
 119     /*
 120      * Next, performance statistics.
 121      *
 122      * Use wall clock time to compute pdelay (before active queue latency) if
 123      * there is no time stamp for active queue entry. This happens when mail
 124      * is bounced by the cleanup server.
 125      *
 126      * Otherwise, use wall clock time to compute adelay (active queue latency)
 127      * if there is no time stamp for hand-off to delivery agent. This happens
 128      * when mail was deferred or bounced by the queue manager.
 129      *
 130      * Otherwise, use wall clock time to compute xdelay (message transfer
 131      * latency) if there is no time stamp for delivery completion. In the
 132      * case of multi-recipient deliveries the delivery agent may specify the
 133      * delivery completion time, so that multiple recipient records show the
 134      * same delay values.
 135      *
 136      * Don't compute the sdelay (connection setup latency) if there is no time
 137      * stamp for connection setup completion.
 138      *
 139      * XXX Apparently, Solaris gettimeofday() can return out-of-range
 140      * microsecond values.
 141      */
 142 #define DELTA(x, y, z) \
 143     do { \
 144         (x).dt_sec = (y).tv_sec - (z).tv_sec; \
 145         (x).dt_usec = (y).tv_usec - (z).tv_usec; \
 146         while ((x).dt_usec < 0) { \
 147             (x).dt_usec += 1000000; \
 148             (x).dt_sec -= 1; \
 149         } \
 150         while ((x).dt_usec >= 1000000) { \
 151             (x).dt_usec -= 1000000; \
 152             (x).dt_sec += 1; \
 153         } \
 154         if ((x).dt_sec < 0) \
 155             (x).dt_sec = (x).dt_usec = 0; \
 156     } while (0)
 157
 158 #define DELTA_ZERO(x) ((x).dt_sec = (x).dt_usec = 0)
 159
 160 #define TIME_STAMPED(x) ((x).tv_sec > 0)
 161
 162     if (TIME_STAMPED(stats->deliver_done))
 163         now = stats->deliver_done;
 164     else
 165         GETTIMEOFDAY(&now);
 166
 167     DELTA(delay, now, stats->incoming_arrival);
 168     DELTA_ZERO(adelay);
 169     DELTA_ZERO(sdelay);
 170     DELTA_ZERO(xdelay);
 171     if (TIME_STAMPED(stats->active_arrival)) {
 172         DELTA(pdelay, stats->active_arrival, stats->incoming_arrival);
 173         if (TIME_STAMPED(stats->agent_handoff)) {
 174             DELTA(adelay, stats->agent_handoff, stats->active_arrival);
 175             if (TIME_STAMPED(stats->conn_setup_done)) {
 176                 DELTA(sdelay, stats->conn_setup_done, stats->agent_handoff);
 177                 DELTA(xdelay, now, stats->conn_setup_done);
 178             } else {
 179                 /* No network client. */
 180                 DELTA(xdelay, now, stats->agent_handoff);
 181             }
 182         } else {
 183             /* No delivery agent. */
 184             DELTA(adelay, now, stats->active_arrival);
 185         }
 186     } else {
 187         /* No queue manager. */
 188         DELTA(pdelay, now, stats->incoming_arrival);
 189     }
 190
 191     /*
 192      * Round off large time values to an integral number of seconds, and
 193      * display small numbers with only two significant digits, as long as
 194      * they do not exceed the time resolution.
 195      */
 196 #define SIG_DIGS        2
 197 #define PRETTY_FORMAT(b, text, x) \
 198     do { \
 199         vstring_strcat((b), text); \
 200         format_tv((b), (x).dt_sec, (x).dt_usec, SIG_DIGS, var_delay_max_res); \
 201     } while (0)
 202
 203     PRETTY_FORMAT(buf, ", delay=", delay);
 204     PRETTY_FORMAT(buf, ", delays=", pdelay);
 205     PRETTY_FORMAT(buf, "/", adelay);
 206     PRETTY_FORMAT(buf, "/", sdelay);
 207     PRETTY_FORMAT(buf, "/", xdelay);
 208
 209     /*
 210      * Finally, the delivery status.
 211      */
 212     vstring_sprintf_append(buf, ", dsn=%s, status=%s (%s)",
 213                            dsn->status, status, dsn->reason);
 214
 215     /*
 216      * Ship it off.
 217      */
 218     msg_info("%s", vstring_str(buf));
 219 }