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 137891
vtc_logopen(const char *id)
79
{
80
        struct vtclog *vl;
81
82 137891
        ALLOC_OBJ(vl, VTCLOG_MAGIC);
83 137899
        AN(vl);
84 137899
        vl->id = id;
85 137899
        vl->vsb = VSB_new_auto();
86 137899
        AZ(pthread_mutex_init(&vl->mtx, NULL));
87 137897
        AZ(pthread_setspecific(log_key, vl));
88 137902
        return (vl);
89
}
90
91
void
92 118678
vtc_logclose(void *arg)
93
{
94 118678
        struct vtclog *vl = arg;
95
96 118678
        CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);
97 118678
        if (pthread_getspecific(log_key) == vl)
98 74746
                AZ(pthread_setspecific(log_key, NULL));
99 118678
        VSB_destroy(&vl->vsb);
100 118678
        AZ(pthread_mutex_destroy(&vl->mtx));
101 118678
        FREE_OBJ(vl);
102 118677
}
103
104
static void v_noreturn_
105 48
vtc_logfail(void)
106
{
107
108 48
        vtc_error = 2;
109 48
        if (pthread_self() != vtc_thread)
110 0
                pthread_exit(NULL);
111
        else
112 48
                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 7474296
vtc_leadinv(const struct vtclog *vl, int lvl, const char *fmt, va_list ap)
127
{
128
129 7474296
        assert(lvl < (int)NLEAD);
130 7474405
        assert(lvl >= 0);
131 14948700
        VSB_printf(vl->vsb, "%s %-4s ",
132 7474295
            lead[lvl < 0 ? 1: lvl], vl->id);
133 7474405
        if (fmt != NULL)
134 7474244
                (void)VSB_vprintf(vl->vsb, fmt, ap);
135 7474323
}
136
137
static void
138 14595
vtc_leadin(const struct vtclog *vl, int lvl, const char *fmt, ...)
139
{
140
        va_list ap;
141
142 14595
        va_start(ap, fmt);
143 14595
        vtc_leadinv(vl, lvl, fmt, ap);
144 14595
        va_end(ap);
145 14595
}
146
147
static void
148 9572404
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 9572404
        l = VSB_len(vl->vsb);
156 9572404
        if (l == 0)
157 135324
                return;
158 9437240
        t_this = (int)round((VTIM_mono() - t0) * 1000);
159 9437240
        AZ(pthread_mutex_lock(&vtclog_mtx));
160 9437441
        if (t_last != t_this) {
161 974301
                assert(vtclog_left > 25);
162 1948602
                i = snprintf(vtclog_buf, vtclog_left,
163 974301
                    "**** dT   %d.%03d\n", t_this / 1000, t_this % 1000);
164 974301
                t_last = t_this;
165 974301
                vtclog_buf += i;
166 974301
                vtclog_left -= i;
167 974301
        }
168 9437441
        assert(vtclog_left > l);
169 9437441
        memcpy(vtclog_buf, VSB_data(vl->vsb), l);
170 9437441
        vtclog_buf += l;
171 9437441
        *vtclog_buf = '\0';
172 9437441
        vtclog_left -= l;
173 9437441
        AZ(pthread_mutex_unlock(&vtclog_mtx));
174 9572762
}
175
176
void
177 48
vtc_fatal(struct vtclog *vl, const char *fmt, ...)
178
{
179
180 48
        GET_VL(vl);
181
        va_list ap;
182 48
        va_start(ap, fmt);
183 48
        vtc_leadinv(vl, 0, fmt, ap);
184 48
        VSB_putc(vl->vsb, '\n');
185 48
        va_end(ap);
186 48
        REL_VL(vl);
187
188 48
        vtc_logfail();
189 0
}
190
191
void
192 7459937
vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
193
{
194
195 7459937
        GET_VL(vl);
196
        va_list ap;
197 7460195
        va_start(ap, fmt);
198 7460195
        if (lvl >= 0) {
199 7459678
                vtc_leadinv(vl, lvl, fmt, ap);
200 7459678
                VSB_putc(vl->vsb, '\n');
201 7459678
        }
202 7460137
        va_end(ap);
203 7460137
        REL_VL(vl);
204
205 7460359
        if (lvl == 0)
206 0
                vtc_logfail();
207 7460358
}
208
209
/**********************************************************************
210
 * Dump a string
211
 */
212
213
#define MAX_DUMP 8192
214
215
void
216 2103650
vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
217
{
218
        char buf[64];
219
220 2103650
        AN(pfx);
221 2103678
        GET_VL(vl);
222 2103713
        if (str == NULL)
223 24
                vtc_leadin(vl, lvl, "%s(null)\n", pfx);
224
        else {
225 2103691
                bprintf(buf, "%s %-4s %s|",
226
                    lead[lvl < 0 ? 1: lvl], vl->id, pfx);
227 2103682
                if (len < 0)
228 1684261
                        len = strlen(str);
229 4207437
                VSB_quote_pfx(vl->vsb, buf, str,
230 2103733
                    len > MAX_DUMP ? MAX_DUMP : len,
231
                    VSB_QUOTE_UNSAFE | VSB_QUOTE_ESCHEX);
232 2103704
                if (len > MAX_DUMP)
233 6944
                        VSB_printf(vl->vsb, "%s [...] (%d)\n",
234 3472
                            buf, len - MAX_DUMP);
235
        }
236 2103607
        REL_VL(vl);
237 2103753
        if (lvl == 0)
238 0
                vtc_logfail();
239 2103754
}
240
241
/**********************************************************************
242
 * Hexdump
243
 */
244
245
void
246 8589
vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
247
    const void *ptr, unsigned len)
248
{
249 8589
        int nl = 1;
250
        unsigned l;
251 8589
        const uint8_t *ss = ptr;
252
253 8589
        AN(pfx);
254 8589
        GET_VL(vl);
255 8589
        if (ss == NULL)
256 0
                vtc_leadin(vl, lvl, "%s(null)\n", pfx);
257
        else {
258 147923
                for (l = 0; l < len; l++, ss++) {
259 139362
                        if (l > 512) {
260 28
                                VSB_printf(vl->vsb, "...");
261 28
                                break;
262
                        }
263 139334
                        if (nl) {
264 14571
                                vtc_leadin(vl, lvl, "%s| ", pfx);
265 14571
                                nl = 0;
266 14571
                        }
267 139334
                        VSB_printf(vl->vsb, " %02x", *ss);
268 139334
                        if ((l & 0xf) == 0xf) {
269 6986
                                VSB_printf(vl->vsb, "\n");
270 6986
                                nl = 1;
271 6986
                        }
272 139334
                }
273
        }
274 8589
        if (!nl)
275 7585
                VSB_printf(vl->vsb, "\n");
276 8589
        REL_VL(vl);
277 8589
        if (lvl == 0)
278 0
                vtc_logfail();
279 8589
}
280
281
/**********************************************************************/
282
283
static void v_noreturn_
284 0
vtc_log_VAS_Fail(const char *func, const char *file, int line,
285
    const char *cond, enum vas_e why)
286
{
287
        struct vtclog *vl;
288 0
        int e = errno;
289
290 0
        (void)why;
291 0
        vl = pthread_getspecific(log_key);
292 0
        if (vl == NULL || vl->act) {
293 0
                fprintf(stderr,
294
                    "Assert error in %s(), %s line %d:\n"
295
                    "  Condition(%s) not true. (errno=%d %s)\n",
296 0
                    func, file, line, cond, e, strerror(e));
297 0
        } else
298 0
                vtc_fatal(vl, "Assert error in %s(), %s line %d:"
299
                    "  Condition(%s) not true."
300 0
                    "  Errno=%d %s", func, file, line, cond, e, strerror(e));
301 0
        abort();
302 0
}
303
304
/**********************************************************************/
305
306
void
307 19200
vtc_loginit(char *buf, unsigned buflen)
308
{
309
310 19200
        VAS_Fail_Func = vtc_log_VAS_Fail;
311 19200
        t0 = VTIM_mono();
312 19200
        vtclog_buf = buf;
313 19200
        vtclog_left = buflen;
314 19200
        AZ(pthread_mutex_init(&vtclog_mtx, NULL));
315 19200
        AZ(pthread_key_create(&log_key, NULL));
316 19200
}
317