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