Quelle  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, tstats, dsn, status)
/* const char *id;
/* MSG_STATS *stats;
/* RECIPIENT *recipient;
/* const char *relay;
/* const POL_STATS *tstats;
/* 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). The address
/* is formatted by the info_log_addr_form(3) routines.
/* .IP relay
/* Host we could (not) talk to.
/* .IP status
/* bounced, deferred, sent, and so on.
/* .IP tstats
/* TLS per-feature status.
/* .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
/*
/* Wietse Venema
/* Google, Inc.
/* 111 8th Avenue
/* New York, NY 10011, USA
/*
/* Wietse Venema
/* porcupine.org
/*--*/

/* 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>
#include <info_log_addr_form.h>
#include <pol_stats.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, const POL_STATS *tstats,
            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,
      info_log_addr_form_recipient(recipient->address));
    if (recipient->orig_addr && *recipient->orig_addr
 && strcasecmp_utf8(recipient->address, recipient->orig_addr) != 0)
 vstring_sprintf_append(buf, ", orig_to=<%s>",
   info_log_addr_form_recipient(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.
     * 
     * TODO(wietse) move this to msg_stats.c
     */
#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);

    /*
     * Optional: TLS per-feature status summary.
     */
#ifdef USE_TLS
    if (tstats && pol_stats_used(tstats)) {
 vstring_sprintf_append(buf, ", tls=");
 pol_stats_format(buf, tstats);
    }
#endif

    /*
     * 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));
}