diff options
Diffstat (limited to 'src/global/log_adhoc.c')
| -rw-r--r-- | src/global/log_adhoc.c | 221 |
1 files changed, 221 insertions, 0 deletions
diff --git a/src/global/log_adhoc.c b/src/global/log_adhoc.c new file mode 100644 index 0000000..e00e930 --- /dev/null +++ b/src/global/log_adhoc.c @@ -0,0 +1,221 @@ +/*++ +/* 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). 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 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 +/*--*/ + +/* 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> + + /* + * 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, + 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. + */ +#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)); +} |