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
        int                             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 234
logexp_delete_tests(struct logexp *le)
170
{
171
        struct logexp_test *test;
172
173 234
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
174 1294
        while ((test = VTAILQ_FIRST(&le->tests))) {
175 826
                CHECK_OBJ_NOTNULL(test, LOGEXP_TEST_MAGIC);
176 826
                VTAILQ_REMOVE(&le->tests, test, list);
177 826
                VSB_destroy(&test->str);
178 826
                if (test->vre)
179 722
                        VRE_free(&test->vre);
180 826
                FREE_OBJ(test);
181
        }
182 234
}
183
184
static void
185 93
logexp_delete(struct logexp *le)
186
{
187 93
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
188 93
        AZ(le->run);
189 93
        AN(le->vsl);
190 93
        VSL_Delete(le->vsl);
191 93
        AZ(le->vslq);
192 93
        logexp_delete_tests(le);
193 93
        free(le->name);
194 93
        free(le->query);
195 93
        VSM_Destroy(&le->vsm);
196 93
        FREE_OBJ(le);
197 93
}
198
199
static struct logexp *
200 93
logexp_new(const char *name, const char *varg)
201
{
202
        struct logexp *le;
203
        struct vsb *vsb, *n_arg;
204
205 93
        ALLOC_OBJ(le, LOGEXP_MAGIC);
206 93
        AN(le);
207 93
        REPLACE(le->name, name);
208 93
        le->vl = vtc_logopen(name);
209 93
        VTAILQ_INIT(&le->tests);
210
211 93
        le->d_arg = 0;
212 93
        le->g_arg = VSL_g_vxid;
213 93
        le->vsm = VSM_New();
214 93
        le->vsl = VSL_New();
215 93
        AN(le->vsm);
216 93
        AN(le->vsl);
217
218 93
        VTAILQ_INSERT_TAIL(&logexps, le, list);
219
220 93
        REPLACE(le->vname, varg);
221
222 93
        vsb = VSB_new_auto();
223 93
        AN(vsb);
224 93
        AZ(VSB_printf(vsb, "${tmpdir}/%s", varg));
225 93
        AZ(VSB_finish(vsb));
226 93
        n_arg = macro_expand(le->vl, VSB_data(vsb));
227 93
        VSB_destroy(&vsb);
228 93
        if (n_arg == NULL)
229 0
                vtc_fatal(le->vl, "-v argument problems");
230 93
        if (VSM_Arg(le->vsm, 'n', VSB_data(n_arg)) <= 0)
231 0
                vtc_fatal(le->vl, "-v argument error: %s",
232 0
                    VSM_Error(le->vsm));
233 93
        VSB_destroy(&n_arg);
234 93
        if (VSM_Attach(le->vsm, -1))
235 0
                vtc_fatal(le->vl, "VSM_Attach: %s", VSM_Error(le->vsm));
236 93
        return (le);
237
}
238
239
static void
240 967
logexp_next(struct logexp *le)
241
{
242 967
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
243
244 967
        if (le->test) {
245 826
                CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
246 826
                le->test = VTAILQ_NEXT(le->test, list);
247
        } else
248 141
                le->test = VTAILQ_FIRST(&le->tests);
249
250 967
        CHECK_OBJ_ORNULL(le->test, LOGEXP_TEST_MAGIC);
251 967
        if (le->test)
252 826
                vtc_log(le->vl, 3, "expecting| %s", VSB_data(le->test->str));
253 967
}
254
255
static int v_matchproto_(VSLQ_dispatch_f)
256 2800
logexp_dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[],
257
    void *priv)
258
{
259
        struct logexp *le;
260
        struct VSL_transaction *t;
261
        int i;
262
        int ok, skip;
263
        int vxid, tag, type, len;
264
        const char *legend, *data;
265
266 2800
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
267
268 5505
        for (i = 0; (t = pt[i]); i++) {
269 16412
                while (1 == VSL_Next(t->c)) {
270 10857
                        if (!VSL_Match(vsl, t->c))
271 13
                                continue;
272
273 10860
                        CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
274 10860
                        AN(t->c->rec.ptr);
275 10860
                        vxid = VSL_ID(t->c->rec.ptr);
276 10860
                        tag = VSL_TAG(t->c->rec.ptr);
277 10860
                        data = VSL_CDATA(t->c->rec.ptr);
278 10860
                        len = VSL_LEN(t->c->rec.ptr) - 1;
279
280 10860
                        if (tag == SLT__Batch)
281 0
                                continue;
282
283 10860
                        ok = 1;
284 10860
                        if (le->test->vxid == LE_LAST) {
285 2922
                                if (le->vxid_last != vxid)
286 136
                                        ok = 0;
287 7938
                        } else if (le->test->vxid >= 0) {
288 3727
                                if (le->test->vxid != vxid)
289 2492
                                        ok = 0;
290
                        }
291 10860
                        if (le->test->tag == LE_LAST) {
292 0
                                if (le->tag_last != tag)
293 0
                                        ok = 0;
294 10860
                        } else if (le->test->tag >= 0) {
295 10843
                                if (le->test->tag != tag)
296 9820
                                        ok = 0;
297
                        }
298 19500
                        if (le->test->vre &&
299 17279
                            le->test->tag >= 0 &&
300 9553
                            le->test->tag == tag &&
301 915
                            VRE_ERROR_NOMATCH == VRE_exec(le->test->vre, data,
302
                                len, 0, 0, NULL, 0, NULL))
303 187
                                ok = 0;
304
305 10859
                        skip = 0;
306 11223
                        if (!ok && (le->test->skip_max == LE_ANY ||
307 364
                                le->test->skip_max > le->skip_cnt))
308 10019
                                skip = 1;
309
310 10859
                        if (ok)
311 837
                                legend = "match";
312 10022
                        else if (skip)
313 10022
                                legend = NULL;
314
                        else
315 0
                                legend = "err";
316 14522
                        type = VSL_CLIENT(t->c->rec.ptr) ? 'c' :
317 3663
                            VSL_BACKEND(t->c->rec.ptr) ? 'b' : '-';
318
319 10859
                        if (legend != NULL)
320 826
                                vtc_log(le->vl, 4, "%3s| %10u %-15s %c %.*s",
321
                                    legend, vxid, VSL_tags[tag], type, len,
322
                                    data);
323
324 10846
                        if (ok) {
325 826
                                le->vxid_last = vxid;
326 826
                                le->tag_last = tag;
327 826
                                le->skip_cnt = 0;
328 826
                                logexp_next(le);
329 826
                                if (le->test == NULL)
330
                                        /* End of test script */
331 141
                                        return (1);
332 10020
                        } else if (skip)
333 10020
                                le->skip_cnt++;
334
                        else {
335
                                /* Signal fail */
336 0
                                return (2);
337
                        }
338
                }
339
        }
340
341 2658
        return (0);
342
}
343
344
static void *
345 141
logexp_thread(void *priv)
346
{
347
        struct logexp *le;
348
        int i;
349
350 141
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
351 141
        AN(le->run);
352 141
        AN(le->vsm);
353 141
        AN(le->vslq);
354
355 141
        AZ(le->test);
356 141
        vtc_log(le->vl, 4, "begin|");
357 141
        if (le->query != NULL)
358 53
                vtc_log(le->vl, 4, "qry| %s", le->query);
359 141
        logexp_next(le);
360 10345
        while (le->test) {
361 10063
                i = VSLQ_Dispatch(le->vslq, logexp_dispatch, le);
362 10063
                if (i == 2)
363 0
                        vtc_fatal(le->vl, "bad| expectation failed");
364 10063
                else if (i < 0)
365 0
                        vtc_fatal(le->vl, "bad| dispatch failed (%d)", i);
366 10063
                else if (i == 0 && le->test)
367 3865
                        VTIM_sleep(0.01);
368
        }
369 141
        vtc_log(le->vl, 4, "end|");
370
371 141
        return (NULL);
372
}
373
374
static void
375 141
logexp_close(struct logexp *le)
376
{
377
378 141
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
379 141
        AN(le->vsm);
380 141
        if (le->vslq)
381 141
                VSLQ_Delete(&le->vslq);
382 141
        AZ(le->vslq);
383 141
}
384
385
static void
386 141
logexp_start(struct logexp *le)
387
{
388
        struct VSL_cursor *c;
389
390 141
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
391 141
        AN(le->vsl);
392 141
        AZ(le->vslq);
393
394 141
        AN(le->vsl);
395 141
        (void)VSM_Status(le->vsm);
396 141
        c = VSL_CursorVSM(le->vsl, le->vsm,
397 141
            (le->d_arg ? 0 : VSL_COPT_TAIL) | VSL_COPT_BATCH);
398 141
        if (c == NULL)
399 0
                vtc_fatal(le->vl, "VSL_CursorVSM: %s", VSL_Error(le->vsl));
400 141
        le->vslq = VSLQ_New(le->vsl, &c, le->g_arg, le->query);
401 141
        if (le->vslq == NULL) {
402 0
                VSL_DeleteCursor(c);
403 0
                vtc_fatal(le->vl, "VSLQ_New: %s", VSL_Error(le->vsl));
404
        }
405 141
        AZ(c);
406
407 141
        le->test = NULL;
408 141
        le->skip_cnt = 0;
409 141
        le->vxid_last = le->tag_last = -1;
410 141
        le->run = 1;
411 141
        AZ(pthread_create(&le->tp, NULL, logexp_thread, le));
412 141
}
413
414
static void
415 141
logexp_wait(struct logexp *le)
416
{
417
        void *res;
418
419 141
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
420 141
        vtc_log(le->vl, 2, "Waiting for logexp");
421 141
        AZ(pthread_join(le->tp, &res));
422 141
        logexp_close(le);
423 141
        if (res != NULL && !vtc_stop)
424 0
                vtc_fatal(le->vl, "logexp returned \"%p\"", (char *)res);
425 141
        le->run = 0;
426 141
}
427
428
static void
429 826
cmd_logexp_expect(CMD_ARGS)
430
{
431
        struct logexp *le;
432
        int skip_max;
433
        int vxid;
434
        int tag;
435
        vre_t *vre;
436
        const char *err;
437
        int pos;
438
        struct logexp_test *test;
439
        char *end;
440
441
        (void)cmd;
442 826
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
443 826
        if (av[1] == NULL || av[2] == NULL || av[3] == NULL)
444 0
                vtc_fatal(vl, "Syntax error");
445
446 826
        if (av[4] != NULL && av[5] != NULL)
447 0
                vtc_fatal(vl, "Syntax error");
448
449 826
        if (!strcmp(av[1], "*"))
450 355
                skip_max = LE_ANY;
451
        else {
452 471
                skip_max = (int)strtol(av[1], &end, 10);
453 471
                if (*end != '\0' || skip_max < 0)
454 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[1]);
455
        }
456 826
        if (!strcmp(av[2], "*"))
457 123
                vxid = LE_ANY;
458 703
        else if (!strcmp(av[2], "="))
459 341
                vxid = LE_LAST;
460
        else {
461 362
                vxid = (int)strtol(av[2], &end, 10);
462 362
                if (*end != '\0' || vxid < 0)
463 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[2]);
464
        }
465 826
        if (!strcmp(av[3], "*"))
466 0
                tag = LE_ANY;
467 826
        else if (!strcmp(av[3], "="))
468 0
                tag = LE_LAST;
469
        else {
470 826
                tag = VSL_Name2Tag(av[3], strlen(av[3]));
471 826
                if (tag < 0)
472 0
                        vtc_fatal(vl, "Unknown tag name: '%s'", av[3]);
473
        }
474 826
        vre = NULL;
475 826
        if (av[4]) {
476 722
                vre = VRE_compile(av[4], 0, &err, &pos);
477 722
                if (vre == NULL)
478 0
                        vtc_fatal(vl, "Regex error (%s): '%s' pos %d",
479 0
                            err, av[4], pos);
480
        }
481
482 826
        ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
483 826
        AN(test);
484 826
        test->str = VSB_new_auto();
485 826
        AN(test->str);
486 826
        AZ(VSB_printf(test->str, "%s %s %s %s ", av[0], av[1], av[2], av[3]));
487 826
        if (av[4])
488 722
                VSB_quote(test->str, av[4], -1, 0);
489 826
        AZ(VSB_finish(test->str));
490 826
        test->skip_max = skip_max;
491 826
        test->vxid = vxid;
492 826
        test->tag = tag;
493 826
        test->vre = vre;
494 826
        VTAILQ_INSERT_TAIL(&le->tests, test, list);
495 826
}
496
497
static const struct cmds logexp_cmds[] = {
498
        { "expect",             cmd_logexp_expect },
499
        { NULL,                 NULL },
500
};
501
502
static void
503 141
logexp_spec(struct logexp *le, const char *spec)
504
{
505 141
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
506
507 141
        logexp_delete_tests(le);
508
509 141
        parse_string(spec, logexp_cmds, le, le->vl);
510 141
}
511
512
void
513 925
cmd_logexpect(CMD_ARGS)
514
{
515
        struct logexp *le, *le2;
516
517
        (void)priv;
518
        (void)cmd;
519
520 925
        if (av == NULL) {
521
                /* Reset and free */
522 771
                VTAILQ_FOREACH_SAFE(le, &logexps, list, le2) {
523 93
                        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
524 93
                        VTAILQ_REMOVE(&logexps, le, list);
525 93
                        if (le->run) {
526 1
                                (void)pthread_cancel(le->tp);
527 1
                                logexp_wait(le);
528
                        }
529 93
                        logexp_delete(le);
530
                }
531 1603
                return;
532
        }
533
534 247
        AZ(strcmp(av[0], "logexpect"));
535 247
        av++;
536
537 247
        VTC_CHECK_NAME(vl, av[0], "Logexpect", 'l');
538 292
        VTAILQ_FOREACH(le, &logexps, list) {
539 199
                if (!strcmp(le->name, av[0]))
540 154
                        break;
541
        }
542 247
        if (le == NULL) {
543 93
                if (strcmp(av[1], "-v") || av[2] == NULL)
544 0
                        vtc_fatal(vl, "new logexp lacks -v");
545 93
                le = logexp_new(av[0], av[2]);
546 93
                av += 2;
547
        }
548 247
        av++;
549
550 892
        for (; *av != NULL; av++) {
551 645
                if (vtc_error)
552 0
                        break;
553 645
                if (!strcmp(*av, "-wait")) {
554 103
                        if (!le->run)
555 0
                                vtc_fatal(le->vl, "logexp not -started '%s'",
556
                                        *av);
557 103
                        logexp_wait(le);
558 103
                        continue;
559
                }
560
561
                /*
562
                 * We do an implict -wait if people muck about with a
563
                 * running logexp.
564
                 */
565 542
                if (le->run)
566 0
                        logexp_wait(le);
567 542
                AZ(le->run);
568
569 542
                if (!strcmp(*av, "-v")) {
570 19
                        if (av[1] == NULL || strcmp(av[1], le->vname))
571 0
                                vtc_fatal(le->vl, "-v argument cannot change");
572 19
                        av++;
573 19
                        continue;
574
                }
575 523
                if (!strcmp(*av, "-d")) {
576 58
                        if (av[1] == NULL)
577 0
                                vtc_fatal(le->vl, "Missing -d argument");
578 58
                        le->d_arg = atoi(av[1]);
579 58
                        av++;
580 58
                        continue;
581
                }
582 465
                if (!strcmp(*av, "-g")) {
583 128
                        if (av[1] == NULL)
584 0
                                vtc_fatal(le->vl, "Missing -g argument");
585 128
                        le->g_arg = VSLQ_Name2Grouping(av[1], strlen(av[1]));
586 128
                        if (le->g_arg < 0)
587 0
                                vtc_fatal(le->vl, "Unknown grouping '%s'",
588 0
                                    av[1]);
589 128
                        av++;
590 128
                        continue;
591
                }
592 337
                if (!strcmp(*av, "-q")) {
593 53
                        if (av[1] == NULL)
594 0
                                vtc_fatal(le->vl, "Missing -q argument");
595 53
                        REPLACE(le->query, av[1]);
596 53
                        av++;
597 53
                        continue;
598
                }
599 284
                if (!strcmp(*av, "-start")) {
600 104
                        logexp_start(le);
601 104
                        continue;
602
                }
603 180
                if (!strcmp(*av, "-run")) {
604 37
                        logexp_start(le);
605 37
                        logexp_wait(le);
606 37
                        continue;
607
                }
608 143
                if (**av == '-') {
609 2
                        if (av[1] != NULL) {
610 2
                                if (VSL_Arg(le->vsl, av[0][1], av[1])) {
611 2
                                        av++;
612 2
                                        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 141
                logexp_spec(le, *av);
619
        }
620
}