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 */ 80typedef 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 87void 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} 220