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
log_adhoc(const char * id,MSG_STATS * stats,RECIPIENT * recipient,const char * relay,DSN * dsn,const char * status)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