/* $NetBSD: log_adhoc.c,v 1.3 2020/03/18 19:05:16 christos Exp $ */
/*++
/* 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));
}