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