| | varnish-cache/bin/varnishtest/vtc_log.c |
0 |
|
/*- |
1 |
|
* Copyright (c) 2008-2011 Varnish Software AS |
2 |
|
* All rights reserved. |
3 |
|
* |
4 |
|
* Author: Poul-Henning Kamp <phk@phk.freebsd.dk> |
5 |
|
* |
6 |
|
* SPDX-License-Identifier: BSD-2-Clause |
7 |
|
* |
8 |
|
* Redistribution and use in source and binary forms, with or without |
9 |
|
* modification, are permitted provided that the following conditions |
10 |
|
* are met: |
11 |
|
* 1. Redistributions of source code must retain the above copyright |
12 |
|
* notice, this list of conditions and the following disclaimer. |
13 |
|
* 2. Redistributions in binary form must reproduce the above copyright |
14 |
|
* notice, this list of conditions and the following disclaimer in the |
15 |
|
* documentation and/or other materials provided with the distribution. |
16 |
|
* |
17 |
|
* THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND |
18 |
|
* ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE |
19 |
|
* IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE |
20 |
|
* ARE DISCLAIMED. IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE |
21 |
|
* FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL |
22 |
|
* DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS |
23 |
|
* OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) |
24 |
|
* HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT |
25 |
|
* LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY |
26 |
|
* OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF |
27 |
|
* SUCH DAMAGE. |
28 |
|
*/ |
29 |
|
|
30 |
|
#include "config.h" |
31 |
|
|
32 |
|
#include <math.h> |
33 |
|
#include <stdarg.h> |
34 |
|
#include <stdio.h> |
35 |
|
#include <stdlib.h> |
36 |
|
#include <string.h> |
37 |
|
|
38 |
|
#include "vtc.h" |
39 |
|
#include "vtc_log.h" |
40 |
|
|
41 |
|
#include "vtim.h" |
42 |
|
|
43 |
|
static pthread_mutex_t vtclog_mtx; |
44 |
|
static char *vtclog_buf; |
45 |
|
static unsigned vtclog_left; |
46 |
|
|
47 |
|
static pthread_key_t log_key; |
48 |
|
static double t0; |
49 |
|
|
50 |
|
void |
51 |
134477 |
vtc_log_set_cmd(struct vtclog *vl, const struct cmds *cmds) |
52 |
|
{ |
53 |
134477 |
AN(cmds); |
54 |
134477 |
vl->cmds = cmds; |
55 |
134477 |
} |
56 |
|
|
57 |
|
/**********************************************************************/ |
58 |
|
|
59 |
|
#define GET_VL(vl) \ |
60 |
|
do { \ |
61 |
|
CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC); \ |
62 |
|
PTOK(pthread_mutex_lock(&vl->mtx)); \ |
63 |
|
vl->act = 1; \ |
64 |
|
VSB_clear(vl->vsb); \ |
65 |
|
} while(0) |
66 |
|
|
67 |
|
#define REL_VL(vl) \ |
68 |
|
do { \ |
69 |
|
AZ(VSB_finish(vl->vsb)); \ |
70 |
|
vtc_log_emit(vl); \ |
71 |
|
VSB_clear(vl->vsb); \ |
72 |
|
vl->act = 0; \ |
73 |
|
PTOK(pthread_mutex_unlock(&vl->mtx)); \ |
74 |
|
} while(0) |
75 |
|
|
76 |
|
|
77 |
|
struct vtclog * |
78 |
189401 |
vtc_logopen(const char *fmt, ...) |
79 |
|
{ |
80 |
|
struct vtclog *vl; |
81 |
|
va_list ap; |
82 |
|
char buf[BUFSIZ]; |
83 |
|
|
84 |
189401 |
va_start(ap, fmt); |
85 |
189401 |
vbprintf(buf, fmt, ap); |
86 |
189401 |
va_end(ap); |
87 |
|
|
88 |
189401 |
ALLOC_OBJ(vl, VTCLOG_MAGIC); |
89 |
189397 |
AN(vl); |
90 |
189397 |
REPLACE(vl->id, buf); |
91 |
189397 |
vl->vsb = VSB_new_auto(); |
92 |
189397 |
PTOK(pthread_mutex_init(&vl->mtx, NULL)); |
93 |
189397 |
PTOK(pthread_setspecific(log_key, vl)); |
94 |
189397 |
return (vl); |
95 |
|
} |
96 |
|
|
97 |
|
void |
98 |
164948 |
vtc_logclose(void *arg) |
99 |
|
{ |
100 |
|
struct vtclog *vl; |
101 |
|
|
102 |
164948 |
CAST_OBJ_NOTNULL(vl, arg, VTCLOG_MAGIC); |
103 |
164948 |
if (pthread_getspecific(log_key) == vl) |
104 |
94702 |
PTOK(pthread_setspecific(log_key, NULL)); |
105 |
164948 |
VSB_destroy(&vl->vsb); |
106 |
164948 |
PTOK(pthread_mutex_destroy(&vl->mtx)); |
107 |
164948 |
REPLACE(vl->id, NULL); |
108 |
164948 |
FREE_OBJ(vl); |
109 |
164948 |
} |
110 |
|
|
111 |
|
static void v_noreturn_ |
112 |
50 |
vtc_logfail(void) |
113 |
|
{ |
114 |
|
|
115 |
50 |
vtc_error = 2; |
116 |
50 |
if (!pthread_equal(pthread_self(), vtc_thread)) |
117 |
0 |
pthread_exit(NULL); |
118 |
|
else |
119 |
50 |
exit(fail_out()); |
120 |
|
} |
121 |
|
|
122 |
|
static const char * const lead[] = { |
123 |
|
"----", |
124 |
|
"* ", |
125 |
|
"** ", |
126 |
|
"*** ", |
127 |
|
"****" |
128 |
|
}; |
129 |
|
|
130 |
|
#define NLEAD (sizeof(lead)/sizeof(lead[0])) |
131 |
|
|
132 |
|
static void |
133 |
10666908 |
vtc_leadinv(const struct vtclog *vl, int lvl, const char *fmt, va_list ap) |
134 |
|
{ |
135 |
|
|
136 |
10666908 |
assert(lvl < (int)NLEAD); |
137 |
10666908 |
assert(lvl >= 0); |
138 |
21333816 |
VSB_printf(vl->vsb, "%s %-5s ", |
139 |
10666908 |
lead[lvl < 0 ? 1: lvl], vl->id); |
140 |
10666908 |
if (fmt != NULL) |
141 |
10667007 |
(void)VSB_vprintf(vl->vsb, fmt, ap); |
142 |
10667150 |
} |
143 |
|
|
144 |
|
static void |
145 |
16833 |
vtc_leadin(const struct vtclog *vl, int lvl, const char *fmt, ...) |
146 |
|
{ |
147 |
|
va_list ap; |
148 |
|
|
149 |
16833 |
va_start(ap, fmt); |
150 |
16833 |
vtc_leadinv(vl, lvl, fmt, ap); |
151 |
16833 |
va_end(ap); |
152 |
16833 |
} |
153 |
|
|
154 |
|
static void |
155 |
13481988 |
vtc_log_emit(const struct vtclog *vl) |
156 |
|
{ |
157 |
|
unsigned l; |
158 |
|
int i; |
159 |
|
int t_this; |
160 |
|
static int t_last = -1; |
161 |
|
|
162 |
13481988 |
l = VSB_len(vl->vsb); |
163 |
13481988 |
if (l == 0) |
164 |
163003 |
return; |
165 |
13318985 |
t_this = (int)round((VTIM_mono() - t0) * 1000); |
166 |
13318985 |
PTOK(pthread_mutex_lock(&vtclog_mtx)); |
167 |
13318985 |
if (t_last != t_this) { |
168 |
979217 |
assert(vtclog_left > 25); |
169 |
1958434 |
i = snprintf(vtclog_buf, vtclog_left, |
170 |
979217 |
"**** dT %d.%03d\n", t_this / 1000, t_this % 1000); |
171 |
979217 |
t_last = t_this; |
172 |
979217 |
vtclog_buf += i; |
173 |
979217 |
vtclog_left -= i; |
174 |
979217 |
} |
175 |
13318985 |
assert(vtclog_left > l); |
176 |
13318985 |
memcpy(vtclog_buf, VSB_data(vl->vsb), l); |
177 |
13318985 |
vtclog_buf += l; |
178 |
13318985 |
*vtclog_buf = '\0'; |
179 |
13318985 |
vtclog_left -= l; |
180 |
13318985 |
PTOK(pthread_mutex_unlock(&vtclog_mtx)); |
181 |
13481988 |
} |
182 |
|
|
183 |
|
void |
184 |
50 |
vtc_fatal(struct vtclog *vl, const char *fmt, ...) |
185 |
|
{ |
186 |
|
|
187 |
50 |
GET_VL(vl); |
188 |
|
va_list ap; |
189 |
50 |
va_start(ap, fmt); |
190 |
50 |
vtc_leadinv(vl, 0, fmt, ap); |
191 |
50 |
VSB_putc(vl->vsb, '\n'); |
192 |
50 |
va_end(ap); |
193 |
50 |
REL_VL(vl); |
194 |
|
|
195 |
50 |
vtc_logfail(); |
196 |
|
} |
197 |
|
|
198 |
|
void |
199 |
10657783 |
vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...) |
200 |
|
{ |
201 |
|
|
202 |
10657783 |
GET_VL(vl); |
203 |
|
va_list ap; |
204 |
10657783 |
va_start(ap, fmt); |
205 |
10657783 |
if (lvl >= 0) { |
206 |
10650064 |
vtc_leadinv(vl, lvl, fmt, ap); |
207 |
10650064 |
VSB_putc(vl->vsb, '\n'); |
208 |
10650064 |
} |
209 |
10657783 |
va_end(ap); |
210 |
10657783 |
REL_VL(vl); |
211 |
|
|
212 |
10657783 |
if (lvl == 0) |
213 |
0 |
vtc_logfail(); |
214 |
10657783 |
} |
215 |
|
|
216 |
|
/********************************************************************** |
217 |
|
* Dump a string |
218 |
|
*/ |
219 |
|
|
220 |
|
#define MAX_DUMP 8192 |
221 |
|
|
222 |
|
void |
223 |
2813766 |
vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len) |
224 |
|
{ |
225 |
|
char buf[64]; |
226 |
2813766 |
int quote = VSB_QUOTE_UNSAFE | VSB_QUOTE_ESCHEX; |
227 |
|
|
228 |
2813766 |
AN(pfx); |
229 |
2813766 |
GET_VL(vl); |
230 |
2813766 |
if (str == NULL) |
231 |
25 |
vtc_leadin(vl, lvl, "%s(null)\n", pfx); |
232 |
|
else { |
233 |
2813741 |
bprintf(buf, "%s %-5s %s|", |
234 |
|
lead[lvl < 0 ? 1: lvl], vl->id, pfx); |
235 |
2813741 |
if (len < 0) |
236 |
2268118 |
len = strlen(str); |
237 |
545623 |
else if (str[0] == 0x1f && (uint8_t)str[1] == 0x8b) |
238 |
6350 |
quote = VSB_QUOTE_HEX; // Dump gzip data in HEX |
239 |
5627482 |
VSB_quote_pfx(vl->vsb, buf, str, |
240 |
2813741 |
len > MAX_DUMP ? MAX_DUMP : len, quote); |
241 |
2813741 |
if (quote == VSB_QUOTE_HEX) |
242 |
6350 |
VSB_putc(vl->vsb, '\n'); |
243 |
2813741 |
if (len > MAX_DUMP) |
244 |
9226 |
VSB_printf(vl->vsb, "%s [...] (%d)\n", |
245 |
4613 |
buf, len - MAX_DUMP); |
246 |
|
} |
247 |
2813766 |
REL_VL(vl); |
248 |
2813766 |
if (lvl == 0) |
249 |
0 |
vtc_logfail(); |
250 |
2813766 |
} |
251 |
|
|
252 |
|
/********************************************************************** |
253 |
|
* Hexdump |
254 |
|
*/ |
255 |
|
|
256 |
|
void |
257 |
9861 |
vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx, |
258 |
|
const void *ptr, unsigned len) |
259 |
|
{ |
260 |
9861 |
int nl = 1; |
261 |
|
unsigned l; |
262 |
9861 |
const uint8_t *ss = ptr; |
263 |
|
|
264 |
9861 |
AN(pfx); |
265 |
9861 |
GET_VL(vl); |
266 |
9861 |
if (ss == NULL) |
267 |
0 |
vtc_leadin(vl, lvl, "%s(null)\n", pfx); |
268 |
|
else { |
269 |
173651 |
for (l = 0; l < len; l++, ss++) { |
270 |
163835 |
if (l > 512) { |
271 |
45 |
VSB_cat(vl->vsb, "..."); |
272 |
45 |
break; |
273 |
|
} |
274 |
163790 |
if (nl) { |
275 |
16808 |
vtc_leadin(vl, lvl, "%s| ", pfx); |
276 |
16808 |
nl = 0; |
277 |
16808 |
} |
278 |
163790 |
VSB_printf(vl->vsb, " %02x", *ss); |
279 |
163790 |
if ((l & 0xf) == 0xf) { |
280 |
8217 |
VSB_cat(vl->vsb, "\n"); |
281 |
8217 |
nl = 1; |
282 |
8217 |
} |
283 |
163790 |
} |
284 |
|
} |
285 |
9861 |
if (!nl) |
286 |
8591 |
VSB_cat(vl->vsb, "\n"); |
287 |
9861 |
REL_VL(vl); |
288 |
9861 |
if (lvl == 0) |
289 |
0 |
vtc_logfail(); |
290 |
9861 |
} |
291 |
|
|
292 |
|
/**********************************************************************/ |
293 |
|
|
294 |
|
static void v_noreturn_ |
295 |
0 |
vtc_log_VAS_Fail(const char *func, const char *file, int line, |
296 |
|
const char *cond, enum vas_e why) |
297 |
|
{ |
298 |
|
struct vtclog *vl; |
299 |
0 |
int e = errno; |
300 |
|
|
301 |
0 |
(void)why; |
302 |
0 |
vl = pthread_getspecific(log_key); |
303 |
0 |
if (vl == NULL || vl->act) { |
304 |
0 |
fprintf(stderr, |
305 |
|
"Assert error in %s(), %s line %d:\n" |
306 |
|
" Condition(%s) not true. (errno=%d %s)\n", |
307 |
0 |
func, file, line, cond, e, strerror(e)); |
308 |
0 |
} else |
309 |
0 |
vtc_fatal(vl, "Assert error in %s(), %s line %d:" |
310 |
|
" Condition(%s) not true." |
311 |
0 |
" Errno=%d %s", func, file, line, cond, e, strerror(e)); |
312 |
0 |
abort(); |
313 |
|
} |
314 |
|
|
315 |
|
/**********************************************************************/ |
316 |
|
|
317 |
|
void |
318 |
24425 |
vtc_loginit(char *buf, unsigned buflen) |
319 |
|
{ |
320 |
|
|
321 |
24425 |
VAS_Fail_Func = vtc_log_VAS_Fail; |
322 |
24425 |
t0 = VTIM_mono(); |
323 |
24425 |
vtclog_buf = buf; |
324 |
24425 |
vtclog_left = buflen; |
325 |
24425 |
PTOK(pthread_mutex_init(&vtclog_mtx, NULL)); |
326 |
24425 |
PTOK(pthread_key_create(&log_key, NULL)); |
327 |
24425 |
} |