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
        unsigned                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
        unsigned                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 125
openout(int append)
168
{
169
170 125
        AN(CTX.w_arg);
171 125
        if (!strcmp(CTX.w_arg, "-"))
172 0
                CTX.fo = stdout;
173
        else
174 125
                CTX.fo = fopen(CTX.w_arg, append ? "a" : "w");
175 125
        if (CTX.fo == NULL)
176 50
                VUT_Error(vut, 1, "Can't open output file (%s)",
177 25
                    strerror(errno));
178 100
}
179
180
static int v_matchproto_(VUT_cb_f)
181 25
rotateout(struct VUT *v)
182
{
183
184 25
        assert(v == vut);
185 25
        AN(CTX.w_arg);
186 25
        AN(CTX.fo);
187 25
        (void)fclose(CTX.fo);
188 25
        openout(1);
189 25
        AN(CTX.fo);
190 25
        return (0);
191
}
192
193
static int v_matchproto_(VUT_cb_f)
194 20915
flushout(struct VUT *v)
195
{
196
197 20915
        assert(v == vut);
198 20915
        AN(CTX.fo);
199 20915
        if (fflush(CTX.fo))
200 0
                return (-5);
201 20915
        return (0);
202 20915
}
203
204
static inline int
205 5125
vsb_fcat(struct vsb *vsb, const struct fragment *f, const char *dflt)
206
{
207 5125
        if (f->gen == CTX.gen) {
208 5025
                assert(f->b <= f->e);
209 5025
                VSB_quote(vsb, f->b, f->e - f->b, CTX.quote_how);
210 5125
        } else if (dflt)
211 100
                VSB_quote(vsb, dflt, -1, CTX.quote_how);
212
        else
213 0
                return (-1);
214 5125
        return (0);
215 5125
}
216
217
static int v_matchproto_(format_f)
218 6850
format_string(const struct format *format)
219
{
220
221 6850
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
222 6850
        AN(format->string);
223 6850
        AZ(VSB_cat(CTX.vsb, format->string));
224 6850
        return (1);
225
}
226
227
static int v_matchproto_(format_f)
228 675
format_strptr(const struct format *format)
229
{
230
231 675
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
232 675
        AN(format->strptr);
233 675
        AN(*format->strptr);
234 675
        AZ(VSB_cat(CTX.vsb, *format->strptr));
235 675
        return (1);
236
}
237
238
static int v_matchproto_(format_f)
239 525
format_int64(const struct format *format)
240
{
241
242 525
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
243 525
        VSB_printf(CTX.vsb, "%jd", (intmax_t)*format->int64);
244 525
        return (1);
245
}
246
247
static int v_matchproto_(format_f)
248 4450
format_fragment(const struct format *format)
249
{
250
251 4450
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
252 4450
        AN(format->frag);
253
254 4450
        if (format->frag->gen != CTX.gen) {
255 1150
                if (format->string == NULL)
256 0
                        return (-1);
257 1150
                VSB_quote(CTX.vsb, format->string, -1, CTX.quote_how);
258 1150
                return (0);
259
        }
260 3300
        AZ(vsb_fcat(CTX.vsb, format->frag, NULL));
261 3300
        return (1);
262 4450
}
263
264
static int v_matchproto_(format_f)
265 1500
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 1500
        CHECK_OBJ_NOTNULL(format, FORMAT_MAGIC);
275 1500
        if (CTX.frag[F_tstart].gen == CTX.gen) {
276 1500
                t_start = strtod(CTX.frag[F_tstart].b, &p);
277 1500
                if (p != CTX.frag[F_tstart].e)
278 0
                        t_start = NAN;
279 1500
        } else
280 0
                t_start = NAN;
281 1500
        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 1500
        if (CTX.frag[F_tend].gen == CTX.gen) {
291 1475
                t_end = strtod(CTX.frag[F_tend].b, &p);
292 1475
                if (p != CTX.frag[F_tend].e)
293 0
                        t_end = t_start;
294 1475
        } else
295 25
                t_end = t_start;
296
297 1500
        AN(format->time_fmt);
298
299 1500
        switch (format->time_type) {
300
        case 't':
301 750
                t = (intmax_t)floor(t_start);
302 750
                (void)localtime_r(&t, &tm);
303 750
                AN(strftime(buf, sizeof buf, format->time_fmt, &tm));
304 750
                AZ(VSB_cat(CTX.vsb, buf));
305 750
                return (1);
306
        case '3':
307 75
                l = (intmax_t)(modf(t_start, &d) * 1e3);
308 75
                break;
309
        case '6':
310 75
                l = (intmax_t)(modf(t_start, &d) * 1e6);
311 75
                break;
312
        case 'S':
313 75
                l = (intmax_t)t_start;
314 75
                break;
315
        case 'M':
316 75
                l = (intmax_t)(t_start * 1e3);
317 75
                break;
318
        case 'U':
319 75
                l = (intmax_t)(t_start * 1e6);
320 75
                break;
321
        case 's':
322 150
                l = (intmax_t)(t_end - t_start);
323 150
                break;
324
        case 'm':
325 75
                l = (intmax_t)((t_end - t_start) * 1e3);
326 75
                break;
327
        case 'u':
328 150
                l = (intmax_t)((t_end - t_start) * 1e6);
329 150
                break;
330
        default:
331 0
                WRONG("Time format specifier");
332 0
        }
333
334
#ifdef __FreeBSD__
335 750
        assert(fmtcheck(format->time_fmt, "%jd") == format->time_fmt);
336
#endif
337 750
        AZ(VSB_printf(CTX.vsb, format->time_fmt, l));
338
339 750
        return (1);
340 1500
}
341
342
static int v_matchproto_(format_f)
343 375
format_requestline(const struct format *format)
344
{
345
346 375
        (void)format;
347 375
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_m], "-"));
348 375
        AZ(VSB_putc(CTX.vsb, ' '));
349 375
        if (CTX.frag[F_host].gen == CTX.gen) {
350 325
                if (strncmp(CTX.frag[F_host].b, "http://", 7))
351 325
                        AZ(VSB_cat(CTX.vsb, "http://"));
352 325
                AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_host], NULL));
353 325
        } else
354 50
                AZ(VSB_cat(CTX.vsb, "http://localhost"));
355 375
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_U], ""));
356 375
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_q], ""));
357 375
        AZ(VSB_putc(CTX.vsb, ' '));
358 375
        AZ(vsb_fcat(CTX.vsb, &CTX.frag[F_H], "HTTP/1.0"));
359 375
        return (1);
360
}
361
362
static int v_matchproto_(format_f)
363 400
format_auth(const struct format *format)
364
{
365 400
        struct vsb *vsb = VSB_new_auto();
366 400
        AN(vsb);
367
        char *q;
368
369 400
        if (CTX.frag[F_auth].gen != CTX.gen ||
370 150
            VENC_Decode_Base64(vsb, CTX.frag[F_auth].b, CTX.frag[F_auth].e)) {
371 250
                VSB_destroy(&vsb);
372 250
                if (format->string == NULL)
373 0
                        return (-1);
374 250
                VSB_quote(CTX.vsb, format->string, -1, CTX.quote_how);
375 250
                return (0);
376
        }
377 150
        AZ(VSB_finish(vsb));
378 150
        q = strchr(VSB_data(vsb), ':');
379 150
        if (q != NULL)
380 150
                *q = '\0';
381 150
        VSB_quote(CTX.vsb, VSB_data(vsb), -1, CTX.quote_how);
382 150
        VSB_destroy(&vsb);
383 150
        return (1);
384 400
}
385
386
static int
387 2000
print(void)
388
{
389
        const struct format *f;
390 2000
        int i, r = 1;
391
392 2000
        VSB_clear(CTX.vsb);
393 16775
        VTAILQ_FOREACH(f, &CTX.format, list) {
394 14775
                CHECK_OBJ_NOTNULL(f, FORMAT_MAGIC);
395 14775
                i = (f->func)(f);
396 14775
                AZ(VSB_error(CTX.vsb));
397 14775
                if (r > i)
398 600
                        r = i;
399 14775
        }
400 2000
        AZ(VSB_putc(CTX.vsb, '\n'));
401 2000
        AZ(VSB_finish(CTX.vsb));
402 2000
        if (r >= 0) {
403 2000
                i = fwrite(VSB_data(CTX.vsb), 1, VSB_len(CTX.vsb), CTX.fo);
404 2000
                if (i != VSB_len(CTX.vsb))
405 0
                        return (-5);
406 2000
        }
407 2000
        return (0);
408 2000
}
409
410
static void
411 5125
addf_string(const char *str)
412
{
413
        struct format *f;
414
415 5125
        AN(str);
416 5125
        ALLOC_OBJ(f, FORMAT_MAGIC);
417 5125
        AN(f);
418 5125
        f->func = format_string;
419 5125
        f->string = strdup(str);
420 5125
        AN(f->string);
421 5125
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
422 5125
}
423
424
static void
425 175
addf_strptr(const char *const *strptr)
426
{
427
        struct format *f;
428
429 175
        AN(strptr);
430 175
        ALLOC_OBJ(f, FORMAT_MAGIC);
431 175
        AN(f);
432 175
        f->func = format_strptr;
433 175
        f->strptr = strptr;
434 175
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
435 175
}
436
437
static void
438 2175
addf_fragment(struct fragment *frag, const char *str)
439
{
440
        struct format *f;
441
442 2175
        AN(frag);
443 2175
        ALLOC_OBJ(f, FORMAT_MAGIC);
444 2175
        AN(f);
445 2175
        f->func = format_fragment;
446 2175
        f->frag = frag;
447 2175
        if (str != NULL) {
448 2175
                f->string = strdup(str);
449 2175
                AN(f->string);
450 2175
        }
451 2175
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
452 2175
}
453
454
static void
455 125
addf_int64(int64_t *i)
456
{
457
        struct format *f;
458
459 125
        AN(i);
460 125
        ALLOC_OBJ(f, FORMAT_MAGIC);
461 125
        AN(f);
462 125
        f->func = format_int64;
463 125
        f->int64 = i;
464 125
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
465 125
}
466
467
static void
468 800
addf_time(char type, const char *fmt)
469
{
470
        struct format *f;
471
472 800
        ALLOC_OBJ(f, FORMAT_MAGIC);
473 800
        AN(f);
474 800
        AN(fmt);
475 800
        f->func = format_time;
476 800
        f->time_type = type;
477 800
        f->time_fmt = strdup(fmt);
478
479 800
        if (f->time_type == 'T') {
480 125
                if (!strcmp(fmt, "s"))
481 50
                        f->time_type = 's';
482 75
                else if (!strcmp(fmt, "ms"))
483 25
                        f->time_type = 'm';
484 50
                else if (!strcmp(fmt, "us"))
485 50
                        f->time_type = 'u';
486
                else
487 0
                        VUT_Error(vut, 1, "Unknown specifier: %%{%s}T",
488 0
                            fmt);
489 125
                REPLACE(f->time_fmt, "%jd");
490 800
        } else if (f->time_type == 't') {
491 675
                if (!strcmp(fmt, "sec")) {
492 25
                        f->time_type = 'S';
493 25
                        REPLACE(f->time_fmt, "%jd");
494 675
                } else if (!strncmp(fmt, "msec", 4)) {
495 75
                        fmt += 4;
496 75
                        if (!strcmp(fmt, "_frac")) {
497 25
                                f->time_type = '3';
498 25
                                REPLACE(f->time_fmt, "%03jd");
499 75
                        } else if (*fmt == '\0') {
500 25
                                f->time_type = 'M';
501 25
                                REPLACE(f->time_fmt, "%jd");
502 25
                        }
503 650
                } else if (!strncmp(fmt, "usec", 4)) {
504 75
                        fmt += 4;
505 75
                        if (!strcmp(fmt, "_frac")) {
506 25
                                f->time_type = '6';
507 25
                                REPLACE(f->time_fmt, "%06jd");
508 75
                        } else if (*fmt == '\0') {
509 25
                                f->time_type = 'U';
510 25
                                REPLACE(f->time_fmt, "%jd");
511 25
                        }
512 75
                }
513 675
        }
514
515 800
        AN(f->time_fmt);
516 800
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
517 800
}
518
519
static void
520 475
addf_requestline(void)
521
{
522
        struct format *f;
523
524 475
        ALLOC_OBJ(f, FORMAT_MAGIC);
525 475
        AN(f);
526 475
        f->func = format_requestline;
527 475
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
528 475
}
529
530
static void
531 50
addf_vcl_log(const char *key)
532
{
533
        struct watch *w;
534
        struct format *f;
535
536 50
        AN(key);
537 50
        ALLOC_OBJ(w, WATCH_MAGIC);
538 50
        AN(w);
539 50
        w->keylen = asprintf(&w->key, "%s:", key);
540 50
        assert(w->keylen > 0);
541 50
        VTAILQ_INSERT_TAIL(&CTX.watch_vcl_log, w, list);
542
543 50
        ALLOC_OBJ(f, FORMAT_MAGIC);
544 50
        AN(f);
545 50
        f->func = format_fragment;
546 50
        f->frag = &w->frag;
547 50
        f->string = strdup("");
548 50
        AN(f->string);
549 50
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
550 50
}
551
552
static void
553 1075
addf_hdr(struct watch_head *head, const char *key)
554
{
555
        struct watch *w;
556
        struct format *f;
557
558 1075
        AN(head);
559 1075
        AN(key);
560 1075
        ALLOC_OBJ(w, WATCH_MAGIC);
561 1075
        AN(w);
562 1075
        w->keylen = asprintf(&w->key, "%s:", key);
563 1075
        assert(w->keylen > 0);
564 1075
        VTAILQ_INSERT_TAIL(head, w, list);
565
566 1075
        ALLOC_OBJ(f, FORMAT_MAGIC);
567 1075
        AN(f);
568 1075
        f->func = format_fragment;
569 1075
        f->frag = &w->frag;
570 1075
        f->string = strdup(CTX.missing_string);
571 1075
        AN(f->string);
572 1075
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
573 1075
}
574
575
static void
576 325
addf_vsl(enum VSL_tag_e tag, long i, const char *prefix)
577
{
578
        struct vsl_watch *w;
579
580 325
        ALLOC_OBJ(w, VSL_WATCH_MAGIC);
581 325
        AN(w);
582 325
        if (VSL_tagflags[tag] && CTX.quote_how != VSB_QUOTE_JSON)
583 50
                VUT_Error(vut, 1, "Tag %s can contain control characters",
584 25
                    VSL_tags[tag]);
585 300
        w->tag = tag;
586 300
        assert(i <= INT_MAX);
587 300
        w->idx = i;
588 300
        if (prefix != NULL) {
589 75
                w->prefixlen = asprintf(&w->prefix, "%s:", prefix);
590 75
                assert(w->prefixlen > 0);
591 75
        }
592 300
        VTAILQ_INSERT_TAIL(&CTX.watch_vsl, w, list);
593 300
        addf_fragment(&w->frag, CTX.missing_string);
594 300
}
595
596
static void
597 450
addf_auth(void)
598
{
599
        struct format *f;
600
601 450
        ALLOC_OBJ(f, FORMAT_MAGIC);
602 450
        AN(f);
603 450
        f->func = format_auth;
604 450
        f->string = strdup("-");
605 450
        AN(f->string);
606 450
        VTAILQ_INSERT_TAIL(&CTX.format, f, list);
607 450
}
608
609
static void
610 975
parse_x_format(char *buf)
611
{
612
        char *e, *r, *s;
613
        long lval;
614
        int slt;
615
616 975
        if (!strcmp(buf, "Varnish:time_firstbyte")) {
617 25
                addf_fragment(&CTX.frag[F_ttfb], CTX.missing_int);
618 25
                return;
619
        }
620 950
        if (!strcmp(buf, "Varnish:hitmiss")) {
621 25
                addf_strptr(&CTX.hitmiss);
622 25
                return;
623
        }
624 925
        if (!strcmp(buf, "Varnish:handling")) {
625 25
                addf_strptr(&CTX.handling);
626 25
                return;
627
        }
628 900
        if (!strcmp(buf, "Varnish:side")) {
629 125
                addf_strptr(&CTX.side);
630 125
                return;
631
        }
632 775
        if (!strcmp(buf, "Varnish:vxid")) {
633 125
                addf_int64(&CTX.vxid);
634 125
                return;
635
        }
636 650
        if (!strncmp(buf, "VCL_Log:", 8)) {
637 50
                addf_vcl_log(buf + 8);
638 50
                return;
639
        }
640 600
        if (!strncmp(buf, "VSL:", 4)) {
641 550
                buf += 4;
642 550
                e = buf;
643 5150
                while (*e != '\0')
644 4600
                        e++;
645 550
                if (e == buf)
646 25
                        VUT_Error(vut, 1, "Missing tag in VSL:");
647 525
                if (e[-1] == ']') {
648 300
                        r = e - 1;
649 1250
                        while (r > buf && *r != '[')
650 950
                                r--;
651 300
                        if (r == buf || r[1] == ']')
652 25
                                VUT_Error(vut, 1, "Syntax error: VSL:%s", buf);
653 275
                        e[-1] = '\0';
654 275
                        lval = strtol(r + 1, &s, 10);
655 275
                        if (s != e - 1)
656 25
                                VUT_Error(vut, 1, "Syntax error: VSL:%s]", buf);
657 250
                        if (lval <= 0 || lval > 255) {
658 100
                                VUT_Error(vut, 1,
659
                                    "Syntax error. Field specifier must be"
660
                                    " between 1 and 255: %s]",
661 50
                                    buf);
662
                        }
663 200
                        *r = '\0';
664 200
                } else
665 225
                        lval = 0;
666 425
                r = buf;
667 3575
                while (r < e && *r != ':')
668 3150
                        r++;
669 425
                if (r != e) {
670 75
                        slt = VSL_Name2Tag(buf, r - buf);
671 75
                        r++;
672 75
                } else {
673 350
                        slt = VSL_Name2Tag(buf, -1);
674 350
                        r = NULL;
675
                }
676 425
                if (slt == -2)
677 25
                        VUT_Error(vut, 1, "Tag not unique: %s", buf);
678 400
                if (slt == -1)
679 75
                        VUT_Error(vut, 1, "Unknown log tag: %s", buf);
680 325
                assert(slt >= 0);
681
682 325
                addf_vsl((enum VSL_tag_e)slt, lval, r);
683 325
                return;
684
        }
685 50
        if (!strcmp(buf, "Varnish:default_format")) {
686 25
                parse_format(FORMAT);
687 25
                return;
688
        }
689 25
        VUT_Error(vut, 1, "Unknown formatting extension: %s", buf);
690 725
}
691
692
static void
693 1650
parse_format(const char *format)
694
{
695
        const char *p, *q;
696
        struct vsb *vsb;
697
        char buf[256];
698
        int b;
699
700 1650
        if (format == NULL)
701 375
                format = FORMAT;
702
703 1650
        vsb = VSB_new_auto();
704 1650
        AN(vsb);
705
706 16075
        for (p = format; *p != '\0'; p++) {
707
708
                /* Allow the most essential escape sequences in format */
709 14500
                if (*p == '\\' && p[1] != '\0') {
710 25
                        if (*++p == 't')
711 0
                                AZ(VSB_putc(vsb, '\t'));
712 25
                        else if (*p == 'n')
713 25
                                AZ(VSB_putc(vsb, '\n'));
714
                        else
715 0
                                AZ(VSB_putc(vsb, *p));
716 25
                        continue;
717
                }
718
719 14475
                if (*p != '%') {
720 8350
                        AZ(VSB_putc(vsb, *p));
721 8350
                        continue;
722
                }
723
724 6125
                if (VSB_len(vsb) > 0) {
725 4600
                        AZ(VSB_finish(vsb));
726 4600
                        addf_string(VSB_data(vsb));
727 4600
                        VSB_clear(vsb);
728 4600
                }
729
730 6125
                p++;
731 6125
                switch (*p) {
732
                case 'b':       /* Body bytes sent */
733 475
                        addf_fragment(&CTX.frag[F_b], CTX.missing_int);
734 475
                        break;
735
                case 'D':       /* Float request time */
736 25
                        addf_time('T', "us");
737 25
                        break;
738
                case 'h':       /* Client host name / IP Address */
739 500
                        addf_fragment(&CTX.frag[F_h], CTX.missing_string);
740 500
                        break;
741
                case 'H':       /* Protocol */
742 25
                        addf_fragment(&CTX.frag[F_H], "HTTP/1.0");
743 25
                        break;
744
                case 'I':       /* Bytes received */
745 25
                        addf_fragment(&CTX.frag[F_I], CTX.missing_int);
746 25
                        break;
747
                case 'l':       /* Client user ID (identd) always '-' */
748 425
                        AZ(VSB_putc(vsb, '-'));
749 425
                        break;
750
                case 'm':       /* Method */
751 25
                        addf_fragment(&CTX.frag[F_m], CTX.missing_string);
752 25
                        break;
753
                case 'O':       /* Bytes sent */
754 25
                        addf_fragment(&CTX.frag[F_O], CTX.missing_int);
755 25
                        break;
756
                case 'q':       /* Query string */
757 25
                        addf_fragment(&CTX.frag[F_q], "");
758 25
                        break;
759
                case 'r':       /* Request line */
760 475
                        addf_requestline();
761 475
                        break;
762
                case 's':       /* Status code */
763 725
                        addf_fragment(&CTX.frag[F_s], CTX.missing_int);
764 725
                        break;
765
                case 't':       /* strftime */
766 425
                        addf_time(*p, TIME_FMT);
767 425
                        break;
768
                case 'T':       /* Int request time */
769 25
                        addf_time(*p, "s");
770 25
                        break;
771
                case 'u':       /* Remote user from auth */
772 450
                        addf_auth();
773 450
                        break;
774
                case 'U':       /* URL */
775 25
                        addf_fragment(&CTX.frag[F_U], CTX.missing_string);
776 25
                        break;
777
                case '{':
778 2425
                        p++;
779 2425
                        q = p;
780 2425
                        b = 1;
781 25650
                        while (*q) {
782 25625
                                if (*q == '{')
783 100
                                        b++;
784 25525
                                else if (*q == '}')
785 2500
                                        if (--b == 0)
786 2400
                                                break;
787 23225
                                q++;
788
                        }
789 2425
                        if (b > 0)
790 50
                                VUT_Error(vut, 1, "Unmatched bracket at: %s",
791 25
                                    p - 2);
792 2400
                        assert((unsigned)(q - p) < sizeof buf - 1);
793 2400
                        strncpy(buf, p, q - p);
794 2400
                        buf[q - p] = '\0';
795 2400
                        q++;
796 2400
                        switch (*q) {
797
                        case 'i':
798 1050
                                addf_hdr(&CTX.watch_reqhdr, buf);
799 1050
                                break;
800
                        case 'o':
801 25
                                addf_hdr(&CTX.watch_resphdr, buf);
802 25
                                break;
803
                        case 't':
804 250
                                addf_time(*q, buf);
805 250
                                break;
806
                        case 'T':
807 75
                                addf_time(*q, buf);
808 75
                                break;
809
                        case 'x':
810 975
                                parse_x_format(buf);
811 975
                                break;
812
                        default:
813 50
                                VUT_Error(vut, 1,
814
                                    "Unknown format specifier at: %s",
815 25
                                    p - 2);
816
                        }
817 2375
                        p = q;
818 2375
                        break;
819
                default:
820 50
                        VUT_Error(vut, 1, "Unknown format specifier at: %s",
821 25
                            p - 1);
822
                }
823 6050
        }
824
825 1575
        if (VSB_len(vsb) > 0) {
826
                /* Add any remaining static */
827 525
                AZ(VSB_finish(vsb));
828 525
                addf_string(VSB_data(vsb));
829 525
                VSB_clear(vsb);
830 525
        }
831
832 1575
        VSB_destroy(&vsb);
833 1575
}
834
835
static int
836 63900
isprefix(const char *prefix, size_t len, const char *b,
837
    const char *e, const char **next)
838
{
839 63900
        assert(len > 0);
840 63900
        if (e < b + len || strncasecmp(b, prefix, len))
841 54625
                return (0);
842 9275
        b += len;
843 9275
        if (next) {
844 18100
                while (b < e && *b == ' ')
845 8825
                        b++;
846 9275
                *next = b;
847 9275
        }
848 9275
        return (1);
849 63900
}
850
851
static void
852 10950
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 10950
        AN(b);
860 10950
        AN(e);
861 10950
        va_start(ap, e);
862
863 10950
        n = 0;
864 25650
        while (1) {
865 25725
                field = va_arg(ap, int);
866 25725
                frag = va_arg(ap, struct fragment *);
867 25725
                if (field == 0) {
868 10950
                        AZ(frag);
869 10950
                        break;
870
                }
871 14775
                p = q = NULL;
872 39225
                while (n < field) {
873 37875
                        while (b < e && isspace(*b))
874 13425
                                b++;
875 24450
                        p = b;
876 209025
                        while (b < e && !isspace(*b))
877 184575
                                b++;
878 24450
                        q = b;
879 24450
                        n++;
880
                }
881 14775
                assert(p != NULL && q != NULL);
882 14775
                if (p >= e || q <= p)
883 75
                        continue;
884 14700
                if (frag->gen != CTX.gen || force) {
885
                        /* We only grab the same matching field once */
886 14350
                        frag->gen = CTX.gen;
887 14350
                        frag->b = p;
888 14350
                        frag->e = q;
889 14350
                }
890
        }
891 10950
        va_end(ap);
892 10950
}
893
894
static void
895 13400
frag_line(int force, const char *b, const char *e, struct fragment *f)
896
{
897
898 13400
        if (f->gen == CTX.gen && !force)
899
                /* We only grab the same matching record once */
900 925
                return;
901
902
        /* Skip leading space */
903 12475
        while (b < e && isspace(*b))
904 0
                ++b;
905
906
        /* Skip trailing space */
907 12475
        while (e > b && isspace(e[-1]))
908 0
                --e;
909
910 12475
        f->gen = CTX.gen;
911 12475
        f->b = b;
912 12475
        f->e = e;
913 13400
}
914
915
static void
916 20925
process_hdr(const struct watch_head *head, const char *b, const char *e)
917
{
918
        struct watch *w;
919
        const char *p;
920
921 25225
        VTAILQ_FOREACH(w, head, list) {
922 4300
                CHECK_OBJ_NOTNULL(w, WATCH_MAGIC);
923 4300
                if (!isprefix(w->key, w->keylen, b, e, &p))
924 3950
                        continue;
925 350
                frag_line(1, p, e, &w->frag);
926 350
        }
927 20925
}
928
929
static void
930 72125
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 106025
        VTAILQ_FOREACH(w, head, list) {
936 33900
                CHECK_OBJ_NOTNULL(w, VSL_WATCH_MAGIC);
937 33900
                if (tag != w->tag)
938 32125
                        continue;
939 1775
                p = b;
940 1775
                if (w->prefixlen > 0 &&
941 1050
                    !isprefix(w->prefix, w->prefixlen, b, e, &p))
942 950
                        continue;
943 825
                if (w->idx == 0)
944 150
                        frag_line(0, p, e, &w->frag);
945
                else
946 675
                        frag_fields(0, p, e, w->idx, &w->frag, 0, NULL);
947 825
        }
948 72125
}
949
950
static int v_matchproto_(VSLQ_dispatch_f)
951 2575
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 2575
        (void)vsl;
961 2575
        (void)priv;
962
963 5150
        for (t = pt[0]; t != NULL; t = *++pt) {
964 2575
                CTX.gen++;
965
966 2575
                if (t->type == VSL_t_req) {
967 1800
                        CTX.side = "c";
968 2575
                } else if (t->type == VSL_t_bereq) {
969 200
                        CTX.side = "b";
970 200
                } else
971 575
                        continue;
972
973 2000
                CTX.hitmiss = "-";
974 2000
                CTX.handling = "-";
975 2000
                CTX.vxid = t->vxid;
976 2000
                skip = 0;
977 74200
                while (skip == 0 && 1 == VSL_Next(t->c)) {
978 72200
                        tag = VSL_TAG(t->c->rec.ptr);
979 72200
                        if (VSL_tagflags[tag] &&
980 100
                            CTX.quote_how != VSB_QUOTE_JSON)
981 75
                                continue;
982
983 72125
                        b = VSL_CDATA(t->c->rec.ptr);
984 72125
                        e = b + VSL_LEN(t->c->rec.ptr);
985 72125
                        if (!VSL_tagflags[tag]) {
986 144200
                                while (e > b && e[-1] == '\0')
987 72100
                                        e--;
988 72100
                        }
989
990 72125
                        switch (tag) {
991
                        case SLT_HttpGarbage:
992 0
                                skip = 1;
993 0
                                break;
994
                        case SLT_PipeAcct:
995 175
                                frag_fields(0, b, e,
996
                                    3, &CTX.frag[F_I],
997
                                    4, &CTX.frag[F_O],
998
                                    0, NULL);
999 175
                                break;
1000
                        case SLT_BackendOpen:
1001 200
                                frag_fields(1, b, e,
1002
                                    3, &CTX.frag[F_h],
1003
                                    0, NULL);
1004 200
                                break;
1005
                        case SLT_ReqStart:
1006 1800
                                frag_fields(0, b, e,
1007
                                    1, &CTX.frag[F_h],
1008
                                    0, NULL);
1009 1800
                                break;
1010
                        case SLT_BereqMethod:
1011
                        case SLT_ReqMethod:
1012 1975
                                frag_line(0, b, e, &CTX.frag[F_m]);
1013 1975
                                break;
1014
                        case SLT_BereqURL:
1015
                        case SLT_ReqURL:
1016 2400
                                p = memchr(b, '?', e - b);
1017 2400
                                if (p == NULL)
1018 1950
                                        p = e;
1019 2400
                                frag_line(0, b, p, &CTX.frag[F_U]);
1020 2400
                                frag_line(0, p, e, &CTX.frag[F_q]);
1021 2400
                                break;
1022
                        case SLT_BereqProtocol:
1023
                        case SLT_ReqProtocol:
1024 2050
                                frag_line(0, b, e, &CTX.frag[F_H]);
1025 2050
                                break;
1026
                        case SLT_BerespStatus:
1027
                        case SLT_RespStatus:
1028 1825
                                frag_line(1, b, e, &CTX.frag[F_s]);
1029 1825
                                break;
1030
                        case SLT_BereqAcct:
1031
                        case SLT_ReqAcct:
1032 1825
                                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 1825
                                break;
1038
                        case SLT_Timestamp:
1039
#define ISPREFIX(a, b, c, d)    isprefix(a, strlen(a), b, c, d)
1040 9550
                                if (ISPREFIX("Start:", b, e, &p)) {
1041 2000
                                        frag_fields(0, p, e, 1,
1042
                                            &CTX.frag[F_tstart], 0, NULL);
1043
1044 15325
                                } else if (ISPREFIX("Resp:", b, e, &p) ||
1045 5950
                                    ISPREFIX("PipeSess:", b, e, &p) ||
1046 5775
                                    ISPREFIX("BerespBody:", b, e, &p)) {
1047 1950
                                        frag_fields(0, p, e, 1,
1048
                                            &CTX.frag[F_tend], 0, NULL);
1049
1050 11000
                                } else if (ISPREFIX("Process:", b, e, &p) ||
1051 3625
                                    ISPREFIX("Pipe:", b, e, &p) ||
1052 3450
                                    ISPREFIX("Beresp:", b, e, &p)) {
1053 2325
                                        frag_fields(0, p, e, 2,
1054
                                            &CTX.frag[F_ttfb], 0, NULL);
1055 2325
                                }
1056 9550
                                break;
1057
                        case SLT_BereqHeader:
1058
                        case SLT_ReqHeader:
1059 8525
                                process_hdr(&CTX.watch_reqhdr, b, e);
1060 8525
                                if (ISPREFIX("Authorization:", b, e, &p) &&
1061 325
                                    ISPREFIX("basic ", p, e, &p))
1062 325
                                        frag_line(0, p, e,
1063
                                            &CTX.frag[F_auth]);
1064 8200
                                else if (ISPREFIX("Host:", b, e, &p))
1065 1900
                                        frag_line(0, p, e,
1066
                                            &CTX.frag[F_host]);
1067
#undef ISPREFIX
1068 8525
                                break;
1069
                        case SLT_BerespHeader:
1070
                        case SLT_RespHeader:
1071 12400
                                process_hdr(&CTX.watch_resphdr, b, e);
1072 12400
                                break;
1073
                        case SLT_VCL_call:
1074 7100
                                if (!strcasecmp(b, "recv")) {
1075 1775
                                        CTX.hitmiss = "-";
1076 1775
                                        CTX.handling = "-";
1077 7100
                                } else if (!strcasecmp(b, "hit")) {
1078 400
                                        CTX.hitmiss = "hit";
1079 400
                                        CTX.handling = "hit";
1080 5325
                                } else if (!strcasecmp(b, "miss")) {
1081 1000
                                        CTX.hitmiss = "miss";
1082 1000
                                        CTX.handling = "miss";
1083 4925
                                } else if (!strcasecmp(b, "pass")) {
1084 75
                                        CTX.hitmiss = "miss";
1085 75
                                        CTX.handling = "pass";
1086 3925
                                } else if (!strcasecmp(b, "synth")) {
1087
                                        /* Arguably, synth isn't a hit or
1088
                                           a miss, but miss is less
1089
                                           wrong */
1090 275
                                        CTX.hitmiss = "miss";
1091 275
                                        CTX.handling = "synth";
1092 275
                                }
1093 7100
                                break;
1094
                        case SLT_VCL_return:
1095 7100
                                if (!strcasecmp(b, "pipe")) {
1096 350
                                        CTX.hitmiss = "miss";
1097 350
                                        CTX.handling = "pipe";
1098 7100
                                } else if (!strcasecmp(b, "restart"))
1099 0
                                        skip = 1;
1100 7100
                                break;
1101
                        case SLT_VCL_Log:
1102 275
                                VTAILQ_FOREACH(w, &CTX.watch_vcl_log, list) {
1103 25
                                        CHECK_OBJ_NOTNULL(w, WATCH_MAGIC);
1104 25
                                        if (e - b < w->keylen ||
1105 25
                                            strncmp(b, w->key, w->keylen))
1106 0
                                                continue;
1107 25
                                        p = b + w->keylen;
1108 25
                                        frag_line(0, p, e, &w->frag);
1109 25
                                }
1110 250
                                break;
1111
                        default:
1112 14950
                                break;
1113
                        }
1114
1115 72125
                        process_vsl(&CTX.watch_vsl, tag, b, e);
1116
                }
1117 2000
                if (skip)
1118 0
                        continue;
1119 2000
                i = print();
1120 2000
                if (i)
1121 0
                        return (i);
1122 2000
        }
1123
1124 2575
        return (0);
1125 2575
}
1126
1127
static char *
1128 75
read_format(const char *formatfile)
1129
{
1130
        FILE *fmtfile;
1131 75
        size_t len = 0;
1132
        int fmtlen;
1133 75
        char *fmt = NULL;
1134
1135 75
        fmtfile = fopen(formatfile, "r");
1136 75
        if (fmtfile == NULL)
1137 50
                VUT_Error(vut, 1, "Can't open format file (%s)",
1138 25
                    strerror(errno));
1139 50
        AN(fmtfile);
1140 50
        fmtlen = getline(&fmt, &len, fmtfile);
1141 50
        if (fmtlen == -1) {
1142 25
                free(fmt);
1143 25
                if (feof(fmtfile))
1144 25
                        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 25
        AZ(fclose(fmtfile));
1149 25
        if (fmt[fmtlen - 1] == '\n')
1150 25
                fmt[fmtlen - 1] = '\0';
1151 25
        return (fmt);
1152
}
1153
1154
int
1155 2050
main(int argc, char * const *argv)
1156
{
1157
        signed char opt;
1158 2050
        char *format = NULL;
1159 2050
        int mode_opt = 0;
1160
1161 2050
        vut = VUT_InitProg(argc, argv, &vopt_spec);
1162 2050
        AN(vut);
1163 2050
        memset(&CTX, 0, sizeof CTX);
1164 2050
        VTAILQ_INIT(&CTX.format);
1165 2050
        VTAILQ_INIT(&CTX.watch_vcl_log);
1166 2050
        VTAILQ_INIT(&CTX.watch_reqhdr);
1167 2050
        VTAILQ_INIT(&CTX.watch_resphdr);
1168 2050
        VTAILQ_INIT(&CTX.watch_vsl);
1169 2050
        CTX.vsb = VSB_new_auto();
1170 2050
        AN(CTX.vsb);
1171 2050
        CTX.quote_how = VSB_QUOTE_ESCHEX;
1172 2050
        REPLACE(CTX.missing_string, "-");
1173 2050
        REPLACE(CTX.missing_int, "-");
1174
1175 1600
        tzset();                // We use localtime_r(3)
1176
1177 6775
        while ((opt = getopt(argc, argv, vopt_spec.vopt_optstring)) != -1) {
1178 5200
                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 275
                        AN(VUT_Arg(vut, opt, NULL));
1187 275
                        mode_opt = 1;
1188 275
                        break;
1189
                case 'F':
1190 1225
                        if (format != NULL)
1191 0
                                VUT_Error(vut, 1, "Format already set");
1192 1225
                        REPLACE(format, optarg);
1193 1225
                        break;
1194
                case 'f':
1195 25
                        if (format != NULL)
1196 0
                                VUT_Error(vut, 1, "Format already set");
1197
                        /* Format string from file */
1198 25
                        format = read_format(optarg);
1199 25
                        AN(format);
1200 25
                        break;
1201
                case 'h':
1202
                        /* Usage help */
1203 25
                        VUT_Usage(vut, &vopt_spec, 0);
1204
                        break;
1205
                case 'j':
1206 125
                        REPLACE(CTX.missing_string, "");
1207 125
                        REPLACE(CTX.missing_int, "0");
1208 125
                        CTX.quote_how = VSB_QUOTE_JSON;
1209 125
                        break;
1210
                case 'w':
1211
                        /* Write to file */
1212 100
                        REPLACE(CTX.w_arg, optarg);
1213 100
                        break;
1214
                default:
1215 3425
                        if (!VUT_Arg(vut, opt, optarg))
1216 0
                                VUT_Usage(vut, &vopt_spec, 1);
1217 3425
                }
1218
        }
1219
1220
        /* default is client mode: */
1221 1575
        if (!mode_opt)
1222 1450
                AN(VUT_Arg(vut, 'c', NULL));
1223
1224 1575
        if (optind != argc)
1225 25
                VUT_Usage(vut, &vopt_spec, 1);
1226
1227 1300
        if (vut->D_opt && !CTX.w_arg)
1228 25
                VUT_Error(vut, 1, "Missing -w option");
1229
1230 1275
        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 1275
        assert(vut->g_arg < VSL_g__MAX);
1235 1275
        if (vut->g_arg != VSL_g_vxid && vut->g_arg != VSL_g_request)
1236 50
                VUT_Error(vut, 1, "Invalid grouping mode: %s",
1237 25
                    VSLQ_grouping[vut->g_arg]);
1238
1239
        /* Prepare output format */
1240 1250
        parse_format(format);
1241 1250
        REPLACE(format, NULL);
1242
1243
        /* Setup output */
1244 1250
        vut->dispatch_f = dispatch_f;
1245 1250
        vut->dispatch_priv = NULL;
1246 1250
        if (CTX.w_arg) {
1247 75
                openout(CTX.a_opt);
1248 75
                AN(CTX.fo);
1249 75
                if (vut->D_opt)
1250 25
                        vut->sighup_f = rotateout;
1251 75
        } else
1252 1175
                CTX.fo = stdout;
1253 1250
        vut->idle_f = flushout;
1254
1255 1250
        VUT_Setup(vut);
1256 1250
        (void)VUT_Main(vut);
1257 1250
        VUT_Fini(&vut);
1258
1259 1250
        exit(0);
1260
}