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