varnish-cache/bin/varnishncsa/varnishncsa.c
0
/*-
1
 * Copyright (c) 2006 Verdens Gang AS
2
 * Copyright (c) 2006-2016 Varnish Software AS
3
 * All rights reserved.
4
 *
5
 * Author: Anders Berg <andersb@vgnett.no>
6
 * Author: Poul-Henning Kamp <phk@phk.freebsd.dk>
7
 * Author: Tollef Fog Heen <tfheen@varnish-software.com>
8
 * Author: Martin Blix Grydeland <mbgrydeland@varnish-software.com>
9
 *
10
 * SPDX-License-Identifier: BSD-2-Clause
11
 *
12
 * Redistribution and use in source and binary forms, with or without
13
 * modification, are permitted provided that the following conditions
14
 * are met:
15
 * 1. Redistributions of source code must retain the above copyright
16
 *    notice, this list of conditions and the following disclaimer.
17
 * 2. Redistributions in binary form must reproduce the above copyright
18
 *    notice, this list of conditions and the following disclaimer in the
19
 *    documentation and/or other materials provided with the distribution.
20
 *
21
 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
22
 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
23
 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
24
 * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
25
 * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
26
 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
27
 * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
28
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
29
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
30
 * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
31
 * SUCH DAMAGE.
32
 *
33
 * Obtain log data from the shared memory log, order it by session ID, and
34
 * display it in Apache / NCSA combined log format.
35
 *
36
 * See doc/sphinx/reference/varnishncsa.rst for the supported format
37
 * specifiers.
38
 *
39
 */
40
41
#include "config.h"
42
43
#include <stdlib.h>
44
#include <stdio.h>
45
#include <unistd.h>
46
#include <string.h>
47
#include <signal.h>
48
#include <stdarg.h>
49
#include <inttypes.h>
50
#include <limits.h>
51
#include <ctype.h>
52
#include <time.h>
53
#include <math.h>
54
55
#define VOPT_DEFINITION
56
#define VOPT_INC "varnishncsa_options.h"
57
58
#include "vdef.h"
59
60
#include "vapi/vsl.h"
61
#include "vapi/voptget.h"
62
#include "vas.h"
63
#include "venc.h"
64
#include "vsb.h"
65
#include "vut.h"
66
#include "vqueue.h"
67
#include "miniobj.h"
68
69
#define TIME_FMT "[%d/%b/%Y:%T %z]"
70
#define FORMAT "%h %l %u %t \"%r\" %s %b \"%{Referer}i\" \"%{User-agent}i\""
71
72
static struct VUT *vut;
73
74
struct format;
75
76
enum e_frag {
77
        F_H,                    /* %H Proto */
78
        F_U,                    /* %U URL path */
79
        F_q,                    /* %q Query string */
80
        F_b,                    /* %b Body bytes sent */
81
        F_h,                    /* %h Host name / IP Address */
82
        F_m,                    /* %m Method */
83
        F_s,                    /* %s Status */
84
        F_I,                    /* %I Bytes received */
85
        F_O,                    /* %O Bytes sent */
86
        F_tstart,               /* Time start */
87
        F_tend,                 /* Time end */
88
        F_ttfb,                 /* %{Varnish:time_firstbyte}x */
89
        F_host,                 /* Host header */
90
        F_auth,                 /* Authorization header */
91
        F__MAX,
92
};
93
94
struct fragment {
95
        uint64_t                gen;
96
        const char              *b, *e;
97
};
98
99
typedef int format_f(const struct format *format);
100
101
struct format {
102
        unsigned                magic;
103
#define FORMAT_MAGIC            0xC3119CDA
104
105
        char                    time_type;
106
        VTAILQ_ENTRY(format)    list;
107
        format_f                *func;
108
        struct fragment         *frag;
109
        char                    *string;
110
        const char *const       *strptr;
111
        char                    *time_fmt;
112
        int64_t                 *int64;
113
};
114
115
struct watch {
116
        unsigned                magic;
117
#define WATCH_MAGIC             0xA7D4005C
118
119
        VTAILQ_ENTRY(watch)     list;
120
        char                    *key;
121
        int                     keylen;
122
        struct fragment         frag;
123
};
124
VTAILQ_HEAD(watch_head, watch);
125
126
struct vsl_watch {
127
        unsigned                magic;
128
#define VSL_WATCH_MAGIC         0xE3E27D23
129
130
        VTAILQ_ENTRY(vsl_watch) list;
131
        enum VSL_tag_e          tag;
132
        int                     idx;
133
        char                    *prefix;
134
        int                     prefixlen;
135
        struct fragment         frag;
136
};
137
VTAILQ_HEAD(vsl_watch_head, vsl_watch);
138
139
static struct ctx {
140
        /* Options */
141
        int                     a_opt;
142
        char                    *w_arg;
143
144
        FILE                    *fo;
145
        struct vsb              *vsb;
146
        uint64_t                gen;
147
        VTAILQ_HEAD(,format)    format;
148
        int                     quote_how;
149
        char                    *missing_string;
150
        char                    *missing_int;
151
152
        /* State */
153
        struct watch_head       watch_vcl_log;
154
        struct watch_head       watch_reqhdr; /* also bereqhdr */
155
        struct watch_head       watch_resphdr; /* also beresphdr */
156
        struct vsl_watch_head   watch_vsl;
157
        struct fragment         frag[F__MAX];
158
        const char              *hitmiss;
159
        const char              *handling;
160
        const char              *side;
161
        int64_t                 vxid;
162
} CTX;
163
164
static void parse_format(const char *format);
165
166
static void
167 200
openout(int append)
168
{
169
170 200
        AN(CTX.w_arg);
171 200
        if (!strcmp(CTX.w_arg, "-"))
172 0
                CTX.fo = stdout;
173
        else
174 200
                CTX.fo = fopen(CTX.w_arg, append ? "a" : "w");
175 200
        if (CTX.fo == NULL)
176 80
                VUT_Error(vut, 1, "Can't open output file (%s)",
177 40
                    strerror(errno));
178 160
}
179
180
static int v_matchproto_(VUT_cb_f)
181 40
rotateout(struct VUT *v)
182
{
183
184 40
        assert(v == vut);
185 40
        AN(CTX.w_arg);
186 40
        AN(CTX.fo);
187 40
        (void)fclose(CTX.fo);
188 40
        openout(1);
189 40
        AN(CTX.fo);
190 40
        return (0);
191
}
192
193
static int v_matchproto_(VUT_cb_f)
194 34050
flushout(struct VUT *v)
195
{
196
197 34050
        assert(v == vut);
198 34050
        AN(CTX.fo);
199 34050
        if (fflush(CTX.fo))
200 0
                return (-5);
201 34050
        return (0);
202 34050
}
203
204
static inline int
205 8360
vsb_fcat(struct vsb *vsb, const struct fragment *f, const char *dflt)
206
{
207 8360
        if (f->gen == CTX.gen) {
208 8200
                assert(f->b <= f->e);
209 8200
                VSB_quote(vsb, f->b, f->e - f->b, CTX.quote_how);
210 8360
        } else if (dflt)
211 160
                VSB_quote(vsb, dflt, -1, CTX.quote_how);
212
        else
213 0
                return (-1);
214 8360
        return (0);
215 8360
}
216
217
static int v_matchproto_(format_f)
218 11040
format_string(const struct format *format)
219
{
220
221 11040
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
222 11040
        AN(format->string);
223 11040
        AZ(VSB_cat(CTX.vsb, format->string));
224 11040
        return (1);
225
}
226
227
static int v_matchproto_(format_f)
228 1080
format_strptr(const struct format *format)
229
{
230
231 1080
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
232 1080
        AN(format->strptr);
233 1080
        AN(*format->strptr);
234 1080
        AZ(VSB_cat(CTX.vsb, *format->strptr));
235 1080
        return (1);
236
}
237
238
static int v_matchproto_(format_f)
239 840
format_int64(const struct format *format)
240
{
241
242 840
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
243 840
        VSB_printf(CTX.vsb, "%jd", (intmax_t)*format->int64);
244 840
        return (1);
245
}
246
247
static int v_matchproto_(format_f)
248 7280
format_fragment(const struct format *format)
249
{
250
251 7280
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
252 7280
        AN(format->frag);
253
254 7280
        if (format->frag->gen != CTX.gen) {
255 1840
                if (format->string == NULL)
256 0
                        return (-1);
257 1840
                VSB_quote(CTX.vsb, format->string, -1, CTX.quote_how);
258 1840
                return (0);
259
        }
260 5440
        AZ(vsb_fcat(CTX.vsb, format->frag, NULL));
261 5440
        return (1);
262 7280
}
263
264
static int v_matchproto_(format_f)
265 2400
format_time(const struct format *format)
266
{
267
        double t_start, t_end, d;
268
        char *p;
269
        char buf[64];
270
        time_t t;
271
        intmax_t l;
272
        struct tm tm;
273
274 2400
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
275 2400
        if (CTX.frag[F_tstart].gen == CTX.gen) {
276 2400
                t_start = strtod(CTX.frag[F_tstart].b, &p);
277 2400
                if (p != CTX.frag[F_tstart].e)
278 0
                        t_start = NAN;
279 2400
        } else
280 0
                t_start = NAN;
281 2400
        if (isnan(t_start)) {
282
                /* Missing t_start is a no go */
283 0
                if (format->string == NULL)
284 0
                        return (-1);
285 0
                AZ(VSB_cat(CTX.vsb, format->string));
286 0
                return (0);
287
        }
288
289
        /* Missing t_end defaults to t_start */
290 2400
        if (CTX.frag[F_tend].gen == CTX.gen) {
291 2360
                t_end = strtod(CTX.frag[F_tend].b, &p);
292 2360
                if (p != CTX.frag[F_tend].e)
293 0
                        t_end = t_start;
294 2360
        } else
295 40
                t_end = t_start;
296
297 2400
        AN(format->time_fmt);
298
299 2400
        switch (format->time_type) {
300
        case 't':
301 1200
                t = (intmax_t)floor(t_start);
302 1200
                (void)localtime_r(&t, &tm);
303 1200
                AN(strftime(buf, sizeof buf, format->time_fmt, &tm));
304 1200
                AZ(VSB_cat(CTX.vsb, buf));
305 1200
                return (1);
306
        case '3':
307 120
                l = (intmax_t)(modf(t_start, &d) * 1e3);
308 120
                break;
309
        case '6':
310 120
                l = (intmax_t)(modf(t_start, &d) * 1e6);
311 120
                break;
312
        case 'S':
313 120
                l = (intmax_t)t_start;
314 120
                break;
315
        case 'M':
316 120
                l = (intmax_t)(t_start * 1e3);
317 120
                break;
318
        case 'U':
319 120
                l = (intmax_t)(t_start * 1e6);
320 120
                break;
321
        case 's':
322 240
                l = (intmax_t)(t_end - t_start);
323 240
                break;
324
        case 'm':
325 120
                l = (intmax_t)((t_end - t_start) * 1e3);
326 120
                break;
327
        case 'u':
328 240
                l = (intmax_t)((t_end - t_start) * 1e6);
329 240
                break;
330
        default:
331 0
                WRONG("Time format specifier");
332 0
        }
333
334
#ifdef __FreeBSD__
335 1200
        assert(fmtcheck(format->time_fmt, "%jd") == format->time_fmt);
336
#endif
337 1200
        AZ(VSB_printf(CTX.vsb, format->time_fmt, l));
338
339 1200
        return (1);
340 2400
}
341
342
static int v_matchproto_(format_f)
343 600
format_requestline(const struct format *format)
344
{
345
346 600
        (void)format;
347 600
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_m], "-"));
348 600
        AZ(VSB_putc(CTX.vsb, ' '));
349 600
        if (CTX.frag[F_host].gen == CTX.gen) {
350 520
                if (strncmp(CTX.frag[F_host].b, "http://", 7))
351 520
                        AZ(VSB_cat(CTX.vsb, "http://"));
352 520
                AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_host], NULL));
353 520
        } else
354 80
                AZ(VSB_cat(CTX.vsb, "http://localhost"));
355 600
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_U], ""));
356 600
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_q], ""));
357 600
        AZ(VSB_putc(CTX.vsb, ' '));
358 600
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_H], "HTTP/1.0"));
359 600
        return (1);
360
}
361
362
static int v_matchproto_(format_f)
363 640
format_auth(const struct format *format)
364
{
365 640
        struct vsb *vsb = VSB_new_auto();
366 640
        AN(vsb);
367
        char *q;
368
369 640
        if (CTX.frag[F_auth].gen != CTX.gen ||
370 240
            VENC_Decode_Base64(vsb, CTX.frag[F_auth].b, CTX.frag[F_auth].e)) {
371 400
                VSB_destroy(&vsb);
372 400
                if (format->string == NULL)
373 0
                        return (-1);
374 400
                VSB_quote(CTX.vsb, format->string, -1, CTX.quote_how);
375 400
                return (0);
376
        }
377 240
        AZ(VSB_finish(vsb));
378 240
        q = strchr(VSB_data(vsb), ':');
379 240
        if (q != NULL)
380 240
                *q = '\0';
381 240
        VSB_quote(CTX.vsb, VSB_data(vsb), -1, CTX.quote_how);
382 240
        VSB_destroy(&vsb);
383 240
        return (1);
384 640
}
385
386
static int
387 3280
print(void)
388
{
389
        const struct format *f;
390 3280
        int i, r = 1;
391
392 3280
        VSB_clear(CTX.vsb);
393 27160
        VTAILQ_FOREACH(f, &CTX.format, list) {
394 23880
                CHECK_OBJ_NOTNULL(f, FORMAT_MAGIC);
395 23880
                i = (f->func)(f);
396 23880
                AZ(VSB_error(CTX.vsb));
397 23880
                if (r > i)
398 960
                        r = i;
399 23880
        }
400 3280
        AZ(VSB_putc(CTX.vsb, '\n'));
401 3280
        AZ(VSB_finish(CTX.vsb));
402 3280
        if (r >= 0) {
403 3280
                i = fwrite(VSB_data(CTX.vsb), 1, VSB_len(CTX.vsb), CTX.fo);
404 3280
                if (i != VSB_len(CTX.vsb))
405 0
                        return (-5);
406 3280
        }
407 3280
        return (0);
408 3280
}
409
410
static void
411 8240
addf_string(const char *str)
412
{
413
        struct format *f;
414
415 8240
        AN(str);
416 8240
        ALLOC_OBJ(f, FORMAT_MAGIC);
417 8240
        AN(f);
418 8240
        f->func = format_string;
419 8240
        f->string = strdup(str);
420 8240
        AN(f->string);
421 8240
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
422 8240
}
423
424
static void
425 280
addf_strptr(const char *const *strptr)
426
{
427
        struct format *f;
428
429 280
        AN(strptr);
430 280
        ALLOC_OBJ(f, FORMAT_MAGIC);
431 280
        AN(f);
432 280
        f->func = format_strptr;
433 280
        f->strptr = strptr;
434 280
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
435 280
}
436
437
static void
438 3520
addf_fragment(struct fragment *frag, const char *str)
439
{
440
        struct format *f;
441
442 3520
        AN(frag);
443 3520
        ALLOC_OBJ(f, FORMAT_MAGIC);
444 3520
        AN(f);
445 3520
        f->func = format_fragment;
446 3520
        f->frag = frag;
447 3520
        if (str != NULL) {
448 3520
                f->string = strdup(str);
449 3520
                AN(f->string);
450 3520
        }
451 3520
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
452 3520
}
453
454
static void
455 200
addf_int64(int64_t *i)
456
{
457
        struct format *f;
458
459 200
        AN(i);
460 200
        ALLOC_OBJ(f, FORMAT_MAGIC);
461 200
        AN(f);
462 200
        f->func = format_int64;
463 200
        f->int64 = i;
464 200
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
465 200
}
466
467
static void
468 1280
addf_time(char type, const char *fmt)
469
{
470
        struct format *f;
471
472 1280
        ALLOC_OBJ(f, FORMAT_MAGIC);
473 1280
        AN(f);
474 1280
        AN(fmt);
475 1280
        f->func = format_time;
476 1280
        f->time_type = type;
477 1280
        f->time_fmt = strdup(fmt);
478
479 1280
        if (f->time_type == 'T') {
480 200
                if (!strcmp(fmt, "s"))
481 80
                        f->time_type = 's';
482 120
                else if (!strcmp(fmt, "ms"))
483 40
                        f->time_type = 'm';
484 80
                else if (!strcmp(fmt, "us"))
485 80
                        f->time_type = 'u';
486
                else
487 0
                        VUT_Error(vut, 1, "Unknown specifier: %%{%s}T",
488 0
                            fmt);
489 200
                REPLACE(f->time_fmt, "%jd");
490 1280
        } else if (f->time_type == 't') {
491 1080
                if (!strcmp(fmt, "sec")) {
492 40
                        f->time_type = 'S';
493 40
                        REPLACE(f->time_fmt, "%jd");
494 1080
                } else if (!strncmp(fmt, "msec", 4)) {
495 120
                        fmt += 4;
496 120
                        if (!strcmp(fmt, "_frac")) {
497 40
                                f->time_type = '3';
498 40
                                REPLACE(f->time_fmt, "%03jd");
499 120
                        } else if (*fmt == '\0') {
500 40
                                f->time_type = 'M';
501 40
                                REPLACE(f->time_fmt, "%jd");
502 40
                        }
503 1040
                } else if (!strncmp(fmt, "usec", 4)) {
504 120
                        fmt += 4;
505 120
                        if (!strcmp(fmt, "_frac")) {
506 40
                                f->time_type = '6';
507 40
                                REPLACE(f->time_fmt, "%06jd");
508 120
                        } else if (*fmt == '\0') {
509 40
                                f->time_type = 'U';
510 40
                                REPLACE(f->time_fmt, "%jd");
511 40
                        }
512 120
                }
513 1080
        }
514
515 1280
        AN(f->time_fmt);
516 1280
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
517 1280
}
518
519
static void
520 760
addf_requestline(void)
521
{
522
        struct format *f;
523
524 760
        ALLOC_OBJ(f, FORMAT_MAGIC);
525 760
        AN(f);
526 760
        f->func = format_requestline;
527 760
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
528 760
}
529
530
static void
531 80
addf_vcl_log(const char *key)
532
{
533
        struct watch *w;
534
        struct format *f;
535
536 80
        AN(key);
537 80
        ALLOC_OBJ(w, WATCH_MAGIC);
538 80
        AN(w);
539 80
        w->keylen = asprintf(&w->key, "%s:", key);
540 80
        assert(w->keylen > 0);
541 80
        VTAILQ_INSERT_TAIL(&CTX.watch_vcl_log, w, list);
542
543 80
        ALLOC_OBJ(f, FORMAT_MAGIC);
544 80
        AN(f);
545 80
        f->func = format_fragment;
546 80
        f->frag = &w->frag;
547 80
        f->string = strdup("");
548 80
        AN(f->string);
549 80
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
550 80
}
551
552
static void
553 1760
addf_hdr(struct watch_head *head, const char *key)
554
{
555
        struct watch *w;
556
        struct format *f;
557
558 1760
        AN(head);
559 1760
        AN(key);
560 1760
        ALLOC_OBJ(w, WATCH_MAGIC);
561 1760
        AN(w);
562 1760
        w->keylen = asprintf(&w->key, "%s:", key);
563 1760
        assert(w->keylen > 0);
564 1760
        VTAILQ_INSERT_TAIL(head, w, list);
565
566 1760
        ALLOC_OBJ(f, FORMAT_MAGIC);
567 1760
        AN(f);
568 1760
        f->func = format_fragment;
569 1760
        f->frag = &w->frag;
570 1760
        f->string = strdup(CTX.missing_string);
571 1760
        AN(f->string);
572 1760
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
573 1760
}
574
575
static void
576 520
addf_vsl(enum VSL_tag_e tag, long i, const char *prefix)
577
{
578
        struct vsl_watch *w;
579
580 520
        ALLOC_OBJ(w, VSL_WATCH_MAGIC);
581 520
        AN(w);
582 520
        if (VSL_tagflags[tag] && CTX.quote_how != VSB_QUOTE_JSON)
583 80
                VUT_Error(vut, 1, "Tag %s can contain control characters",
584 40
                    VSL_tags[tag]);
585 480
        w->tag = tag;
586 480
        assert(i <= INT_MAX);
587 480
        w->idx = i;
588 480
        if (prefix != NULL) {
589 120
                w->prefixlen = asprintf(&w->prefix, "%s:", prefix);
590 120
                assert(w->prefixlen > 0);
591 120
        }
592 480
        VTAILQ_INSERT_TAIL(&CTX.watch_vsl, w, list);
593 480
        addf_fragment(&w->frag, CTX.missing_string);
594 480
}
595
596
static void
597 720
addf_auth(void)
598
{
599
        struct format *f;
600
601 720
        ALLOC_OBJ(f, FORMAT_MAGIC);
602 720
        AN(f);
603 720
        f->func = format_auth;
604 720
        f->string = strdup("-");
605 720
        AN(f->string);
606 720
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
607 720
}
608
609
static void
610 1560
parse_x_format(char *buf)
611
{
612
        char *e, *r, *s;
613
        long lval;
614
        int slt;
615
616 1560
        if (!strcmp(buf, "Varnish:time_firstbyte")) {
617 40
                addf_fragment(&CTX.frag[F_ttfb], CTX.missing_int);
618 40
                return;
619
        }
620 1520
        if (!strcmp(buf, "Varnish:hitmiss")) {
621 40
                addf_strptr(&CTX.hitmiss);
622 40
                return;
623
        }
624 1480
        if (!strcmp(buf, "Varnish:handling")) {
625 40
                addf_strptr(&CTX.handling);
626 40
                return;
627
        }
628 1440
        if (!strcmp(buf, "Varnish:side")) {
629 200
                addf_strptr(&CTX.side);
630 200
                return;
631
        }
632 1240
        if (!strcmp(buf, "Varnish:vxid")) {
633 200
                addf_int64(&CTX.vxid);
634 200
                return;
635
        }
636 1040
        if (!strncmp(buf, "VCL_Log:", 8)) {
637 80
                addf_vcl_log(buf + 8);
638 80
                return;
639
        }
640 960
        if (!strncmp(buf, "VSL:", 4)) {
641 880
                buf += 4;
642 880
                e = buf;
643 8240
                while (*e != '\0')
644 7360
                        e++;
645 880
                if (e == buf)
646 40
                        VUT_Error(vut, 1, "Missing tag in VSL:");
647 840
                if (e[-1] == ']') {
648 480
                        r = e - 1;
649 2000
                        while (r > buf && *r != '[')
650 1520
                                r--;
651 480
                        if (r == buf || r[1] == ']')
652 40
                                VUT_Error(vut, 1, "Syntax error: VSL:%s", buf);
653 440
                        e[-1] = '\0';
654 440
                        lval = strtol(r + 1, &s, 10);
655 440
                        if (s != e - 1)
656 40
                                VUT_Error(vut, 1, "Syntax error: VSL:%s]", buf);
657 400
                        if (lval <= 0 || lval > 255) {
658 160
                                VUT_Error(vut, 1,
659
                                    "Syntax error. Field specifier must be"
660
                                    " between 1 and 255: %s]",
661 80
                                    buf);
662
                        }
663 320
                        *r = '\0';
664 320
                } else
665 360
                        lval = 0;
666 680
                r = buf;
667 5720
                while (r < e && *r != ':')
668 5040
                        r++;
669 680
                if (r != e) {
670 120
                        slt = VSL_Name2Tag(buf, r - buf);
671 120
                        r++;
672 120
                } else {
673 560
                        slt = VSL_Name2Tag(buf, -1);
674 560
                        r = NULL;
675
                }
676 680
                if (slt == -2)
677 40
                        VUT_Error(vut, 1, "Tag not unique: %s", buf);
678 640
                if (slt == -1)
679 120
                        VUT_Error(vut, 1, "Unknown log tag: %s", buf);
680 520
                assert(slt >= 0);
681
682 520
                addf_vsl((enum VSL_tag_e)slt, lval, r);
683 520
                return;
684
        }
685 80
        if (!strcmp(buf, "Varnish:default_format")) {
686 40
                parse_format(FORMAT);
687 40
                return;
688
        }
689 40
        VUT_Error(vut, 1, "Unknown formatting extension: %s", buf);
690 1160
}
691
692
static void
693 2680
parse_format(const char *format)
694
{
695
        const char *p, *q;
696
        struct vsb *vsb;
697
        char buf[256];
698
        int b;
699
700 2680
        if (format == NULL)
701 600
                format = FORMAT;
702
703 2680
        vsb = VSB_new_auto();
704 2680
        AN(vsb);
705
706 25880
        for (p = format; *p != '\0'; p++) {
707
708
                /* Allow the most essential escape sequences in format */
709 23320
                if (*p == '\\' && p[1] != '\0') {
710 40
                        if (*++p == 't')
711 0
                                AZ(VSB_putc(vsb, '\t'));
712 40
                        else if (*p == 'n')
713 40
                                AZ(VSB_putc(vsb, '\n'));
714
                        else
715 0
                                AZ(VSB_putc(vsb, *p));
716 40
                        continue;
717
                }
718
719 23280
                if (*p != '%') {
720 13400
                        AZ(VSB_putc(vsb, *p));
721 13400
                        continue;
722
                }
723
724 9880
                if (VSB_len(vsb) > 0) {
725 7400
                        AZ(VSB_finish(vsb));
726 7400
                        addf_string(VSB_data(vsb));
727 7400
                        VSB_clear(vsb);
728 7400
                }
729
730 9880
                p++;
731 9880
                switch (*p) {
732
                case 'b':       /* Body bytes sent */
733 800
                        addf_fragment(&CTX.frag[F_b], CTX.missing_int);
734 800
                        break;
735
                case 'D':       /* Float request time */
736 40
                        addf_time('T', "us");
737 40
                        break;
738
                case 'h':       /* Client host name / IP Address */
739 800
                        addf_fragment(&CTX.frag[F_h], CTX.missing_string);
740 800
                        break;
741
                case 'H':       /* Protocol */
742 40
                        addf_fragment(&CTX.frag[F_H], "HTTP/1.0");
743 40
                        break;
744
                case 'I':       /* Bytes received */
745 40
                        addf_fragment(&CTX.frag[F_I], CTX.missing_int);
746 40
                        break;
747
                case 'l':       /* Client user ID (identd) always '-' */
748 680
                        AZ(VSB_putc(vsb, '-'));
749 680
                        break;
750
                case 'm':       /* Method */
751 40
                        addf_fragment(&CTX.frag[F_m], CTX.missing_string);
752 40
                        break;
753
                case 'O':       /* Bytes sent */
754 40
                        addf_fragment(&CTX.frag[F_O], CTX.missing_int);
755 40
                        break;
756
                case 'q':       /* Query string */
757 40
                        addf_fragment(&CTX.frag[F_q], "");
758 40
                        break;
759
                case 'r':       /* Request line */
760 760
                        addf_requestline();
761 760
                        break;
762
                case 's':       /* Status code */
763 1160
                        addf_fragment(&CTX.frag[F_s], CTX.missing_int);
764 1160
                        break;
765
                case 't':       /* strftime */
766 680
                        addf_time(*p, TIME_FMT);
767 680
                        break;
768
                case 'T':       /* Int request time */
769 40
                        addf_time(*p, "s");
770 40
                        break;
771
                case 'u':       /* Remote user from auth */
772 720
                        addf_auth();
773 720
                        break;
774
                case 'U':       /* URL */
775 40
                        addf_fragment(&CTX.frag[F_U], CTX.missing_string);
776 40
                        break;
777
                case '{':
778 3920
                        p++;
779 3920
                        q = p;
780 3920
                        b = 1;
781 41240
                        while (*q) {
782 41200
                                if (*q == '{')
783 160
                                        b++;
784 41040
                                else if (*q == '}')
785 4040
                                        if (--b == 0)
786 3880
                                                break;
787 37320
                                q++;
788
                        }
789 3920
                        if (b > 0)
790 80
                                VUT_Error(vut, 1, "Unmatched bracket at: %s",
791 40
                                    p - 2);
792 3880
                        assert((unsigned)(q - p) < sizeof buf - 1);
793 3880
                        strncpy(buf, p, q - p);
794 3880
                        buf[q - p] = '\0';
795 3880
                        q++;
796 3880
                        switch (*q) {
797
                        case 'i':
798 1720
                                addf_hdr(&CTX.watch_reqhdr, buf);
799 1720
                                break;
800
                        case 'o':
801 40
                                addf_hdr(&CTX.watch_resphdr, buf);
802 40
                                break;
803
                        case 't':
804 400
                                addf_time(*q, buf);
805 400
                                break;
806
                        case 'T':
807 120
                                addf_time(*q, buf);
808 120
                                break;
809
                        case 'x':
810 1560
                                parse_x_format(buf);
811 1560
                                break;
812
                        default:
813 80
                                VUT_Error(vut, 1,
814
                                    "Unknown format specifier at: %s",
815 40
                                    p - 2);
816
                        }
817 3840
                        p = q;
818 3840
                        break;
819
                default:
820 80
                        VUT_Error(vut, 1, "Unknown format specifier at: %s",
821 40
                            p - 1);
822
                }
823 9760
        }
824
825 2560
        if (VSB_len(vsb) > 0) {
826
                /* Add any remaining static */
827 840
                AZ(VSB_finish(vsb));
828 840
                addf_string(VSB_data(vsb));
829 840
                VSB_clear(vsb);
830 840
        }
831
832 2560
        VSB_destroy(&vsb);
833 2560
}
834
835
static int
836 105880
isprefix(const char *prefix, size_t len, const char *b,
837
    const char *e, const char **next)
838
{
839 105880
        assert(len > 0);
840 105880
        if (e < b + len || strncasecmp(b, prefix, len))
841 90560
                return (0);
842 15320
        b += len;
843 15320
        if (next) {
844 29880
                while (b < e && *b == ' ')
845 14560
                        b++;
846 15320
                *next = b;
847 15320
        }
848 15320
        return (1);
849 105880
}
850
851
static void
852 17920
frag_fields(int force, const char *b, const char *e, ...)
853
{
854
        va_list ap;
855
        const char *p, *q;
856
        int n, field;
857
        struct fragment *frag;
858
859 17920
        AN(b);
860 17920
        AN(e);
861 17920
        va_start(ap, e);
862
863 17920
        n = 0;
864 42000
        while (1) {
865 42120
                field = va_arg(ap, int);
866 42120
                frag = va_arg(ap, struct fragment *);
867 42120
                if (field == 0) {
868 17920
                        AZ(frag);
869 17920
                        break;
870
                }
871 24200
                p = q = NULL;
872 64400
                while (n < field) {
873 62360
                        while (b < e && isspace(*b))
874 22160
                                b++;
875 40200
                        p = b;
876 342840
                        while (b < e && !isspace(*b))
877 302640
                                b++;
878 40200
                        q = b;
879 40200
                        n++;
880
                }
881 24200
                assert(p != NULL && q != NULL);
882 24200
                if (p >= e || q <= p)
883 120
                        continue;
884 24080
                if (frag->gen != CTX.gen || force) {
885
                        /* We only grab the same matching field once */
886 23480
                        frag->gen = CTX.gen;
887 23480
                        frag->b = p;
888 23480
                        frag->e = q;
889 23480
                }
890
        }
891 17920
        va_end(ap);
892 17920
}
893
894
static void
895 22000
frag_line(int force, const char *b, const char *e, struct fragment *f)
896
{
897
898 22000
        if (f->gen == CTX.gen && !force)
899
                /* We only grab the same matching record once */
900 1480
                return;
901
902
        /* Skip leading space */
903 20520
        while (b < e && isspace(*b))
904 0
                ++b;
905
906
        /* Skip trailing space */
907 20520
        while (e > b && isspace(e[-1]))
908 0
                --e;
909
910 20520
        f->gen = CTX.gen;
911 20520
        f->b = b;
912 20520
        f->e = e;
913 22000
}
914
915
static void
916 34040
process_hdr(const struct watch_head *head, const char *b, const char *e)
917
{
918
        struct watch *w;
919
        const char *p;
920
921 41360
        VTAILQ_FOREACH(w, head, list) {
922 7320
                CHECK_OBJ_NOTNULL(w, WATCH_MAGIC);
923 7320
                if (!isprefix(w->key, w->keylen, b, e, &p))
924 6680
                        continue;
925 640
                frag_line(1, p, e, &w->frag);
926 640
        }
927 34040
}
928
929
static void
930 117560
process_vsl(const struct vsl_watch_head *head, enum VSL_tag_e tag,
931
    const char *b, const char *e)
932
{
933
        struct vsl_watch *w;
934
        const char *p;
935 171800
        VTAILQ_FOREACH(w, head, list) {
936 54240
                CHECK_OBJ_NOTNULL(w, VSL_WATCH_MAGIC);
937 54240
                if (tag != w->tag)
938 51400
                        continue;
939 2840
                p = b;
940 2840
                if (w->prefixlen > 0 &&
941 1680
                    !isprefix(w->prefix, w->prefixlen, b, e, &p))
942 1520
                        continue;
943 1320
                if (w->idx == 0)
944 240
                        frag_line(0, p, e, &w->frag);
945
                else
946 1080
                        frag_fields(0, p, e, w->idx, &w->frag, 0, NULL);
947 1320
        }
948 117560
}
949
950
static int v_matchproto_(VSLQ_dispatch_f)
951 4200
dispatch_f(struct VSL_data *vsl, struct VSL_transaction * const pt[],
952
    void *priv)
953
{
954
        struct VSL_transaction *t;
955
        enum VSL_tag_e tag;
956
        const char *b, *e, *p;
957
        struct watch *w;
958
        int i, skip;
959
960 4200
        (void)vsl;
961 4200
        (void)priv;
962
963 8400
        for (t = pt[0]; t != NULL; t = *++pt) {
964 4200
                CTX.gen++;
965
966 4200
                if (t->type == VSL_t_req) {
967 2880
                        CTX.side = "c";
968 4200
                } else if (t->type == VSL_t_bereq) {
969 400
                        CTX.side = "b";
970 400
                } else
971 920
                        continue;
972
973 3280
                CTX.hitmiss = "-";
974 3280
                CTX.handling = "-";
975 3280
                CTX.vxid = t->vxid;
976 3280
                skip = 0;
977 120960
                while (skip == 0 && 1 == VSL_Next(t->c)) {
978 117680
                        tag = VSL_TAG(t->c->rec.ptr);
979 117680
                        if (VSL_tagflags[tag] &&
980 160
                            CTX.quote_how != VSB_QUOTE_JSON)
981 120
                                continue;
982
983 117560
                        b = VSL_CDATA(t->c->rec.ptr);
984 117560
                        e = b + VSL_LEN(t->c->rec.ptr);
985 117560
                        if (!VSL_tagflags[tag]) {
986 235040
                                while (e > b && e[-1] == '\0')
987 117520
                                        e--;
988 117520
                        }
989
990 117560
                        switch (tag) {
991
                        case SLT_HttpGarbage:
992 0
                                skip = 1;
993 0
                                break;
994
                        case SLT_PipeAcct:
995 280
                                frag_fields(0, b, e,
996
                                    3, &CTX.frag[F_I],
997
                                    4, &CTX.frag[F_O],
998
                                    0, NULL);
999 280
                                break;
1000
                        case SLT_BackendOpen:
1001 400
                                frag_fields(1, b, e,
1002
                                    3, &CTX.frag[F_h],
1003
                                    0, NULL);
1004 400
                                break;
1005
                        case SLT_ReqStart:
1006 2880
                                frag_fields(0, b, e,
1007
                                    1, &CTX.frag[F_h],
1008
                                    0, NULL);
1009 2880
                                break;
1010
                        case SLT_BereqMethod:
1011
                        case SLT_ReqMethod:
1012 3240
                                frag_line(0, b, e, &CTX.frag[F_m]);
1013 3240
                                break;
1014
                        case SLT_BereqURL:
1015
                        case SLT_ReqURL:
1016 3920
                                p = memchr(b, '?', e - b);
1017 3920
                                if (p == NULL)
1018 3160
                                        p = e;
1019 3920
                                frag_line(0, b, p, &CTX.frag[F_U]);
1020 3920
                                frag_line(0, p, e, &CTX.frag[F_q]);
1021 3920
                                break;
1022
                        case SLT_BereqProtocol:
1023
                        case SLT_ReqProtocol:
1024 3360
                                frag_line(0, b, e, &CTX.frag[F_H]);
1025 3360
                                break;
1026
                        case SLT_BerespStatus:
1027
                        case SLT_RespStatus:
1028 2960
                                frag_line(1, b, e, &CTX.frag[F_s]);
1029 2960
                                break;
1030
                        case SLT_BereqAcct:
1031
                        case SLT_ReqAcct:
1032 3000
                                frag_fields(0, b, e,
1033
                                    3, &CTX.frag[F_I],
1034
                                    5, &CTX.frag[F_b],
1035
                                    6, &CTX.frag[F_O],
1036
                                    0, NULL);
1037 3000
                                break;
1038
                        case SLT_Timestamp:
1039
#define ISPREFIX(a, b, c, d)    isprefix(a, strlen(a), b, c, d)
1040 15720
                                if (ISPREFIX("Start:", b, e, &p)) {
1041 3280
                                        frag_fields(0, p, e, 1,
1042
                                            &CTX.frag[F_tstart], 0, NULL);
1043
1044 25320
                                } else if (ISPREFIX("Resp:", b, e, &p) ||
1045 9880
                                    ISPREFIX("PipeSess:", b, e, &p) ||
1046 9600
                                    ISPREFIX("BerespBody:", b, e, &p)) {
1047 3160
                                        frag_fields(0, p, e, 1,
1048
                                            &CTX.frag[F_tend], 0, NULL);
1049
1050 18200
                                } else if (ISPREFIX("Process:", b, e, &p) ||
1051 6040
                                    ISPREFIX("Pipe:", b, e, &p) ||
1052 5760
                                    ISPREFIX("Beresp:", b, e, &p)) {
1053 3840
                                        frag_fields(0, p, e, 2,
1054
                                            &CTX.frag[F_ttfb], 0, NULL);
1055 3840
                                }
1056 15720
                                break;
1057
                        case SLT_BereqHeader:
1058
                        case SLT_ReqHeader:
1059 14080
                                process_hdr(&CTX.watch_reqhdr, b, e);
1060 14080
                                if (ISPREFIX("Authorization:", b, e, &p) &&
1061 560
                                    ISPREFIX("basic ", p, e, &p))
1062 560
                                        frag_line(0, p, e,
1063
                                            &CTX.frag[F_auth]);
1064 13520
                                else if (ISPREFIX("Host:", b, e, &p))
1065 3120
                                        frag_line(0, p, e,
1066
                                            &CTX.frag[F_host]);
1067
#undef ISPREFIX
1068 14080
                                break;
1069
                        case SLT_BerespHeader:
1070
                        case SLT_RespHeader:
1071 19960
                                process_hdr(&CTX.watch_resphdr, b, e);
1072 19960
                                break;
1073
                        case SLT_VCL_call:
1074 11440
                                if (!strcasecmp(b, "recv")) {
1075 2840
                                        CTX.hitmiss = "-";
1076 2840
                                        CTX.handling = "-";
1077 11440
                                } else if (!strcasecmp(b, "hit")) {
1078 640
                                        CTX.hitmiss = "hit";
1079 640
                                        CTX.handling = "hit";
1080 8600
                                } else if (!strcasecmp(b, "miss")) {
1081 1600
                                        CTX.hitmiss = "miss";
1082 1600
                                        CTX.handling = "miss";
1083 7960
                                } else if (!strcasecmp(b, "pass")) {
1084 120
                                        CTX.hitmiss = "miss";
1085 120
                                        CTX.handling = "pass";
1086 6360
                                } else if (!strcasecmp(b, "synth")) {
1087
                                        /* Arguably, synth isn't a hit or
1088
                                           a miss, but miss is less
1089
                                           wrong */
1090 440
                                        CTX.hitmiss = "miss";
1091 440
                                        CTX.handling = "synth";
1092 440
                                }
1093 11440
                                break;
1094
                        case SLT_VCL_return:
1095 11440
                                if (!strcasecmp(b, "pipe")) {
1096 560
                                        CTX.hitmiss = "miss";
1097 560
                                        CTX.handling = "pipe";
1098 11440
                                } else if (!strcasecmp(b, "restart"))
1099 0
                                        skip = 1;
1100 11440
                                break;
1101
                        case SLT_VCL_Log:
1102 440
                                VTAILQ_FOREACH(w, &CTX.watch_vcl_log, list) {
1103 40
                                        CHECK_OBJ_NOTNULL(w, WATCH_MAGIC);
1104 40
                                        if (e - b < w->keylen ||
1105 40
                                            strncmp(b, w->key, w->keylen))
1106 0
                                                continue;
1107 40
                                        p = b + w->keylen;
1108 40
                                        frag_line(0, p, e, &w->frag);
1109 40
                                }
1110 400
                                break;
1111
                        default:
1112 24480
                                break;
1113
                        }
1114
1115 117560
                        process_vsl(&CTX.watch_vsl, tag, b, e);
1116
                }
1117 3280
                if (skip)
1118 0
                        continue;
1119 3280
                i = print();
1120 3280
                if (i)
1121 0
                        return (i);
1122 3280
        }
1123
1124 4200
        return (0);
1125 4200
}
1126
1127
static char *
1128 120
read_format(const char *formatfile)
1129
{
1130
        FILE *fmtfile;
1131 120
        size_t len = 0;
1132
        int fmtlen;
1133 120
        char *fmt = NULL;
1134
1135 120
        fmtfile = fopen(formatfile, "r");
1136 120
        if (fmtfile == NULL)
1137 80
                VUT_Error(vut, 1, "Can't open format file (%s)",
1138 40
                    strerror(errno));
1139 80
        AN(fmtfile);
1140 80
        fmtlen = getline(&fmt, &len, fmtfile);
1141 80
        if (fmtlen == -1) {
1142 40
                free(fmt);
1143 40
                if (feof(fmtfile))
1144 40
                        VUT_Error(vut, 1, "Empty format file");
1145 0
                VUT_Error(vut, 1, "Can't read format from file (%s)",
1146 0
                    strerror(errno));
1147
        }
1148 40
        AZ(fclose(fmtfile));
1149 40
        if (fmt[fmtlen - 1] == '\n')
1150 40
                fmt[fmtlen - 1] = '\0';
1151 40
        return (fmt);
1152
}
1153
1154
int
1155 3400
main(int argc, char * const *argv)
1156
{
1157
        signed char opt;
1158 3400
        char *format = NULL;
1159 3400
        int mode_opt = 0;
1160
1161 3400
        vut = VUT_InitProg(argc, argv, &vopt_spec);
1162 3400
        AN(vut);
1163 3400
        memset(&CTX, 0, sizeof CTX);
1164 3400
        VTAILQ_INIT(&CTX.format);
1165 3400
        VTAILQ_INIT(&CTX.watch_vcl_log);
1166 3400
        VTAILQ_INIT(&CTX.watch_reqhdr);
1167 3400
        VTAILQ_INIT(&CTX.watch_resphdr);
1168 3400
        VTAILQ_INIT(&CTX.watch_vsl);
1169 3400
        CTX.vsb = VSB_new_auto();
1170 3400
        AN(CTX.vsb);
1171 3400
        CTX.quote_how = VSB_QUOTE_ESCHEX;
1172 3400
        REPLACE(CTX.missing_string, "-");
1173 3400
        REPLACE(CTX.missing_int, "-");
1174
1175 2520
        tzset();                // We use localtime_r(3)
1176
1177 10920
        while ((opt = getopt(argc, argv, vopt_spec.vopt_optstring)) != -1) {
1178 8440
                switch (opt) {
1179
                case 'a':
1180
                        /* Append to file */
1181 0
                        CTX.a_opt = 1;
1182 0
                        break;
1183
                case 'b': /* backend mode */
1184
                case 'c': /* client mode */
1185
                case 'E': /* show ESI */
1186 480
                        AN(VUT_Arg(vut, opt, NULL));
1187 480
                        mode_opt = 1;
1188 480
                        break;
1189
                case 'F':
1190 2000
                        if (format != NULL)
1191 0
                                VUT_Error(vut, 1, "Format already set");
1192 2000
                        REPLACE(format, optarg);
1193 2000
                        break;
1194
                case 'f':
1195 40
                        if (format != NULL)
1196 0
                                VUT_Error(vut, 1, "Format already set");
1197
                        /* Format string from file */
1198 40
                        format = read_format(optarg);
1199 40
                        AN(format);
1200 40
                        break;
1201
                case 'h':
1202
                        /* Usage help */
1203 40
                        VUT_Usage(vut, &vopt_spec, 0);
1204
                        break;
1205
                case 'j':
1206 200
                        REPLACE(CTX.missing_string, "");
1207 200
                        REPLACE(CTX.missing_int, "0");
1208 200
                        CTX.quote_how = VSB_QUOTE_JSON;
1209 200
                        break;
1210
                case 'w':
1211
                        /* Write to file */
1212 160
                        REPLACE(CTX.w_arg, optarg);
1213 160
                        break;
1214
                default:
1215 5520
                        if (!VUT_Arg(vut, opt, optarg))
1216 0
                                VUT_Usage(vut, &vopt_spec, 1);
1217 5520
                }
1218
        }
1219
1220
        /* default is client mode: */
1221 2480
        if (!mode_opt)
1222 2320
                AN(VUT_Arg(vut, 'c', NULL));
1223
1224 2480
        if (optind != argc)
1225 40
                VUT_Usage(vut, &vopt_spec, 1);
1226
1227 2120
        if (vut->D_opt && !CTX.w_arg)
1228 40
                VUT_Error(vut, 1, "Missing -w option");
1229
1230 2080
        if (vut->D_opt && !strcmp(CTX.w_arg, "-"))
1231 0
                VUT_Error(vut, 1, "Daemon cannot write to stdout");
1232
1233
        /* Check for valid grouping mode */
1234 2080
        assert(vut->g_arg < VSL_g__MAX);
1235 2080
        if (vut->g_arg != VSL_g_vxid && vut->g_arg != VSL_g_request)
1236 80
                VUT_Error(vut, 1, "Invalid grouping mode: %s",
1237 40
                    VSLQ_grouping[vut->g_arg]);
1238
1239
        /* Prepare output format */
1240 2040
        parse_format(format);
1241 2040
        REPLACE(format, NULL);
1242
1243
        /* Setup output */
1244 2040
        vut->dispatch_f = dispatch_f;
1245 2040
        vut->dispatch_priv = NULL;
1246 2040
        if (CTX.w_arg) {
1247 120
                openout(CTX.a_opt);
1248 120
                AN(CTX.fo);
1249 120
                if (vut->D_opt)
1250 40
                        vut->sighup_f = rotateout;
1251 120
        } else
1252 1920
                CTX.fo = stdout;
1253 2040
        vut->idle_f = flushout;
1254
1255 2040
        VUT_Setup(vut);
1256 2040
        (void)VUT_Main(vut);
1257 2040
        VUT_Fini(&vut);
1258
1259 2040
        exit(0);
1260
}