varnish-cache/bin/varnishtest/vtc_logexp.c
0
/*-
1
 * Copyright (c) 2008-2015 Varnish Software AS
2
 * All rights reserved.
3
 *
4
 * Author: Martin Blix Grydeland <martin@varnish-software.com>
5
 *
6
 * SPDX-License-Identifier: BSD-2-Clause
7
 *
8
 * Redistribution and use in source and binary forms, with or without
9
 * modification, are permitted provided that the following conditions
10
 * are met:
11
 * 1. Redistributions of source code must retain the above copyright
12
 *    notice, this list of conditions and the following disclaimer.
13
 * 2. Redistributions in binary form must reproduce the above copyright
14
 *    notice, this list of conditions and the following disclaimer in the
15
 *    documentation and/or other materials provided with the distribution.
16
 *
17
 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
18
 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
19
 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
20
 * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
21
 * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
22
 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
23
 * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
24
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
25
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
26
 * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
27
 * SUCH DAMAGE.
28
 */
29
30
#ifdef VTEST_WITH_VTC_LOGEXPECT
31
32
/* SECTION: logexpect logexpect
33
 *
34
 * Reads the VSL and looks for records matching a given specification. It will
35
 * process records trying to match the first pattern, and when done, will
36
 * continue processing, trying to match the following pattern. If a pattern
37
 * isn't matched, the test will fail.
38
 *
39
 * logexpect threads are declared this way::
40
 *
41
 *         logexpect lNAME -v <id> [-g <grouping>] [-d 0|1] [-q query] \
42
 *                 [vsl arguments] {
43
 *                         expect <skip> <vxid> <tag> <regex>
44
 *                         expect <skip> <vxid> <tag> <regex>
45
 *                         fail add <vxid> <tag> <regex>
46
 *                         fail clear
47
 *                         abort
48
 *                         ...
49
 *                 } [-start|-wait|-run]
50
 *
51
 * And once declared, you can start them, or wait on them::
52
 *
53
 *         logexpect lNAME <-start|-wait>
54
 *
55
 * With:
56
 *
57
 * lNAME
58
 *         Name the logexpect thread, it must start with 'l'.
59
 *
60
 * \-v id
61
 *         Specify the varnish instance to use (most of the time, id=v1).
62
 *
63
 * \-g <session|request|vxid|raw
64
 *         Decide how records are grouped, see -g in ``man varnishlog`` for more
65
 *         information.
66
 *
67
 * \-d <0|1>
68
 *         Start processing log records at the head of the log instead of the
69
 *         tail.
70
 *
71
 * \-q query
72
 *         Filter records using a query expression, see ``man vsl-query`` for
73
 *         more information. Multiple -q options are not supported.
74
 *
75
 * \-m
76
 *         Also emit log records for misses (only for debugging)
77
 *
78
 * \-err
79
 *         Invert the meaning of success. Usually called once to expect the
80
 *         logexpect to fail
81
 *
82
 * \-start
83
 *         Start the logexpect thread in the background.
84
 *
85
 * \-wait
86
 *         Wait for the logexpect thread to finish
87
 *
88
 * \-run
89
 *        Equivalent to "-start -wait".
90
 *
91
 * VSL arguments (similar to the varnishlog options):
92
 *
93
 * \-C
94
 *         Use caseless regex
95
 *
96
 * \-i <taglist>
97
 *         Include tags
98
 *
99
 * \-I <[taglist:]regex>
100
 *         Include by regex
101
 *
102
 * \-T <seconds>
103
 *         Transaction end timeout
104
 *
105
 * expect specification:
106
 *
107
 * skip: [uint|*|?]
108
 *         Max number of record to skip
109
 *
110
 * vxid: [uint|*|=]
111
 *         vxid to match
112
 *
113
 * tag:  [tagname|*|=]
114
 *         Tag to match against
115
 *
116
 * regex:
117
 *         regular expression to match against (optional)
118
 *
119
 * For skip, vxid and tag, '*' matches anything, '=' expects the value of the
120
 * previous matched record. The '?' marker is equivalent to zero, expecting a
121
 * match on the next record. The difference is that '?' can be used when the
122
 * order of individual consecutive logs is not deterministic. In other words,
123
 * lines from a block of alternatives marked by '?' can be matched in any order,
124
 * but all need to match eventually.
125
 *
126
 * fail specification:
127
 *
128
 * add: Add to the fail list
129
 *
130
 *      Arguments are equivalent to expect, except for skip missing
131
 *
132
 * clear: Clear the fail list
133
 *
134
 * Any number of fail specifications can be active during execution of
135
 * a logexpect. All active fail specifications are matched against every
136
 * log line and, if any match, the logexpect fails immediately.
137
 *
138
 * For a logexpect to end successfully, there must be no specs on the fail list,
139
 * so logexpects should always end with
140
 *
141
 *      expect <skip> <vxid> <tag> <termination-condition>
142
 *      fail clear
143
 *
144
 * .. XXX can we come up with a better solution which is still safe?
145
 *
146
 * abort specification:
147
 *
148
 * abort(3) varnishtest, intended to help debugging of the VSL client library
149
 * itself.
150
 */
151
152
#include "config.h"
153
154
#include <stdlib.h>
155
#include <stdio.h>
156
#include <string.h>
157
#include <stdint.h>
158
159
#include "vapi/vsm.h"
160
#include "vapi/vsl.h"
161
162
#include "vtc.h"
163
164
#include "vtim.h"
165
#include "vre.h"
166
167
#define LE_ANY   (-1)
168
#define LE_LAST  (-2)
169
#define LE_ALT   (-3)
170
#define LE_SEEN  (-4)
171
#define LE_FAIL  (-5)
172
#define LE_CLEAR (-6)   // clear fail list
173
#define LE_ABORT (-7)
174
175
struct logexp_test {
176
        unsigned                        magic;
177
#define LOGEXP_TEST_MAGIC               0x6F62B350
178
        VTAILQ_ENTRY(logexp_test)       list;
179
        VTAILQ_ENTRY(logexp_test)       faillist;
180
181
        struct vsb                      *str;
182
        int64_t                         vxid;
183
        int                             tag;
184
        vre_t                           *vre;
185
        int                             skip_max;
186
};
187
188
VTAILQ_HEAD(tests_head,logexp_test);
189
190
struct logexp {
191
        unsigned                        magic;
192
#define LOGEXP_MAGIC                    0xE81D9F1B
193
        VTAILQ_ENTRY(logexp)            list;
194
195
        char                            *name;
196
        char                            *vname;
197
        struct vtclog                   *vl;
198
        char                            run;
199
        struct tests_head               tests;
200
201
        struct logexp_test              *test;
202
        int                             skip_cnt;
203
        int64_t                         vxid_last;
204
        int                             tag_last;
205
206
        struct tests_head               fail;
207
208
        int                             m_arg;
209
        int                             err_arg;
210
        int                             d_arg;
211
        enum VSL_grouping_e             g_arg;
212
        char                            *query;
213
214
        struct vsm                      *vsm;
215
        struct VSL_data                 *vsl;
216
        struct VSLQ                     *vslq;
217
        pthread_t                       tp;
218
};
219
220
static VTAILQ_HEAD(, logexp)            logexps =
221
        VTAILQ_HEAD_INITIALIZER(logexps);
222
223
static cmd_f cmd_logexp_expect;
224
static cmd_f cmd_logexp_fail;
225
static cmd_f cmd_logexp_abort;
226
227
static const struct cmds logexp_cmds[] = {
228
        { "expect",             cmd_logexp_expect },
229
        { "fail",               cmd_logexp_fail },
230
        { "abort",              cmd_logexp_abort },
231
        { NULL,                 NULL },
232
};
233
234
static void
235 4750
logexp_delete_tests(struct logexp *le)
236
{
237
        struct logexp_test *test;
238
239 4750
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
240 21230
        while (!VTAILQ_EMPTY(&le->tests)) {
241 16480
                test = VTAILQ_FIRST(&le->tests);
242 16480
                CHECK_OBJ_NOTNULL(test, LOGEXP_TEST_MAGIC);
243 16480
                VTAILQ_REMOVE(&le->tests, test, list);
244 16480
                VSB_destroy(&test->str);
245 16480
                if (test->vre)
246 14740
                        VRE_free(&test->vre);
247 16480
                FREE_OBJ(test);
248
        }
249 4750
}
250
251
static void
252 2100
logexp_delete(struct logexp *le)
253
{
254 2100
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
255 2100
        AZ(le->run);
256 2100
        AN(le->vsl);
257 2100
        VSL_Delete(le->vsl);
258 2100
        AZ(le->vslq);
259 2100
        logexp_delete_tests(le);
260 2100
        free(le->name);
261 2100
        free(le->vname);
262 2100
        free(le->query);
263 2100
        VSM_Destroy(&le->vsm);
264 2100
        vtc_logclose(le->vl);
265 2100
        FREE_OBJ(le);
266 2100
}
267
268
static struct logexp *
269 2100
logexp_new(const char *name, const char *varg)
270
{
271
        struct logexp *le;
272
        struct vsb *n_arg;
273
274 2100
        ALLOC_OBJ(le, LOGEXP_MAGIC);
275 2100
        AN(le);
276 2100
        REPLACE(le->name, name);
277 2100
        le->vl = vtc_logopen("%s", name);
278 2100
        vtc_log_set_cmd(le->vl, logexp_cmds);
279 2100
        VTAILQ_INIT(&le->tests);
280
281 2100
        le->d_arg = 0;
282 2100
        le->g_arg = VSL_g_vxid;
283 2100
        le->vsm = VSM_New();
284 2100
        le->vsl = VSL_New();
285 2100
        AN(le->vsm);
286 2100
        AN(le->vsl);
287
288 2100
        VTAILQ_INSERT_TAIL(&logexps, le, list);
289
290 2100
        REPLACE(le->vname, varg);
291
292 2100
        n_arg = macro_expandf(le->vl, "${tmpdir}/%s", varg);
293 2100
        if (n_arg == NULL)
294 0
                vtc_fatal(le->vl, "-v argument problems");
295 2100
        if (VSM_Arg(le->vsm, 'n', VSB_data(n_arg)) <= 0)
296 0
                vtc_fatal(le->vl, "-v argument error: %s",
297 0
                    VSM_Error(le->vsm));
298 2100
        VSB_destroy(&n_arg);
299 2100
        if (VSM_Attach(le->vsm, -1))
300 0
                vtc_fatal(le->vl, "VSM_Attach: %s", VSM_Error(le->vsm));
301 2100
        return (le);
302
}
303
304
static void
305 2670
logexp_clean(const struct tests_head *head)
306
{
307
        struct logexp_test *test;
308
309 19150
        VTAILQ_FOREACH(test, head, list)
310 16480
                if (test->skip_max == LE_SEEN)
311 0
                        test->skip_max = LE_ALT;
312 2670
}
313
314
static struct logexp_test *
315 50
logexp_alt(struct logexp_test *test)
316
{
317 50
        assert(test->skip_max == LE_ALT);
318
319 50
        do
320 110
                test = VTAILQ_NEXT(test, list);
321 60
        while (test != NULL && test->skip_max == LE_SEEN);
322
323 50
        if (test == NULL || test->skip_max != LE_ALT)
324 0
                return (NULL);
325
326 50
        return (test);
327 50
}
328
329
static void
330 19180
logexp_next(struct logexp *le)
331
{
332 19180
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
333
334 19180
        if (le->test && le->test->skip_max == LE_ALT) {
335
                /*
336
                 * if an alternative was not seen, continue at this expection
337
                 * with the next vsl
338
                 */
339
                (void)0;
340 19180
        } else if (le->test) {
341 16480
                CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
342 16480
                le->test = VTAILQ_NEXT(le->test, list);
343 16480
        } else {
344 2670
                logexp_clean(&le->tests);
345 2670
                VTAILQ_INIT(&le->fail);
346 2670
                le->test = VTAILQ_FIRST(&le->tests);
347
        }
348
349 19180
        if (le->test == NULL)
350 2670
                return;
351
352 16510
        CHECK_OBJ(le->test, LOGEXP_TEST_MAGIC);
353
354 16510
        switch (le->test->skip_max) {
355
        case LE_SEEN:
356 30
                logexp_next(le);
357 30
                return;
358
        case LE_CLEAR:
359 120
                vtc_log(le->vl, 3, "cond | fail clear");
360 120
                VTAILQ_INIT(&le->fail);
361 120
                logexp_next(le);
362 120
                return;
363
        case LE_FAIL:
364 150
                vtc_log(le->vl, 3, "cond | %s", VSB_data(le->test->str));
365 150
                VTAILQ_INSERT_TAIL(&le->fail, le->test, faillist);
366 150
                logexp_next(le);
367 150
                return;
368
        case LE_ABORT:
369 0
                abort();
370
                NEEDLESS(return);
371
        default:
372 16210
                vtc_log(le->vl, 3, "test | %s", VSB_data(le->test->str));
373 16210
        }
374 19180
}
375
376
enum le_match_e {
377
        LEM_OK,
378
        LEM_SKIP,
379
        LEM_FAIL
380
};
381
382
static enum le_match_e
383 268907
logexp_match(const struct logexp *le, struct logexp_test *test,
384
    const char *data, int64_t vxid, int tag, int type, int len)
385
{
386
        const char *legend;
387 268907
        int ok = 1, skip = 0, alt, fail, vxid_ok = 0;
388
389 268907
        AN(le);
390 268907
        AN(test);
391 268907
        assert(test->skip_max != LE_SEEN);
392 268907
        assert(test->skip_max != LE_CLEAR);
393
394 268907
        if (test->vxid == LE_LAST) {
395 47414
                if (le->vxid_last != vxid)
396 3510
                        ok = 0;
397 47414
                vxid_ok = ok;
398 268907
        } else if (test->vxid >= 0) {
399 79601
                if (test->vxid != vxid)
400 53302
                        ok = 0;
401 79601
                vxid_ok = ok;
402 79601
        }
403 268907
        if (test->tag == LE_LAST) {
404 7
                if (le->tag_last != tag)
405 0
                        ok = 0;
406 268907
        } else if (test->tag >= 0) {
407 268900
                if (test->tag != tag)
408 246482
                        ok = 0;
409 268900
        }
410 289689
        if (test->vre &&
411 241090
            test->tag >= 0 &&
412 241090
            test->tag == tag &&
413 20782
            VRE_ERROR_NOMATCH == VRE_match(test->vre, data, len, 0, NULL))
414 6102
                ok = 0;
415
416 268901
        alt = (test->skip_max == LE_ALT);
417 268901
        fail = (test->skip_max == LE_FAIL);
418
419 268901
        if (!ok && !alt && (test->skip_max == LE_ANY ||
420 5780
                    test->skip_max > le->skip_cnt))
421 248010
                skip = 1;
422
423 268901
        if (skip && vxid_ok && tag == SLT_End)
424 0
                fail = 1;
425
426 268901
        if (fail) {
427 4630
                if (ok) {
428 10
                        legend = "fail";
429 4630
                } else if (skip) {
430 0
                        legend = "end";
431 0
                        skip = 0;
432 4620
                } else if (le->m_arg) {
433 0
                        legend = "fmiss";
434 0
                } else {
435 4620
                        legend = NULL;
436
                }
437 4630
        }
438 264271
        else if (ok)
439 16210
                legend = "match";
440 248061
        else if (skip && le->m_arg)
441 230
                legend = "miss";
442 247831
        else if (skip || alt)
443 247831
                legend = NULL;
444
        else
445 0
                legend = "err";
446
447 268901
        if (legend != NULL)
448 32900
                vtc_log(le->vl, 4, "%-5s| %10ju %-15s %c %.*s",
449 16450
                    legend, (intmax_t)vxid, VSL_tags[tag], type, len,
450 16450
                    data);
451
452 268901
        if (ok) {
453 16219
                if (alt)
454 220
                        test->skip_max = LE_SEEN;
455 16219
                return (LEM_OK);
456
        }
457 252682
        if (alt) {
458 50
                test = logexp_alt(test);
459 50
                if (test == NULL)
460 0
                        return (LEM_FAIL);
461 50
                vtc_log(le->vl, 3, "alt  | %s", VSB_data(test->str));
462 50
                return (logexp_match(le, test, data, vxid, tag, type, len));
463
        }
464 252632
        if (skip)
465 248012
                return (LEM_SKIP);
466 4620
        return (LEM_FAIL);
467 268901
}
468
469
static enum le_match_e
470 264370
logexp_failchk(const struct logexp *le,
471
    const char *data, int64_t vxid, int tag, int type, int len)
472
{
473
        struct logexp_test *test;
474
        static enum le_match_e r;
475
476 264370
        if (VTAILQ_FIRST(&le->fail) == NULL)
477 261260
                return (LEM_SKIP);
478
479 7730
        VTAILQ_FOREACH(test, &le->fail, faillist) {
480 4630
                r = logexp_match(le, test, data, vxid, tag, type, len);
481 4630
                if (r == LEM_OK)
482 10
                        return (LEM_FAIL);
483 4620
                assert (r == LEM_FAIL);
484 4620
        }
485 3100
        return (LEM_OK);
486 264370
}
487
488
static int
489 388944
logexp_done(const struct logexp *le)
490
{
491 388944
        return ((VTAILQ_FIRST(&le->fail) == NULL) && le->test == NULL);
492
}
493
494
static int v_matchproto_(VSLQ_dispatch_f)
495 98074
logexp_dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[],
496
    void *priv)
497
{
498
        struct logexp *le;
499
        struct VSL_transaction *t;
500
        int i;
501
        enum le_match_e r;
502
        int64_t vxid;
503
        int tag, type, len;
504
        const char *data;
505
506 98074
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
507
508 194108
        for (i = 0; (t = pt[i]) != NULL; i++) {
509 363485
                while (1 == VSL_Next(t->c)) {
510 267451
                        if (!VSL_Match(vsl, t->c))
511 3070
                                continue;
512
513 264381
                        AN(t->c->rec.ptr);
514 264381
                        tag = VSL_TAG(t->c->rec.ptr);
515
516 264381
                        if (tag == SLT__Batch || tag == SLT_Witness)
517 24
                                continue;
518
519 264381
                        vxid = VSL_ID(t->c->rec.ptr);
520 264381
                        data = VSL_CDATA(t->c->rec.ptr);
521 264381
                        len = VSL_LEN(t->c->rec.ptr) - 1;
522 264381
                        type = VSL_CLIENT(t->c->rec.ptr) ? 'c' :
523 81991
                            VSL_BACKEND(t->c->rec.ptr) ? 'b' : '-';
524
525 264381
                        r = logexp_failchk(le, data, vxid, tag, type, len);
526 264381
                        if (r == LEM_FAIL)
527 10
                                return (r);
528 264371
                        if (le->test == NULL) {
529 150
                                assert (r == LEM_OK);
530 150
                                continue;
531
                        }
532
533 264221
                        CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
534
535 528442
                        r = logexp_match(le, le->test,
536 264221
                            data, vxid, tag, type, len);
537 264221
                        if (r == LEM_FAIL)
538 0
                                return (r);
539 264221
                        if (r == LEM_SKIP) {
540 248011
                                le->skip_cnt++;
541 248011
                                continue;
542
                        }
543 16210
                        assert(r == LEM_OK);
544 16210
                        le->vxid_last = vxid;
545 16210
                        le->tag_last = tag;
546 16210
                        le->skip_cnt = 0;
547 16210
                        logexp_next(le);
548 16210
                        if (logexp_done(le))
549 2640
                                return (1);
550
                }
551 96034
        }
552 95424
        return (0);
553 98074
}
554
555
static void *
556 2478
logexp_thread(void *priv)
557
{
558
        struct logexp *le;
559
        int i;
560
561 2478
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
562 2478
        AN(le->run);
563 2478
        AN(le->vsm);
564 2478
        AN(le->vslq);
565
566 2478
        AZ(le->test);
567 2478
        vtc_log(le->vl, 4, "begin|");
568 2478
        if (le->query != NULL)
569 1190
                vtc_log(le->vl, 4, "qry  | %s", le->query);
570 2478
        logexp_next(le);
571 285804
        while (!logexp_done(le) && !vtc_stop && !vtc_error) {
572 283208
                i = VSLQ_Dispatch(le->vslq, logexp_dispatch, le);
573 283208
                if (i == 2 && le->err_arg) {
574 10
                        vtc_log(le->vl, 4, "done | failed as expected");
575 10
                        return (NULL);
576
                }
577 283198
                if (i == 2)
578 0
                        vtc_fatal(le->vl, "bad  | expectation failed");
579 283198
                else if (i < 0)
580 0
                        vtc_fatal(le->vl, "bad  | dispatch failed (%d)", i);
581 283198
                else if (i == 0 && ! logexp_done(le))
582 84423
                        VTIM_sleep(0.01);
583
        }
584 2660
        if (!logexp_done(le))
585 0
                vtc_fatal(le->vl, "bad  | outstanding expectations");
586 2660
        vtc_log(le->vl, 4, "done |");
587
588 2660
        return (NULL);
589 2670
}
590
591
static void
592 2670
logexp_close(struct logexp *le)
593
{
594
595 2670
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
596 2670
        AN(le->vsm);
597 2670
        if (le->vslq)
598 2670
                VSLQ_Delete(&le->vslq);
599 2670
        AZ(le->vslq);
600 2670
}
601
602
static void
603 2670
logexp_start(struct logexp *le)
604
{
605
        struct VSL_cursor *c;
606
607 2670
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
608 2670
        AN(le->vsl);
609 2670
        AZ(le->vslq);
610
611 2670
        AN(le->vsl);
612 2670
        (void)VSM_Status(le->vsm);
613 5340
        c = VSL_CursorVSM(le->vsl, le->vsm,
614 2670
            (le->d_arg ? 0 : VSL_COPT_TAIL) | VSL_COPT_BATCH);
615 2670
        if (c == NULL)
616 0
                vtc_fatal(le->vl, "VSL_CursorVSM: %s", VSL_Error(le->vsl));
617 2670
        le->vslq = VSLQ_New(le->vsl, &c, le->g_arg, le->query);
618 2670
        if (le->vslq == NULL) {
619 0
                VSL_DeleteCursor(c);
620 0
                vtc_fatal(le->vl, "VSLQ_New: %s", VSL_Error(le->vsl));
621
        }
622 2670
        AZ(c);
623
624 2670
        le->test = NULL;
625 2670
        le->skip_cnt = 0;
626 2670
        le->vxid_last = le->tag_last = -1;
627 2670
        le->run = 1;
628 2670
        PTOK(pthread_create(&le->tp, NULL, logexp_thread, le));
629 2670
}
630
631
static void
632 2670
logexp_wait(struct logexp *le)
633
{
634
        void *res;
635
636 2670
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
637 2670
        vtc_log(le->vl, 2, "Waiting for logexp");
638 2670
        PTOK(pthread_join(le->tp, &res));
639 2670
        logexp_close(le);
640 2670
        if (res != NULL && !vtc_stop)
641 0
                vtc_fatal(le->vl, "logexp returned \"%p\"", (char *)res);
642 2670
        le->run = 0;
643 2670
}
644
645
/* shared by expect and fail: parse from av[2] (vxid) onwards */
646
647
static void
648 16360
cmd_logexp_common(struct logexp *le, struct vtclog *vl,
649
    int skip_max, char * const *av)
650
{
651
        vre_t *vre;
652
        struct vsb vsb[1];
653
        int64_t vxid;
654
        int err, pos, tag;
655
        struct logexp_test *test;
656
        char *end, errbuf[VRE_ERROR_LEN];
657
658 16360
        if (!strcmp(av[2], "*"))
659 2140
                vxid = LE_ANY;
660 14220
        else if (!strcmp(av[2], "="))
661 8790
                vxid = LE_LAST;
662
        else {
663 5430
                vxid = strtoll(av[2], &end, 10);
664 5430
                if (*end != '\0' || vxid < 0)
665 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[2]);
666
        }
667 16360
        if (!strcmp(av[3], "*"))
668 0
                tag = LE_ANY;
669 16360
        else if (!strcmp(av[3], "="))
670 0
                tag = LE_LAST;
671
        else {
672 16360
                tag = VSL_Name2Tag(av[3], strlen(av[3]));
673 16360
                if (tag < 0)
674 0
                        vtc_fatal(vl, "Unknown tag name: '%s'", av[3]);
675
        }
676 16360
        vre = NULL;
677 16360
        if (av[4]) {
678 14740
                vre = VRE_compile(av[4], 0, &err, &pos, 1);
679 14740
                if (vre == NULL) {
680 0
                        AN(VSB_init(vsb, errbuf, sizeof errbuf));
681 0
                        AZ(VRE_error(vsb, err));
682 0
                        AZ(VSB_finish(vsb));
683 0
                        VSB_fini(vsb);
684 0
                        vtc_fatal(vl, "Regex error (%s): '%s' pos %d",
685 0
                            errbuf, av[4], pos);
686
                }
687 14740
        }
688
689 16360
        ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
690 16360
        AN(test);
691 16360
        test->str = VSB_new_auto();
692 16360
        AN(test->str);
693 16360
        AZ(VSB_printf(test->str, "%s %s %s %s ", av[0], av[1], av[2], av[3]));
694 16360
        if (av[4])
695 14740
                VSB_quote(test->str, av[4], -1, 0);
696 16360
        AZ(VSB_finish(test->str));
697 16360
        test->skip_max = skip_max;
698 16360
        test->vxid = vxid;
699 16360
        test->tag = tag;
700 16360
        test->vre = vre;
701 16360
        VTAILQ_INSERT_TAIL(&le->tests, test, list);
702 16360
}
703
704
static void
705 16210
cmd_logexp_expect(CMD_ARGS)
706
{
707
        struct logexp *le;
708
        int skip_max;
709
        char *end;
710
711 16210
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
712 16210
        if (av[1] == NULL || av[2] == NULL || av[3] == NULL)
713 0
                vtc_fatal(vl, "Syntax error");
714
715 16210
        if (av[4] != NULL && av[5] != NULL)
716 0
                vtc_fatal(vl, "Syntax error");
717
718 16210
        if (!strcmp(av[1], "*"))
719 5350
                skip_max = LE_ANY;
720 10860
        else if (!strcmp(av[1], "?"))
721 220
                skip_max = LE_ALT;
722
        else {
723 10640
                skip_max = (int)strtol(av[1], &end, 10);
724 10640
                if (*end != '\0' || skip_max < 0)
725 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[1]);
726
        }
727 16210
        cmd_logexp_common(le, vl, skip_max, av);
728 16210
}
729
730
static void
731 270
cmd_logexp_fail(CMD_ARGS)
732
{
733
        struct logexp *le;
734
        struct logexp_test *test;
735
736 270
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
737
738 270
        if (av[1] == NULL)
739 0
                vtc_fatal(vl, "Syntax error");
740
741 270
        if (!strcmp(av[1], "clear")) {
742 120
                ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
743 120
                AN(test);
744 120
                test->skip_max = LE_CLEAR;
745 120
                test->str = VSB_new_auto();
746 120
                AN(test->str);
747 120
                AZ(VSB_printf(test->str, "%s %s",
748
                    av[0], av[1]));
749 120
                AZ(VSB_finish(test->str));
750
751 120
                VTAILQ_INSERT_TAIL(&le->tests, test, list);
752 120
                return;
753
        }
754
755 150
        if (strcmp(av[1], "add"))
756 0
                vtc_fatal(vl, "Unknown fail argument '%s'", av[1]);
757
758 150
        if (av[2] == NULL || av[3] == NULL)
759 0
                vtc_fatal(vl, "Syntax error");
760
761 150
        cmd_logexp_common(le, vl, LE_FAIL, av);
762 270
}
763
764
/* aid vsl debugging */
765
static void
766 0
cmd_logexp_abort(CMD_ARGS)
767
{
768
769
        struct logexp *le;
770
771 0
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
772
773 0
        cmd_logexp_common(le, vl, LE_ABORT, av);
774 0
}
775
776
static void
777 2650
logexp_spec(struct logexp *le, const char *spec)
778
{
779 2650
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
780
781 2650
        logexp_delete_tests(le);
782
783 2650
        parse_string(le->vl, le, spec);
784 2650
}
785
786
void
787 14900
cmd_logexpect(CMD_ARGS)
788
{
789
        struct logexp *le, *le2;
790
        int i;
791
792 14900
        (void)priv;
793
794 14900
        if (av == NULL) {
795
                /* Reset and free */
796 12180
                VTAILQ_FOREACH_SAFE(le, &logexps, list, le2) {
797 2100
                        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
798 2100
                        VTAILQ_REMOVE(&logexps, le, list);
799 2100
                        if (le->run) {
800 10
                                (void)pthread_cancel(le->tp);
801 10
                                logexp_wait(le);
802 10
                        }
803 2100
                        logexp_delete(le);
804 2100
                }
805 10080
                return;
806
        }
807
808 4820
        AZ(strcmp(av[0], "logexpect"));
809 4820
        av++;
810
811 4820
        VTC_CHECK_NAME(vl, av[0], "Logexpect", 'l');
812 9450
        VTAILQ_FOREACH(le, &logexps, list) {
813 7350
                if (!strcmp(le->name, av[0]))
814 2720
                        break;
815 4630
        }
816 4820
        if (le == NULL) {
817 2100
                if (strcmp(av[1], "-v") || av[2] == NULL)
818 0
                        vtc_fatal(vl, "new logexp lacks -v");
819 2100
                le = logexp_new(av[0], av[2]);
820 2100
                av += 2;
821 2100
        }
822 4820
        av++;
823
824 16670
        for (; *av != NULL; av++) {
825 11850
                if (vtc_error)
826 0
                        break;
827 11850
                if (!strcmp(*av, "-wait")) {
828 2090
                        if (!le->run)
829 0
                                vtc_fatal(le->vl, "logexp not -started '%s'",
830 0
                                        *av);
831 2090
                        logexp_wait(le);
832 2090
                        continue;
833
                }
834
835
                /*
836
                 * We do an implicit -wait if people muck about with a
837
                 * running logexp.
838
                 */
839 9760
                if (le->run)
840 0
                        logexp_wait(le);
841 9760
                AZ(le->run);
842
843 9760
                if (!strcmp(*av, "-v")) {
844 180
                        if (av[1] == NULL || strcmp(av[1], le->vname))
845 0
                                vtc_fatal(le->vl, "-v argument cannot change");
846 180
                        av++;
847 180
                        continue;
848
                }
849 9580
                if (!strcmp(*av, "-d")) {
850 810
                        if (av[1] == NULL)
851 0
                                vtc_fatal(le->vl, "Missing -d argument");
852 810
                        le->d_arg = atoi(av[1]);
853 810
                        av++;
854 810
                        continue;
855
                }
856 8770
                if (!strcmp(*av, "-g")) {
857 2110
                        if (av[1] == NULL)
858 0
                                vtc_fatal(le->vl, "Missing -g argument");
859 2110
                        i = VSLQ_Name2Grouping(av[1], strlen(av[1]));
860 2110
                        if (i < 0)
861 0
                                vtc_fatal(le->vl, "Unknown grouping '%s'",
862 0
                                    av[1]);
863 2110
                        le->g_arg = (enum VSL_grouping_e)i;
864 2110
                        av++;
865 2110
                        continue;
866
                }
867 6660
                if (!strcmp(*av, "-q")) {
868 1090
                        if (av[1] == NULL)
869 0
                                vtc_fatal(le->vl, "Missing -q argument");
870 1090
                        REPLACE(le->query, av[1]);
871 1090
                        av++;
872 1090
                        continue;
873
                }
874 5570
                if (!strcmp(*av, "-m")) {
875 10
                        le->m_arg = !le->m_arg;
876 10
                        continue;
877
                }
878 5560
                if (!strcmp(*av, "-err")) {
879 10
                        le->err_arg = !le->err_arg;
880 10
                        continue;
881
                }
882 5550
                if (!strcmp(*av, "-start")) {
883 2100
                        logexp_start(le);
884 2100
                        continue;
885
                }
886 3450
                if (!strcmp(*av, "-run")) {
887 570
                        logexp_start(le);
888 570
                        logexp_wait(le);
889 570
                        continue;
890
                }
891 2880
                if (**av == '-') {
892 230
                        if (av[1] != NULL) {
893 230
                                if (VSL_Arg(le->vsl, av[0][1], av[1])) {
894 230
                                        av++;
895 230
                                        continue;
896
                                }
897 0
                                vtc_fatal(le->vl, "%s", VSL_Error(le->vsl));
898
                        }
899 0
                        vtc_fatal(le->vl, "Unknown logexp argument: %s", *av);
900
                }
901 2650
                logexp_spec(le, *av);
902 2650
        }
903 14900
}
904
905
#endif /* VTEST_WITH_VTC_LOGEXPECT */