1 /* $NetBSD: log_adhoc.c,v 1.2 2017/02/14 01:16:45 christos 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 /* Utility library. */ 61 62 #include <msg.h> 63 #include <vstring.h> 64 #include <format_tv.h> 65 #include <stringops.h> 66 67 /* Global library. */ 68 69 #include <log_adhoc.h> 70 #include <mail_params.h> 71 72 /* 73 * Don't use "struct timeval" for time differences; use explicit signed 74 * types instead. The code below relies on signed values to detect clocks 75 * jumping back. 76 */ 77 typedef struct { 78 long dt_sec; /* make sure it's signed */ 79 long dt_usec; /* make sure it's signed */ 80 } DELTA_TIME; 81 82 /* log_adhoc - ad-hoc logging */ 83 84 void log_adhoc(const char *id, MSG_STATS *stats, RECIPIENT *recipient, 85 const char *relay, DSN *dsn, 86 const char *status) 87 { 88 static VSTRING *buf; 89 DELTA_TIME delay; /* end-to-end delay */ 90 DELTA_TIME pdelay; /* time before queue manager */ 91 DELTA_TIME adelay; /* queue manager latency */ 92 DELTA_TIME sdelay; /* connection set-up latency */ 93 DELTA_TIME xdelay; /* transmission latency */ 94 struct timeval now; 95 96 /* 97 * Alas, we need an intermediate buffer for the pre-formatted result. 98 * There are several optional fields, and the delay fields are formatted 99 * in a manner that is not supported by vstring_sprintf(). 100 */ 101 if (buf == 0) 102 buf = vstring_alloc(100); 103 104 /* 105 * First, critical information that identifies the nature of the 106 * transaction. 107 */ 108 vstring_sprintf(buf, "%s: to=<%s>", id, recipient->address); 109 if (recipient->orig_addr && *recipient->orig_addr 110 && strcasecmp_utf8(recipient->address, recipient->orig_addr) != 0) 111 vstring_sprintf_append(buf, ", orig_to=<%s>", recipient->orig_addr); 112 vstring_sprintf_append(buf, ", relay=%s", relay); 113 if (stats->reuse_count > 0) 114 vstring_sprintf_append(buf, ", conn_use=%d", stats->reuse_count + 1); 115 116 /* 117 * Next, performance statistics. 118 * 119 * Use wall clock time to compute pdelay (before active queue latency) if 120 * there is no time stamp for active queue entry. This happens when mail 121 * is bounced by the cleanup server. 122 * 123 * Otherwise, use wall clock time to compute adelay (active queue latency) 124 * if there is no time stamp for hand-off to delivery agent. This happens 125 * when mail was deferred or bounced by the queue manager. 126 * 127 * Otherwise, use wall clock time to compute xdelay (message transfer 128 * latency) if there is no time stamp for delivery completion. In the 129 * case of multi-recipient deliveries the delivery agent may specify the 130 * delivery completion time, so that multiple recipient records show the 131 * same delay values. 132 * 133 * Don't compute the sdelay (connection setup latency) if there is no time 134 * stamp for connection setup completion. 135 * 136 * XXX Apparently, Solaris gettimeofday() can return out-of-range 137 * microsecond values. 138 */ 139 #define DELTA(x, y, z) \ 140 do { \ 141 (x).dt_sec = (y).tv_sec - (z).tv_sec; \ 142 (x).dt_usec = (y).tv_usec - (z).tv_usec; \ 143 while ((x).dt_usec < 0) { \ 144 (x).dt_usec += 1000000; \ 145 (x).dt_sec -= 1; \ 146 } \ 147 while ((x).dt_usec >= 1000000) { \ 148 (x).dt_usec -= 1000000; \ 149 (x).dt_sec += 1; \ 150 } \ 151 if ((x).dt_sec < 0) \ 152 (x).dt_sec = (x).dt_usec = 0; \ 153 } while (0) 154 155 #define DELTA_ZERO(x) ((x).dt_sec = (x).dt_usec = 0) 156 157 #define TIME_STAMPED(x) ((x).tv_sec > 0) 158 159 if (TIME_STAMPED(stats->deliver_done)) 160 now = stats->deliver_done; 161 else 162 GETTIMEOFDAY(&now); 163 164 DELTA(delay, now, stats->incoming_arrival); 165 DELTA_ZERO(adelay); 166 DELTA_ZERO(sdelay); 167 DELTA_ZERO(xdelay); 168 if (TIME_STAMPED(stats->active_arrival)) { 169 DELTA(pdelay, stats->active_arrival, stats->incoming_arrival); 170 if (TIME_STAMPED(stats->agent_handoff)) { 171 DELTA(adelay, stats->agent_handoff, stats->active_arrival); 172 if (TIME_STAMPED(stats->conn_setup_done)) { 173 DELTA(sdelay, stats->conn_setup_done, stats->agent_handoff); 174 DELTA(xdelay, now, stats->conn_setup_done); 175 } else { 176 /* No network client. */ 177 DELTA(xdelay, now, stats->agent_handoff); 178 } 179 } else { 180 /* No delivery agent. */ 181 DELTA(adelay, now, stats->active_arrival); 182 } 183 } else { 184 /* No queue manager. */ 185 DELTA(pdelay, now, stats->incoming_arrival); 186 } 187 188 /* 189 * Round off large time values to an integral number of seconds, and 190 * display small numbers with only two significant digits, as long as 191 * they do not exceed the time resolution. 192 */ 193 #define SIG_DIGS 2 194 #define PRETTY_FORMAT(b, text, x) \ 195 do { \ 196 vstring_strcat((b), text); \ 197 format_tv((b), (x).dt_sec, (x).dt_usec, SIG_DIGS, var_delay_max_res); \ 198 } while (0) 199 200 PRETTY_FORMAT(buf, ", delay=", delay); 201 PRETTY_FORMAT(buf, ", delays=", pdelay); 202 PRETTY_FORMAT(buf, "/", adelay); 203 PRETTY_FORMAT(buf, "/", sdelay); 204 PRETTY_FORMAT(buf, "/", xdelay); 205 206 /* 207 * Finally, the delivery status. 208 */ 209 vstring_sprintf_append(buf, ", dsn=%s, status=%s (%s)", 210 dsn->status, status, dsn->reason); 211 212 /* 213 * Ship it off. 214 */ 215 msg_info("%s", vstring_str(buf)); 216 } 217