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
}