1/*++ 2/* NAME 3/* log_adhoc 3 4/* SUMMARY 5/* ad-hoc delivery event logging 6/* SYNOPSIS 7/* #include <log_adhoc.h> 8/* 9/* void log_adhoc(id, stats, recipient, relay, dsn, status) 10/* const char *id; 11/* MSG_STATS *stats; 12/* RECIPIENT *recipient; 13/* const char *relay; 14/* DSN *dsn; 15/* const char *status; 16/* DESCRIPTION 17/* This module logs delivery events in an ad-hoc manner. 18/* 19/* log_adhoc() appends a record to the mail logfile 20/* 21/* Arguments: 22/* .IP queue 23/* The message queue name of the original message file. 24/* .IP id 25/* The queue id of the original message file. 26/* .IP stats 27/* Time stamps from different message delivery stages 28/* and session reuse count. 29/* .IP recipient 30/* Recipient information. See recipient_list(3). 31/* .IP sender 32/* The sender envelope address. 33/* .IP relay 34/* Host we could (not) talk to. 35/* .IP status 36/* bounced, deferred, sent, and so on. 37/* .IP dsn 38/* Delivery status information. See dsn(3). 39/* BUGS 40/* Should be replaced by routines with an attribute-value based 41/* interface instead of an interface that uses a rigid argument list. 42/* LICENSE 43/* .ad 44/* .fi 45/* The Secure Mailer license must be distributed with this software. 46/* AUTHOR(S) 47/* Wietse Venema 48/* IBM T.J. Watson Research 49/* P.O. Box 704 50/* Yorktown Heights, NY 10598, USA 51/*--*/ 52 53/* System library. */ 54 55#include <sys_defs.h> 56#include <string.h> 57 58#ifdef STRCASECMP_IN_STRINGS_H 59#include <strings.h> 60#endif 61 62/* Utility library. */ 63 64#include <msg.h> 65#include <vstring.h> 66#include <format_tv.h> 67 68/* Global library. */ 69 70#include <log_adhoc.h> 71#include <mail_params.h> 72 73 /* 74 * Don't use "struct timeval" for time differences; use explicit signed 75 * types instead. The code below relies on signed values to detect clocks 76 * jumping back. 77 */ 78typedef struct { 79 int dt_sec; /* make sure it's signed */ 80 int dt_usec; /* make sure it's signed */ 81} DELTA_TIME; 82 83/* log_adhoc - ad-hoc logging */ 84 85void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, 86 const char *relay, DSN *dsn, 87 const char *status) 88{ 89 static VSTRING *buf; 90 DELTA_TIME delay; /* end-to-end delay */ 91 DELTA_TIME pdelay; /* time before queue manager */ 92 DELTA_TIME adelay; /* queue manager latency */ 93 DELTA_TIME sdelay; /* connection set-up latency */ 94 DELTA_TIME xdelay; /* transmission latency */ 95 struct timeval now; 96 97 /* 98 * Alas, we need an intermediate buffer for the pre-formatted result. 99 * There are several optional fields, and the delay fields are formatted 100 * in a manner that is not supported by vstring_sprintf(). 101 */ 102 if (buf == 0) 103 buf = vstring_alloc(100); 104 105 /* 106 * First, critical information that identifies the nature of the 107 * transaction. 108 */ 109 vstring_sprintf(buf, "%s: to=<%s>", id, recipient->address); 110 if (recipient->orig_addr && *recipient->orig_addr 111 && strcasecmp(recipient->address, recipient->orig_addr) != 0) 112 vstring_sprintf_append(buf, ", orig_to=<%s>", recipient->orig_addr); 113 vstring_sprintf_append(buf, ", relay=%s", relay); 114 if (stats->reuse_count > 0) 115 vstring_sprintf_append(buf, ", conn_use=%d", stats->reuse_count + 1); 116 117 /* 118 * Next, performance statistics. 119 * 120 * Use wall clock time to compute pdelay (before active queue latency) if 121 * there is no time stamp for active queue entry. This happens when mail 122 * is bounced by the cleanup server. 123 * 124 * Otherwise, use wall clock time to compute adelay (active queue latency) 125 * if there is no time stamp for hand-off to delivery agent. This happens 126 * when mail was deferred or bounced by the queue manager. 127 * 128 * Otherwise, use wall clock time to compute xdelay (message transfer 129 * latency) if there is no time stamp for delivery completion. In the 130 * case of multi-recipient deliveries the delivery agent may specify the 131 * delivery completion time, so that multiple recipient records show the 132 * same delay values. 133 * 134 * Don't compute the sdelay (connection setup latency) if there is no time 135 * stamp for connection setup completion. 136 * 137 * XXX Apparently, Solaris gettimeofday() can return out-of-range 138 * microsecond values. 139 */ 140#define DELTA(x, y, z) \ 141 do { \ 142 (x).dt_sec = (y).tv_sec - (z).tv_sec; \ 143 (x).dt_usec = (y).tv_usec - (z).tv_usec; \ 144 while ((x).dt_usec < 0) { \ 145 (x).dt_usec += 1000000; \ 146 (x).dt_sec -= 1; \ 147 } \ 148 while ((x).dt_usec >= 1000000) { \ 149 (x).dt_usec -= 1000000; \ 150 (x).dt_sec += 1; \ 151 } \ 152 if ((x).dt_sec < 0) \ 153 (x).dt_sec = (x).dt_usec = 0; \ 154 } while (0) 155 156#define DELTA_ZERO(x) ((x).dt_sec = (x).dt_usec = 0) 157 158#define TIME_STAMPED(x) ((x).tv_sec > 0) 159 160 if (TIME_STAMPED(stats->deliver_done)) 161 now = stats->deliver_done; 162 else 163 GETTIMEOFDAY(&now); 164 165 DELTA(delay, now, stats->incoming_arrival); 166 DELTA_ZERO(adelay); 167 DELTA_ZERO(sdelay); 168 DELTA_ZERO(xdelay); 169 if (TIME_STAMPED(stats->active_arrival)) { 170 DELTA(pdelay, stats->active_arrival, stats->incoming_arrival); 171 if (TIME_STAMPED(stats->agent_handoff)) { 172 DELTA(adelay, stats->agent_handoff, stats->active_arrival); 173 if (TIME_STAMPED(stats->conn_setup_done)) { 174 DELTA(sdelay, stats->conn_setup_done, stats->agent_handoff); 175 DELTA(xdelay, now, stats->conn_setup_done); 176 } else { 177 /* No network client. */ 178 DELTA(xdelay, now, stats->agent_handoff); 179 } 180 } else { 181 /* No delivery agent. */ 182 DELTA(adelay, now, stats->active_arrival); 183 } 184 } else { 185 /* No queue manager. */ 186 DELTA(pdelay, now, stats->incoming_arrival); 187 } 188 189 /* 190 * Round off large time values to an integral number of seconds, and 191 * display small numbers with only two significant digits, as long as 192 * they do not exceed the time resolution. 193 */ 194#define SIG_DIGS 2 195#define PRETTY_FORMAT(b, text, x) \ 196 do { \ 197 vstring_strcat((b), text); \ 198 format_tv((b), (x).dt_sec, (x).dt_usec, SIG_DIGS, var_delay_max_res); \ 199 } while (0) 200 201 PRETTY_FORMAT(buf, ", delay=", delay); 202 PRETTY_FORMAT(buf, ", delays=", pdelay); 203 PRETTY_FORMAT(buf, "/", adelay); 204 PRETTY_FORMAT(buf, "/", sdelay); 205 PRETTY_FORMAT(buf, "/", xdelay); 206 207 /* 208 * Finally, the delivery status. 209 */ 210 vstring_sprintf_append(buf, ", dsn=%s, status=%s (%s)", 211 dsn->status, status, dsn->reason); 212 213 /* 214 * Ship it off. 215 */ 216 msg_info("%s", vstring_str(buf)); 217} 218