1 /* $NetBSD: log_adhoc.c,v 1.1.1.1 2009/06/23 10:08:46 tron Exp $ */ 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 */ 80 typedef 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 87 void 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