log_adhoc.c

[詳解]

/*++
/* NAME
/*  log_adhoc 3
/* SUMMARY
/*  ad-hoc delivery event logging
/* SYNOPSIS
/*  #include <log_adhoc.h>
/*
/*  void    log_adhoc(id, stats, recipient, relay, dsn, status)
/*  const char *id;
/*  MSG_STATS *stats;
/*  RECIPIENT *recipient;
/*  const char *relay;
/*  DSN *dsn;
/*  const char *status;
/* DESCRIPTION
/*  This module logs delivery events in an ad-hoc manner.
/*
/*  log_adhoc() appends a record to the mail logfile
/*
/*  Arguments:
/* .IP queue
/*  The message queue name of the original message file.
/* .IP id
/*  The queue id of the original message file.
/* .IP stats
/*  Time stamps from different message delivery stages
/*  and session reuse count.
/* .IP recipient
/*  Recipient information. See recipient_list(3).
/* .IP sender
/*  The sender envelope address.
/* .IP relay
/*  Host we could (not) talk to.
/* .IP status
/*  bounced, deferred, sent, and so on.
/* .IP dsn
/*  Delivery status information. See dsn(3).
/* BUGS
/*  Should be replaced by routines with an attribute-value based
/*  interface instead of an interface that uses a rigid argument list.
/* LICENSE
/* .ad
/* .fi
/*  The Secure Mailer license must be distributed with this software.
/* AUTHOR(S)
/*  Wietse Venema
/*  IBM T.J. Watson Research
/*  P.O. Box 704
/*  Yorktown Heights, NY 10598, USA
/*--*/

/* System library. */

#include <sys_defs.h>
#include <string.h>

/* Utility library. */

#include <msg.h>
#include <vstring.h>
#include <format_tv.h>
#include <stringops.h>

/* Global library. */

#include <log_adhoc.h>
#include <mail_params.h>

 /*
  * Don't use "struct timeval" for time differences; use explicit signed
  * types instead. The code below relies on signed values to detect clocks
  * jumping back.
  */
typedef struct {
    long    dt_sec;         /* make sure it's signed */
    long    dt_usec;            /* make sure it's signed */
} DELTA_TIME;

/* log_adhoc - ad-hoc logging */

void    log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient,
                  const char *relay, DSN *dsn,
                  const char *status)
{
    static VSTRING *buf;
    DELTA_TIME delay;           /* end-to-end delay */
    DELTA_TIME pdelay;          /* time before queue manager */
    DELTA_TIME adelay;          /* queue manager latency */
    DELTA_TIME sdelay;          /* connection set-up latency */
    DELTA_TIME xdelay;          /* transmission latency */
    struct timeval now;

    /*
     * Alas, we need an intermediate buffer for the pre-formatted result.
     * There are several optional fields, and the delay fields are formatted
     * in a manner that is not supported by vstring_sprintf().
     */
    if (buf == 0)
    buf = vstring_alloc(100);

    /*
     * First, critical information that identifies the nature of the
     * transaction.
     */
    vstring_sprintf(buf, "%s: to=<%s>", id, recipient->address);
    if (recipient->orig_addr && *recipient->orig_addr
    && strcasecmp_utf8(recipient->address, recipient->orig_addr) != 0)
    vstring_sprintf_append(buf, ", orig_to=<%s>", recipient->orig_addr);
    vstring_sprintf_append(buf, ", relay=%s", relay);
    if (stats->reuse_count > 0)
    vstring_sprintf_append(buf, ", conn_use=%d", stats->reuse_count + 1);

    /*
     * Next, performance statistics.
     * 
     * Use wall clock time to compute pdelay (before active queue latency) if
     * there is no time stamp for active queue entry. This happens when mail
     * is bounced by the cleanup server.
     * 
     * Otherwise, use wall clock time to compute adelay (active queue latency)
     * if there is no time stamp for hand-off to delivery agent. This happens
     * when mail was deferred or bounced by the queue manager.
     * 
     * Otherwise, use wall clock time to compute xdelay (message transfer
     * latency) if there is no time stamp for delivery completion. In the
     * case of multi-recipient deliveries the delivery agent may specify the
     * delivery completion time, so that multiple recipient records show the
     * same delay values.
     * 
     * Don't compute the sdelay (connection setup latency) if there is no time
     * stamp for connection setup completion.
     * 
     * XXX Apparently, Solaris gettimeofday() can return out-of-range
     * microsecond values.
     */
#define DELTA(x, y, z) \
    do { \
    (x).dt_sec = (y).tv_sec - (z).tv_sec; \
    (x).dt_usec = (y).tv_usec - (z).tv_usec; \
    while ((x).dt_usec < 0) { \
        (x).dt_usec += 1000000; \
        (x).dt_sec -= 1; \
    } \
    while ((x).dt_usec >= 1000000) { \
        (x).dt_usec -= 1000000; \
        (x).dt_sec += 1; \
    } \
    if ((x).dt_sec < 0) \
        (x).dt_sec = (x).dt_usec = 0; \
    } while (0)

#define DELTA_ZERO(x) ((x).dt_sec = (x).dt_usec = 0)

#define TIME_STAMPED(x) ((x).tv_sec > 0)

    if (TIME_STAMPED(stats->deliver_done))
    now = stats->deliver_done;
    else
    GETTIMEOFDAY(&now);

    DELTA(delay, now, stats->incoming_arrival);
    DELTA_ZERO(adelay);
    DELTA_ZERO(sdelay);
    DELTA_ZERO(xdelay);
    if (TIME_STAMPED(stats->active_arrival)) {
    DELTA(pdelay, stats->active_arrival, stats->incoming_arrival);
    if (TIME_STAMPED(stats->agent_handoff)) {
        DELTA(adelay, stats->agent_handoff, stats->active_arrival);
        if (TIME_STAMPED(stats->conn_setup_done)) {
        DELTA(sdelay, stats->conn_setup_done, stats->agent_handoff);
        DELTA(xdelay, now, stats->conn_setup_done);
        } else {
        /* No network client. */
        DELTA(xdelay, now, stats->agent_handoff);
        }
    } else {
        /* No delivery agent. */
        DELTA(adelay, now, stats->active_arrival);
    }
    } else {
    /* No queue manager. */
    DELTA(pdelay, now, stats->incoming_arrival);
    }

    /*
     * Round off large time values to an integral number of seconds, and
     * display small numbers with only two significant digits, as long as
     * they do not exceed the time resolution.
     */
#define SIG_DIGS    2
#define PRETTY_FORMAT(b, text, x) \
    do { \
    vstring_strcat((b), text); \
    format_tv((b), (x).dt_sec, (x).dt_usec, SIG_DIGS, var_delay_max_res); \
    } while (0)

    PRETTY_FORMAT(buf, ", delay=", delay);
    PRETTY_FORMAT(buf, ", delays=", pdelay);
    PRETTY_FORMAT(buf, "/", adelay);
    PRETTY_FORMAT(buf, "/", sdelay);
    PRETTY_FORMAT(buf, "/", xdelay);

    /*
     * Finally, the delivery status.
     */
    vstring_sprintf_append(buf, ", dsn=%s, status=%s (%s)",
               dsn->status, status, dsn->reason);

    /*
     * Ship it off.
     */
    msg_info("%s", vstring_str(buf));
}