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