vinyl-cache/bin/vinyltest/vtest2/src/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
#include "vbt.h"
43
44
static pthread_mutex_t  vtclog_mtx;
45
static char             *vtclog_buf;
46
static unsigned         vtclog_left;
47
48
static pthread_key_t log_key;
49
static double t0;
50
51
void
52 24954
vtc_log_set_cmd(struct vtclog *vl, const struct cmds *cmds)
53
{
54 24954
        AN(cmds);
55 24954
        vl->cmds = cmds;
56 24954
}
57
58
/**********************************************************************/
59
60
#define GET_VL(vl)                                      \
61
        do {                                            \
62
                CHECK_OBJ_NOTNULL(vl, VTCLOG_MAGIC);    \
63
                PTOK(pthread_mutex_lock(&vl->mtx));     \
64
                vl->act = 1;                            \
65
                VSB_clear(vl->vsb);                     \
66
        } while(0)
67
68
#define REL_VL(vl)                                      \
69
        do {                                            \
70
                AZ(VSB_finish(vl->vsb));                \
71
                vtc_log_emit(vl);                       \
72
                VSB_clear(vl->vsb);                     \
73
                vl->act = 0;                            \
74
                PTOK(pthread_mutex_unlock(&vl->mtx));   \
75
        } while(0)
76
77
78
struct vtclog *
79 42966
vtc_logopen(const char *fmt, ...)
80
{
81
        struct vtclog *vl;
82
        va_list ap;
83
        char buf[BUFSIZ];
84
85 42966
        va_start(ap, fmt);
86 42966
        vbprintf(buf, fmt, ap);
87 42966
        va_end(ap);
88
89 42966
        ALLOC_OBJ(vl, VTCLOG_MAGIC);
90 42964
        AN(vl);
91 42964
        REPLACE(vl->id, buf);
92 42964
        vl->vsb = VSB_new_auto();
93 42964
        PTOK(pthread_mutex_init(&vl->mtx, NULL));
94 42964
        PTOK(pthread_setspecific(log_key, vl));
95 42964
        return (vl);
96
}
97
98
void
99 37504
vtc_logclose(void *arg)
100
{
101
        struct vtclog *vl;
102
103 37504
        CAST_OBJ_NOTNULL(vl, arg, VTCLOG_MAGIC);
104 37504
        if (pthread_getspecific(log_key) == vl)
105 21392
                PTOK(pthread_setspecific(log_key, NULL));
106 37504
        VSB_destroy(&vl->vsb);
107 37504
        PTOK(pthread_mutex_destroy(&vl->mtx));
108 37504
        REPLACE(vl->id, NULL);
109 37504
        FREE_OBJ(vl);
110 37504
}
111
112
static void v_noreturn_
113 15
vtc_logfail(void)
114
{
115
116 15
        vtc_error = 2;
117 15
        if (!pthread_equal(pthread_self(), vtc_thread))
118 0
                pthread_exit(NULL);
119
        else
120 15
                exit(fail_out());
121
122
        WRONG("unreachable"); /*lint !e827 Help Coverity Scan see noreturn. */
123
}
124
125
static const char * const lead[] = {
126
        "----",
127
        "*   ",
128
        "**  ",
129
        "*** ",
130
        "****"
131
};
132
133
#define NLEAD (sizeof(lead)/sizeof(lead[0]))
134
135
static void
136 2461270
vtc_leadinv(const struct vtclog *vl, int lvl, const char *fmt, va_list ap)
137
{
138
139 2461270
        assert(lvl < (int)NLEAD);
140 2461270
        assert(lvl >= 0);
141 4922540
        VSB_printf(vl->vsb, "%s %-5s ",
142 2461270
            lead[lvl < 0 ? 1: lvl], vl->id);
143 2461270
        if (fmt != NULL)
144 2461327
                (void)VSB_vprintf(vl->vsb, fmt, ap);
145 2461384
}
146
147
static void
148 3459
vtc_leadin(const struct vtclog *vl, int lvl, const char *fmt, ...)
149
{
150
        va_list ap;
151
152 3459
        va_start(ap, fmt);
153 3459
        vtc_leadinv(vl, lvl, fmt, ap);
154 3459
        va_end(ap);
155 3459
}
156
157
static void
158 3123856
vtc_log_emit(const struct vtclog *vl)
159
{
160
        unsigned l;
161
        int i;
162
        int t_this;
163
        static int t_last = -1;
164
165 3123856
        l = VSB_len(vl->vsb);
166 3123856
        if (l == 0)
167 45477
                return;
168 3078379
        t_this = (int)round((VTIM_mono() - t0) * 1000);
169 3078379
        PTOK(pthread_mutex_lock(&vtclog_mtx));
170 3078379
        if (t_last != t_this) {
171 239678
                assert(vtclog_left > 25);
172 479356
                i = snprintf(vtclog_buf, vtclog_left,
173 239678
                    "**** dT    %d.%03d\n", t_this / 1000, t_this % 1000);
174 239678
                t_last = t_this;
175 239678
                vtclog_buf += i;
176 239678
                vtclog_left -= i;
177 239678
        }
178 3078379
        assert(vtclog_left > l);
179 3078379
        memcpy(vtclog_buf, VSB_data(vl->vsb), l);
180 3078379
        vtclog_buf += l;
181 3078379
        *vtclog_buf = '\0';
182 3078379
        vtclog_left -= l;
183 3078379
        PTOK(pthread_mutex_unlock(&vtclog_mtx));
184 3123856
}
185
186
void
187 15
vtc_fatal(struct vtclog *vl, const char *fmt, ...)
188
{
189
190 15
        GET_VL(vl);
191
        va_list ap;
192 15
        va_start(ap, fmt);
193 15
        vtc_leadinv(vl, 0, fmt, ap);
194 15
        VSB_putc(vl->vsb, '\n');
195 15
        va_end(ap);
196 15
        REL_VL(vl);
197
198 15
        vtc_logfail();
199
}
200
201
void
202 2468714
vtc_log(struct vtclog *vl, int lvl, const char *fmt, ...)
203
{
204
205 2468714
        GET_VL(vl);
206
        va_list ap;
207 2468714
        va_start(ap, fmt);
208 2468714
        if (lvl >= 0) {
209 2457847
                vtc_leadinv(vl, lvl, fmt, ap);
210 2457847
                VSB_putc(vl->vsb, '\n');
211 2457847
        }
212 2468714
        va_end(ap);
213 2468714
        REL_VL(vl);
214
215 2468714
        if (lvl == 0)
216 0
                vtc_logfail();
217 2468714
}
218
219
/**********************************************************************
220
 * Dump a string
221
 */
222
223
#define MAX_DUMP 8192
224
225
void
226 652861
vtc_dump(struct vtclog *vl, int lvl, const char *pfx, const char *str, int len)
227
{
228
        char buf[64];
229 652861
        int quote = VSB_QUOTE_UNSAFE | VSB_QUOTE_ESCHEX;
230
231 652861
        AN(pfx);
232 652861
        GET_VL(vl);
233 652861
        if (str == NULL)
234 5
                vtc_leadin(vl, lvl, "%s(null)\n", pfx);
235
        else {
236 652856
                bprintf(buf, "%s %-5s %s|",
237
                    lead[lvl < 0 ? 1: lvl], vl->id, pfx);
238 652856
                if (len < 0)
239 517918
                        len = strlen(str);
240 134938
                else if (str[0] == 0x1f && (uint8_t)str[1] == 0x8b)
241 1295
                        quote = VSB_QUOTE_HEX; // Dump gzip data in HEX
242 1305712
                VSB_quote_pfx(vl->vsb, buf, str,
243 652856
                    len > MAX_DUMP ? MAX_DUMP : len, quote);
244 652856
                if (quote == VSB_QUOTE_HEX)
245 1295
                        VSB_putc(vl->vsb, '\n');
246 652856
                if (len > MAX_DUMP)
247 3208
                        VSB_printf(vl->vsb, "%s [...] (%d)\n",
248 1604
                            buf, len - MAX_DUMP);
249
        }
250 652861
        REL_VL(vl);
251 652861
        if (lvl == 0)
252 0
                vtc_logfail();
253 652861
}
254
255
/**********************************************************************
256
 * Hexdump
257
 */
258
259
void
260 2043
vtc_hexdump(struct vtclog *vl, int lvl, const char *pfx,
261
    const void *ptr, unsigned len)
262
{
263 2043
        int nl = 1;
264
        unsigned l;
265 2043
        const uint8_t *ss = ptr;
266
267 2043
        AN(pfx);
268 2043
        GET_VL(vl);
269 2043
        if (ss == NULL)
270 0
                vtc_leadin(vl, lvl, "%s(null)\n", pfx);
271
        else {
272 35911
                for (l = 0; l < len; l++, ss++) {
273 33875
                        if (l > 512) {
274 7
                                VSB_cat(vl->vsb, "...");
275 7
                                break;
276
                        }
277 33868
                        if (nl) {
278 3454
                                vtc_leadin(vl, lvl, "%s| ", pfx);
279 3454
                                nl = 0;
280 3454
                        }
281 33868
                        VSB_printf(vl->vsb, " %02x", *ss);
282 33868
                        if ((l & 0xf) == 0xf) {
283 1668
                                VSB_cat(vl->vsb, "\n");
284 1668
                                nl = 1;
285 1668
                        }
286 33868
                }
287
        }
288 2043
        if (!nl)
289 1786
                VSB_cat(vl->vsb, "\n");
290 2043
        REL_VL(vl);
291 2043
        if (lvl == 0)
292 0
                vtc_logfail();
293 2043
}
294
295
/**********************************************************************/
296
297
static void v_noreturn_
298 0
vtc_log_VAS_Fail(const char *func, const char *file, int line,
299
    const char *cond, enum vas_e why)
300
{
301 0
        char buf[4096] = "";
302
        struct vtclog *vl;
303 0
        int e = errno;
304
305 0
        (void)why;
306
307 0
        if (VBT_dump(sizeof buf, buf) < 0) {
308 0
                bprintf(buf, "Failed to print backtrace: %d (%s)\n",
309
                    errno, strerror(errno));
310 0
        }
311
312 0
        vl = pthread_getspecific(log_key);
313 0
        if (vl == NULL || vl->act) {
314 0
                fprintf(stderr,
315
                    "Assert error in %s(), %s line %d:\n"
316
                    "  Condition(%s) not true. (errno=%d %s)\n"
317
                    "%s\n",
318 0
                    func, file, line, cond, e, strerror(e), buf);
319 0
        } else {
320 0
                vtc_fatal(vl, "Assert error in %s(), %s line %d:"
321
                    "  Condition(%s) not true."
322
                    "  Errno=%d %s\n"
323
                    "%s\n",
324 0
                    func, file, line, cond, e, strerror(e), buf);
325
        }
326 0
        abort();
327
}
328
329
/**********************************************************************/
330
331
void
332 5455
vtc_loginit(char *buf, unsigned buflen)
333
{
334
335 5455
        VAS_Fail_Func = vtc_log_VAS_Fail;
336 5455
        t0 = VTIM_mono();
337 5455
        vtclog_buf = buf;
338 5455
        vtclog_left = buflen;
339 5455
        PTOK(pthread_mutex_init(&vtclog_mtx, NULL));
340 5455
        PTOK(pthread_key_create(&log_key, NULL));
341 5455
}