varnish-cache/bin/varnishtest/vtc_logexp.c
1
/*-
2
 * Copyright (c) 2008-2015 Varnish Software AS
3
 * All rights reserved.
4
 *
5
 * Author: Martin Blix Grydeland <martin@varnish-software.com>
6
 *
7
 * Redistribution and use in source and binary forms, with or without
8
 * modification, are permitted provided that the following conditions
9
 * are met:
10
 * 1. Redistributions of source code must retain the above copyright
11
 *    notice, this list of conditions and the following disclaimer.
12
 * 2. Redistributions in binary form must reproduce the above copyright
13
 *    notice, this list of conditions and the following disclaimer in the
14
 *    documentation and/or other materials provided with the distribution.
15
 *
16
 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
17
 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
18
 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
19
 * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
20
 * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
21
 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
22
 * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
23
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
24
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
25
 * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
26
 * SUCH DAMAGE.
27
 */
28
29
/* SECTION: logexpect logexpect
30
 *
31
 * Reads the VSL and looks for records matching a given specification. It will
32
 * process records trying to match the first pattern, and when done, will
33
 * continue processing, trying to match the following pattern. If a pattern
34
 * isn't matched, the test will fail.
35
 *
36
 * logexpect threads are declared this way::
37
 *
38
 *         logexpect lNAME -v <id> [-g <grouping>] [-d 0|1] [-q query] \
39
 *                 [vsl arguments] {
40
 *                         expect <skip> <vxid> <tag> <regex>
41
 *                         expect <skip> <vxid> <tag> <regex>
42
 *                         ...
43
 *                 } [-start|-wait]
44
 *
45
 * And once declared, you can start them, or wait on them::
46
 *
47
 *         logexpect lNAME <-start|-wait>
48
 *
49
 * With:
50
 *
51
 * lNAME
52
 *         Name the logexpect thread, it must start with 'l'.
53
 *
54
 * \-v id
55
 *         Specify the varnish instance to use (most of the time, id=v1).
56
 *
57
 * \-g <session|request|vxid|raw
58
 *         Decide how records are grouped, see -g in ``man varnishlog`` for more
59
 *         information.
60
 *
61
 * \-d <0|1>
62
 *         Start processing log records at the head of the log instead of the
63
 *         tail.
64
 *
65
 * \-q query
66
 *         Filter records using a query expression, see ``man vsl-query`` for
67
 *         more information.
68
 *
69
 * \-start
70
 *         Start the logexpect thread in the background.
71
 *
72
 * \-wait
73
 *         Wait for the logexpect thread to finish
74
 *
75
 * VSL arguments (similar to the varnishlog options):
76
 *
77
 * \-b|-c
78
 *         Process only backend/client records.
79
 *
80
 * \-C
81
 *         Use caseless regex
82
 *
83
 * \-i <taglist>
84
 *         Include tags
85
 *
86
 * \-I <[taglist:]regex>
87
 *         Include by regex
88
 *
89
 * \-T <seconds>
90
 *         Transaction end timeout
91
 *
92
 * And the arguments of the specifications lines are:
93
 *
94
 * skip: [uint|*]
95
 *         Max number of record to skip
96
 *
97
 * vxid: [uint|*|=]
98
 *         vxid to match
99
 *
100
 * tag:  [tagname|*|=]
101
 *         Tag to match against
102
 *
103
 * regex:
104
 *         regular expression to match against (optional)
105
 *
106
 * For skip, vxid and tag, '*' matches anything, '=' expects the value of the
107
 * previous matched record.
108
 */
109
110
#include "config.h"
111
112
#include <stdlib.h>
113
#include <stdio.h>
114
#include <string.h>
115
#include <stdint.h>
116
117
#include "vapi/vsm.h"
118
#include "vapi/vsl.h"
119
#include "vtim.h"
120
#include "vre.h"
121
122
#include "vtc.h"
123
124
#define LE_ANY  (-1)
125
#define LE_LAST (-2)
126
127
struct logexp_test {
128
        unsigned                        magic;
129
#define LOGEXP_TEST_MAGIC               0x6F62B350
130
        VTAILQ_ENTRY(logexp_test)       list;
131
132
        struct vsb                      *str;
133
        int                             vxid;
134
        int                             tag;
135
        vre_t                           *vre;
136
        int                             skip_max;
137
};
138
139
struct logexp {
140
        unsigned                        magic;
141
#define LOGEXP_MAGIC                    0xE81D9F1B
142
        VTAILQ_ENTRY(logexp)            list;
143
144
        char                            *name;
145
        char                            *vname;
146
        struct vtclog                   *vl;
147
        char                            run;
148
        VTAILQ_HEAD(,logexp_test)       tests;
149
150
        struct logexp_test              *test;
151
        int                             skip_cnt;
152
        int                             vxid_last;
153
        int                             tag_last;
154
155
        int                             d_arg;
156
        enum VSL_grouping_e             g_arg;
157
        char                            *query;
158
159
        struct vsm                      *vsm;
160
        struct VSL_data                 *vsl;
161
        struct VSLQ                     *vslq;
162
        pthread_t                       tp;
163
};
164
165
static VTAILQ_HEAD(, logexp)            logexps =
166
        VTAILQ_HEAD_INITIALIZER(logexps);
167
168
static void
169 1340
logexp_delete_tests(struct logexp *le)
170
{
171
        struct logexp_test *test;
172
173 1340
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
174 7155
        while (!VTAILQ_EMPTY(&le->tests)) {
175 4475
                test = VTAILQ_FIRST(&le->tests);
176 4475
                CHECK_OBJ_NOTNULL(test, LOGEXP_TEST_MAGIC);
177 4475
                VTAILQ_REMOVE(&le->tests, test, list);
178 4475
                VSB_destroy(&test->str);
179 4475
                if (test->vre)
180 3920
                        VRE_free(&test->vre);
181 4475
                FREE_OBJ(test);
182
        }
183 1340
}
184
185
static void
186 540
logexp_delete(struct logexp *le)
187
{
188 540
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
189 540
        AZ(le->run);
190 540
        AN(le->vsl);
191 540
        VSL_Delete(le->vsl);
192 540
        AZ(le->vslq);
193 540
        logexp_delete_tests(le);
194 540
        free(le->name);
195 540
        free(le->vname);
196 540
        free(le->query);
197 540
        VSM_Destroy(&le->vsm);
198 540
        vtc_logclose(le->vl);
199 540
        FREE_OBJ(le);
200 540
}
201
202
static struct logexp *
203 540
logexp_new(const char *name, const char *varg)
204
{
205
        struct logexp *le;
206
        struct vsb *n_arg;
207
208 540
        ALLOC_OBJ(le, LOGEXP_MAGIC);
209 540
        AN(le);
210 540
        REPLACE(le->name, name);
211 540
        le->vl = vtc_logopen(name);
212 540
        VTAILQ_INIT(&le->tests);
213
214 540
        le->d_arg = 0;
215 540
        le->g_arg = VSL_g_vxid;
216 540
        le->vsm = VSM_New();
217 540
        le->vsl = VSL_New();
218 540
        AN(le->vsm);
219 540
        AN(le->vsl);
220
221 540
        VTAILQ_INSERT_TAIL(&logexps, le, list);
222
223 540
        REPLACE(le->vname, varg);
224
225 540
        n_arg = macro_expandf(le->vl, "${tmpdir}/%s", varg);
226 540
        if (n_arg == NULL)
227 0
                vtc_fatal(le->vl, "-v argument problems");
228 540
        if (VSM_Arg(le->vsm, 'n', VSB_data(n_arg)) <= 0)
229 0
                vtc_fatal(le->vl, "-v argument error: %s",
230 0
                    VSM_Error(le->vsm));
231 540
        VSB_destroy(&n_arg);
232 540
        if (VSM_Attach(le->vsm, -1))
233 0
                vtc_fatal(le->vl, "VSM_Attach: %s", VSM_Error(le->vsm));
234 540
        return (le);
235
}
236
237
static void
238 5285
logexp_next(struct logexp *le)
239
{
240 5285
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
241
242 5285
        if (le->test) {
243 4475
                CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
244 4475
                le->test = VTAILQ_NEXT(le->test, list);
245
        } else
246 810
                le->test = VTAILQ_FIRST(&le->tests);
247
248 5285
        CHECK_OBJ_ORNULL(le->test, LOGEXP_TEST_MAGIC);
249 5285
        if (le->test)
250 4475
                vtc_log(le->vl, 3, "expecting| %s", VSB_data(le->test->str));
251 5285
}
252
253
static int v_matchproto_(VSLQ_dispatch_f)
254 19314
logexp_dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[],
255
    void *priv)
256
{
257
        struct logexp *le;
258
        struct VSL_transaction *t;
259
        int i;
260
        int ok, skip;
261
        int vxid, tag, type, len;
262
        const char *legend, *data;
263
264 19314
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
265
266 38061
        for (i = 0; (t = pt[i]) != NULL; i++) {
267 99523
                while (1 == VSL_Next(t->c)) {
268 61202
                        if (!VSL_Match(vsl, t->c))
269 70
                                continue;
270
271 61184
                        CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
272 61184
                        AN(t->c->rec.ptr);
273 61184
                        vxid = VSL_ID(t->c->rec.ptr);
274 61184
                        tag = VSL_TAG(t->c->rec.ptr);
275 61184
                        data = VSL_CDATA(t->c->rec.ptr);
276 61184
                        len = VSL_LEN(t->c->rec.ptr) - 1;
277
278 61184
                        if (tag == SLT__Batch)
279 0
                                continue;
280
281 61184
                        ok = 1;
282 61184
                        if (le->test->vxid == LE_LAST) {
283 15463
                                if (le->vxid_last != vxid)
284 645
                                        ok = 0;
285 45721
                        } else if (le->test->vxid >= 0) {
286 25407
                                if (le->test->vxid != vxid)
287 18224
                                        ok = 0;
288
                        }
289 61184
                        if (le->test->tag == LE_LAST) {
290 0
                                if (le->tag_last != tag)
291 0
                                        ok = 0;
292 61184
                        } else if (le->test->tag >= 0) {
293 61137
                                if (le->test->tag != tag)
294 55577
                                        ok = 0;
295
                        }
296 111287
                        if (le->test->vre &&
297 100207
                            le->test->tag >= 0 &&
298 55083
                            le->test->tag == tag &&
299 4979
                            VRE_ERROR_NOMATCH == VRE_exec(le->test->vre, data,
300
                                len, 0, 0, NULL, 0, NULL))
301 1034
                                ok = 0;
302
303 61184
                        skip = 0;
304 61209
                        if (!ok && (le->test->skip_max == LE_ANY ||
305 25
                                le->test->skip_max > le->skip_cnt))
306 56679
                                skip = 1;
307
308 61184
                        if (ok)
309 4503
                                legend = "match";
310 56681
                        else if (skip)
311 56681
                                legend = NULL;
312
                        else
313 0
                                legend = "err";
314 80199
                        type = VSL_CLIENT(t->c->rec.ptr) ? 'c' :
315 19015
                            VSL_BACKEND(t->c->rec.ptr) ? 'b' : '-';
316
317 61184
                        if (legend != NULL)
318 4475
                                vtc_log(le->vl, 4, "%3s| %10u %-15s %c %.*s",
319
                                    legend, vxid, VSL_tags[tag], type, len,
320
                                    data);
321
322 61155
                        if (ok) {
323 4475
                                le->vxid_last = vxid;
324 4475
                                le->tag_last = tag;
325 4475
                                le->skip_cnt = 0;
326 4475
                                logexp_next(le);
327 4475
                                if (le->test == NULL)
328
                                        /* End of test script */
329 800
                                        return (1);
330 56680
                        } else if (skip)
331 56680
                                le->skip_cnt++;
332
                        else {
333
                                /* Signal fail */
334 0
                                return (2);
335
                        }
336
                }
337
        }
338
339 18512
        return (0);
340
}
341
342
static void *
343 810
logexp_thread(void *priv)
344
{
345
        struct logexp *le;
346
        int i;
347
348 810
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
349 810
        AN(le->run);
350 810
        AN(le->vsm);
351 810
        AN(le->vslq);
352
353 810
        AZ(le->test);
354 810
        vtc_log(le->vl, 4, "begin|");
355 810
        if (le->query != NULL)
356 285
                vtc_log(le->vl, 4, "qry| %s", le->query);
357 810
        logexp_next(le);
358 65101
        while (le->test) {
359 63481
                i = VSLQ_Dispatch(le->vslq, logexp_dispatch, le);
360 63482
                if (i == 2)
361 0
                        vtc_fatal(le->vl, "bad| expectation failed");
362 63482
                else if (i < 0)
363 0
                        vtc_fatal(le->vl, "bad| dispatch failed (%d)", i);
364 63482
                else if (i == 0 && le->test)
365 26322
                        VTIM_sleep(0.01);
366
        }
367 810
        vtc_log(le->vl, 4, "end|");
368
369 810
        return (NULL);
370
}
371
372
static void
373 810
logexp_close(struct logexp *le)
374
{
375
376 810
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
377 810
        AN(le->vsm);
378 810
        if (le->vslq)
379 810
                VSLQ_Delete(&le->vslq);
380 810
        AZ(le->vslq);
381 810
}
382
383
static void
384 810
logexp_start(struct logexp *le)
385
{
386
        struct VSL_cursor *c;
387
388 810
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
389 810
        AN(le->vsl);
390 810
        AZ(le->vslq);
391
392 810
        AN(le->vsl);
393 810
        (void)VSM_Status(le->vsm);
394 810
        c = VSL_CursorVSM(le->vsl, le->vsm,
395 810
            (le->d_arg ? 0 : VSL_COPT_TAIL) | VSL_COPT_BATCH);
396 810
        if (c == NULL)
397 0
                vtc_fatal(le->vl, "VSL_CursorVSM: %s", VSL_Error(le->vsl));
398 810
        le->vslq = VSLQ_New(le->vsl, &c, le->g_arg, le->query);
399 810
        if (le->vslq == NULL) {
400 0
                VSL_DeleteCursor(c);
401 0
                vtc_fatal(le->vl, "VSLQ_New: %s", VSL_Error(le->vsl));
402
        }
403 810
        AZ(c);
404
405 810
        le->test = NULL;
406 810
        le->skip_cnt = 0;
407 810
        le->vxid_last = le->tag_last = -1;
408 810
        le->run = 1;
409 810
        AZ(pthread_create(&le->tp, NULL, logexp_thread, le));
410 810
}
411
412
static void
413 810
logexp_wait(struct logexp *le)
414
{
415
        void *res;
416
417 810
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
418 810
        vtc_log(le->vl, 2, "Waiting for logexp");
419 810
        AZ(pthread_join(le->tp, &res));
420 810
        logexp_close(le);
421 810
        if (res != NULL && !vtc_stop)
422 0
                vtc_fatal(le->vl, "logexp returned \"%p\"", (char *)res);
423 810
        le->run = 0;
424 810
}
425
426
static void
427 4475
cmd_logexp_expect(CMD_ARGS)
428
{
429
        struct logexp *le;
430
        int skip_max;
431
        int vxid;
432
        int tag;
433
        vre_t *vre;
434
        const char *err;
435
        int pos;
436
        struct logexp_test *test;
437
        char *end;
438
439
        (void)cmd;
440 4475
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
441 4475
        if (av[1] == NULL || av[2] == NULL || av[3] == NULL)
442 0
                vtc_fatal(vl, "Syntax error");
443
444 4475
        if (av[4] != NULL && av[5] != NULL)
445 0
                vtc_fatal(vl, "Syntax error");
446
447 4475
        if (!strcmp(av[1], "*"))
448 2120
                skip_max = LE_ANY;
449
        else {
450 2355
                skip_max = (int)strtol(av[1], &end, 10);
451 2355
                if (*end != '\0' || skip_max < 0)
452 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[1]);
453
        }
454 4475
        if (!strcmp(av[2], "*"))
455 645
                vxid = LE_ANY;
456 3830
        else if (!strcmp(av[2], "="))
457 1830
                vxid = LE_LAST;
458
        else {
459 2000
                vxid = (int)strtol(av[2], &end, 10);
460 2000
                if (*end != '\0' || vxid < 0)
461 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[2]);
462
        }
463 4475
        if (!strcmp(av[3], "*"))
464 0
                tag = LE_ANY;
465 4475
        else if (!strcmp(av[3], "="))
466 0
                tag = LE_LAST;
467
        else {
468 4475
                tag = VSL_Name2Tag(av[3], strlen(av[3]));
469 4475
                if (tag < 0)
470 0
                        vtc_fatal(vl, "Unknown tag name: '%s'", av[3]);
471
        }
472 4475
        vre = NULL;
473 4475
        if (av[4]) {
474 3920
                vre = VRE_compile(av[4], 0, &err, &pos);
475 3920
                if (vre == NULL)
476 0
                        vtc_fatal(vl, "Regex error (%s): '%s' pos %d",
477 0
                            err, av[4], pos);
478
        }
479
480 4475
        ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
481 4475
        AN(test);
482 4475
        test->str = VSB_new_auto();
483 4475
        AN(test->str);
484 4475
        AZ(VSB_printf(test->str, "%s %s %s %s ", av[0], av[1], av[2], av[3]));
485 4475
        if (av[4])
486 3920
                VSB_quote(test->str, av[4], -1, 0);
487 4475
        AZ(VSB_finish(test->str));
488 4475
        test->skip_max = skip_max;
489 4475
        test->vxid = vxid;
490 4475
        test->tag = tag;
491 4475
        test->vre = vre;
492 4475
        VTAILQ_INSERT_TAIL(&le->tests, test, list);
493 4475
}
494
495
static const struct cmds logexp_cmds[] = {
496
        { "expect",             cmd_logexp_expect },
497
        { NULL,                 NULL },
498
};
499
500
static void
501 800
logexp_spec(struct logexp *le, const char *spec)
502
{
503 800
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
504
505 800
        logexp_delete_tests(le);
506
507 800
        parse_string(spec, logexp_cmds, le, le->vl);
508 800
}
509
510
void
511 5215
cmd_logexpect(CMD_ARGS)
512
{
513
        struct logexp *le, *le2;
514
        int i;
515
516
        (void)priv;
517
        (void)cmd;
518
519 5215
        if (av == NULL) {
520
                /* Reset and free */
521 4355
                VTAILQ_FOREACH_SAFE(le, &logexps, list, le2) {
522 540
                        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
523 540
                        VTAILQ_REMOVE(&logexps, le, list);
524 540
                        if (le->run) {
525 5
                                (void)pthread_cancel(le->tp);
526 5
                                logexp_wait(le);
527
                        }
528 540
                        logexp_delete(le);
529
                }
530 3815
                return;
531
        }
532
533 1400
        AZ(strcmp(av[0], "logexpect"));
534 1400
        av++;
535
536 1400
        VTC_CHECK_NAME(vl, av[0], "Logexpect", 'l');
537 1670
        VTAILQ_FOREACH(le, &logexps, list) {
538 1130
                if (!strcmp(le->name, av[0]))
539 860
                        break;
540
        }
541 1400
        if (le == NULL) {
542 540
                if (strcmp(av[1], "-v") || av[2] == NULL)
543 0
                        vtc_fatal(vl, "new logexp lacks -v");
544 540
                le = logexp_new(av[0], av[2]);
545 540
                av += 2;
546
        }
547 1400
        av++;
548
549 5100
        for (; *av != NULL; av++) {
550 3700
                if (vtc_error)
551 0
                        break;
552 3700
                if (!strcmp(*av, "-wait")) {
553 580
                        if (!le->run)
554 0
                                vtc_fatal(le->vl, "logexp not -started '%s'",
555
                                        *av);
556 580
                        logexp_wait(le);
557 580
                        continue;
558
                }
559
560
                /*
561
                 * We do an implict -wait if people muck about with a
562
                 * running logexp.
563
                 */
564 3120
                if (le->run)
565 0
                        logexp_wait(le);
566 3120
                AZ(le->run);
567
568 3120
                if (!strcmp(*av, "-v")) {
569 125
                        if (av[1] == NULL || strcmp(av[1], le->vname))
570 0
                                vtc_fatal(le->vl, "-v argument cannot change");
571 125
                        av++;
572 125
                        continue;
573
                }
574 2995
                if (!strcmp(*av, "-d")) {
575 340
                        if (av[1] == NULL)
576 0
                                vtc_fatal(le->vl, "Missing -d argument");
577 340
                        le->d_arg = atoi(av[1]);
578 340
                        av++;
579 340
                        continue;
580
                }
581 2655
                if (!strcmp(*av, "-g")) {
582 740
                        if (av[1] == NULL)
583 0
                                vtc_fatal(le->vl, "Missing -g argument");
584 740
                        i = VSLQ_Name2Grouping(av[1], strlen(av[1]));
585 740
                        if (i < 0)
586 0
                                vtc_fatal(le->vl, "Unknown grouping '%s'",
587 0
                                    av[1]);
588 740
                        le->g_arg = (enum VSL_grouping_e)i;
589 740
                        av++;
590 740
                        continue;
591
                }
592 1915
                if (!strcmp(*av, "-q")) {
593 285
                        if (av[1] == NULL)
594 0
                                vtc_fatal(le->vl, "Missing -q argument");
595 285
                        REPLACE(le->query, av[1]);
596 285
                        av++;
597 285
                        continue;
598
                }
599 1630
                if (!strcmp(*av, "-start")) {
600 585
                        logexp_start(le);
601 585
                        continue;
602
                }
603 1045
                if (!strcmp(*av, "-run")) {
604 225
                        logexp_start(le);
605 225
                        logexp_wait(le);
606 225
                        continue;
607
                }
608 820
                if (**av == '-') {
609 20
                        if (av[1] != NULL) {
610 20
                                if (VSL_Arg(le->vsl, av[0][1], av[1])) {
611 20
                                        av++;
612 20
                                        continue;
613
                                }
614 0
                                vtc_fatal(le->vl, "%s", VSL_Error(le->vsl));
615
                        }
616 0
                        vtc_fatal(le->vl, "Unknown logexp argument: %s", *av);
617
                }
618 800
                logexp_spec(le, *av);
619
        }
620
}