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 11525
logexp_delete_tests(struct logexp *le)
236
{
237
        struct logexp_test *test;
238
239 11525
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
240 52225
        while (!VTAILQ_EMPTY(&le->tests)) {
241 40700
                test = VTAILQ_FIRST(&le->tests);
242 40700
                CHECK_OBJ_NOTNULL(test, LOGEXP_TEST_MAGIC);
243 40700
                VTAILQ_REMOVE(&le->tests, test, list);
244 40700
                VSB_destroy(&test->str);
245 40700
                if (test->vre)
246 36500
                        VRE_free(&test->vre);
247 40700
                FREE_OBJ(test);
248
        }
249 11525
}
250
251
static void
252 5075
logexp_delete(struct logexp *le)
253
{
254 5075
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
255 5075
        AZ(le->run);
256 5075
        AN(le->vsl);
257 5075
        VSL_Delete(le->vsl);
258 5075
        AZ(le->vslq);
259 5075
        logexp_delete_tests(le);
260 5075
        free(le->name);
261 5075
        free(le->vname);
262 5075
        free(le->query);
263 5075
        VSM_Destroy(&le->vsm);
264 5075
        vtc_logclose(le->vl);
265 5075
        FREE_OBJ(le);
266 5075
}
267
268
static struct logexp *
269 5075
logexp_new(const char *name, const char *varg)
270
{
271
        struct logexp *le;
272
        struct vsb *n_arg;
273
274 5075
        ALLOC_OBJ(le, LOGEXP_MAGIC);
275 5075
        AN(le);
276 5075
        REPLACE(le->name, name);
277 5075
        le->vl = vtc_logopen("%s", name);
278 5075
        vtc_log_set_cmd(le->vl, logexp_cmds);
279 5075
        VTAILQ_INIT(&le->tests);
280
281 5075
        le->d_arg = 0;
282 5075
        le->g_arg = VSL_g_vxid;
283 5075
        le->vsm = VSM_New();
284 5075
        le->vsl = VSL_New();
285 5075
        AN(le->vsm);
286 5075
        AN(le->vsl);
287
288 5075
        VTAILQ_INSERT_TAIL(&logexps, le, list);
289
290 5075
        REPLACE(le->vname, varg);
291
292 5075
        n_arg = macro_expandf(le->vl, "${tmpdir}/%s", varg);
293 5075
        if (n_arg == NULL)
294 0
                vtc_fatal(le->vl, "-v argument problems");
295 5075
        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 5075
        VSB_destroy(&n_arg);
299 5075
        if (VSM_Attach(le->vsm, -1))
300 0
                vtc_fatal(le->vl, "VSM_Attach: %s", VSM_Error(le->vsm));
301 5075
        return (le);
302
}
303
304
static void
305 6500
logexp_clean(const struct tests_head *head)
306
{
307
        struct logexp_test *test;
308
309 47200
        VTAILQ_FOREACH(test, head, list)
310 40700
                if (test->skip_max == LE_SEEN)
311 0
                        test->skip_max = LE_ALT;
312 6500
}
313
314
static struct logexp_test *
315 125
logexp_alt(struct logexp_test *test)
316
{
317 125
        assert(test->skip_max == LE_ALT);
318
319 125
        do
320 275
                test = VTAILQ_NEXT(test, list);
321 150
        while (test != NULL && test->skip_max == LE_SEEN);
322
323 125
        if (test == NULL || test->skip_max != LE_ALT)
324 0
                return (NULL);
325
326 125
        return (test);
327 125
}
328
329
static void
330 47275
logexp_next(struct logexp *le)
331
{
332 47275
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
333
334 47275
        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 47275
        } else if (le->test) {
341 40700
                CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
342 40700
                le->test = VTAILQ_NEXT(le->test, list);
343 40700
        } else {
344 6500
                logexp_clean(&le->tests);
345 6500
                VTAILQ_INIT(&le->fail);
346 6500
                le->test = VTAILQ_FIRST(&le->tests);
347
        }
348
349 47275
        if (le->test == NULL)
350 6500
                return;
351
352 40775
        CHECK_OBJ(le->test, LOGEXP_TEST_MAGIC);
353
354 40775
        switch (le->test->skip_max) {
355
        case LE_SEEN:
356 75
                logexp_next(le);
357 75
                return;
358
        case LE_CLEAR:
359 250
                vtc_log(le->vl, 3, "cond | fail clear");
360 250
                VTAILQ_INIT(&le->fail);
361 250
                logexp_next(le);
362 250
                return;
363
        case LE_FAIL:
364 325
                vtc_log(le->vl, 3, "cond | %s", VSB_data(le->test->str));
365 325
                VTAILQ_INSERT_TAIL(&le->fail, le->test, faillist);
366 325
                logexp_next(le);
367 325
                return;
368
        case LE_ABORT:
369 0
                abort();
370
                NEEDLESS(return);
371
        default:
372 40125
                vtc_log(le->vl, 3, "test | %s", VSB_data(le->test->str));
373 40125
        }
374 47275
}
375
376
enum le_match_e {
377
        LEM_OK,
378
        LEM_SKIP,
379
        LEM_FAIL
380
};
381
382
static enum le_match_e
383 661882
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 661882
        int ok = 1, skip = 0, alt, fail, vxid_ok = 0;
388
389 661882
        AN(le);
390 661882
        AN(test);
391 661882
        assert(test->skip_max != LE_SEEN);
392 661882
        assert(test->skip_max != LE_CLEAR);
393
394 661882
        if (test->vxid == LE_LAST) {
395 116381
                if (le->vxid_last != vxid)
396 8775
                        ok = 0;
397 116381
                vxid_ok = ok;
398 661882
        } else if (test->vxid >= 0) {
399 198298
                if (test->vxid != vxid)
400 133202
                        ok = 0;
401 198298
                vxid_ok = ok;
402 198298
        }
403 661882
        if (test->tag == LE_LAST) {
404 7
                if (le->tag_last != tag)
405 0
                        ok = 0;
406 661882
        } else if (test->tag >= 0) {
407 661874
                if (test->tag != tag)
408 606170
                        ok = 0;
409 661874
        }
410 713572
        if (test->vre &&
411 594376
            test->tag >= 0 &&
412 594377
            test->tag == tag &&
413 51690
            VRE_ERROR_NOMATCH == VRE_match(test->vre, data, len, 0, NULL))
414 15315
                ok = 0;
415
416 661884
        alt = (test->skip_max == LE_ALT);
417 661884
        fail = (test->skip_max == LE_FAIL);
418
419 661884
        if (!ok && !alt && (test->skip_max == LE_ANY ||
420 12450
                    test->skip_max > le->skip_cnt))
421 612059
                skip = 1;
422
423 661884
        if (skip && vxid_ok && tag == SLT_End)
424 0
                fail = 1;
425
426 661884
        if (fail) {
427 9575
                if (ok) {
428 25
                        legend = "fail";
429 9575
                } else if (skip) {
430 0
                        legend = "end";
431 0
                        skip = 0;
432 9550
                } else if (le->m_arg) {
433 0
                        legend = "fmiss";
434 0
                } else {
435 9550
                        legend = NULL;
436
                }
437 9575
        }
438 652309
        else if (ok)
439 40125
                legend = "match";
440 612184
        else if (skip && le->m_arg)
441 575
                legend = "miss";
442 611609
        else if (skip || alt)
443 611609
                legend = NULL;
444
        else
445 0
                legend = "err";
446
447 661884
        if (legend != NULL)
448 81450
                vtc_log(le->vl, 4, "%-5s| %10ju %-15s %c %.*s",
449 40725
                    legend, (intmax_t)vxid, VSL_tags[tag], type, len,
450 40725
                    data);
451
452 661884
        if (ok) {
453 40149
                if (alt)
454 550
                        test->skip_max = LE_SEEN;
455 40149
                return (LEM_OK);
456
        }
457 621735
        if (alt) {
458 125
                test = logexp_alt(test);
459 125
                if (test == NULL)
460 0
                        return (LEM_FAIL);
461 125
                vtc_log(le->vl, 3, "alt  | %s", VSB_data(test->str));
462 125
                return (logexp_match(le, test, data, vxid, tag, type, len));
463
        }
464 621610
        if (skip)
465 612060
                return (LEM_SKIP);
466 9550
        return (LEM_FAIL);
467 661884
}
468
469
static enum le_match_e
470 652560
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 652560
        if (VTAILQ_FIRST(&le->fail) == NULL)
477 646785
                return (LEM_SKIP);
478
479 15325
        VTAILQ_FOREACH(test, &le->fail, faillist) {
480 9575
                r = logexp_match(le, test, data, vxid, tag, type, len);
481 9575
                if (r == LEM_OK)
482 25
                        return (LEM_FAIL);
483 9550
                assert (r == LEM_FAIL);
484 9550
        }
485 5750
        return (LEM_OK);
486 652560
}
487
488
static int
489 927093
logexp_done(const struct logexp *le)
490
{
491 927093
        return ((VTAILQ_FIRST(&le->fail) == NULL) && le->test == NULL);
492
}
493
494
static int v_matchproto_(VSLQ_dispatch_f)
495 242779
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 242779
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
507
508 480623
        for (i = 0; (t = pt[i]) != NULL; i++) {
509 898102
                while (1 == VSL_Next(t->c)) {
510 660258
                        if (!VSL_Match(vsl, t->c))
511 7674
                                continue;
512
513 652584
                        AN(t->c->rec.ptr);
514 652584
                        tag = VSL_TAG(t->c->rec.ptr);
515
516 652584
                        if (tag == SLT__Batch || tag == SLT_Witness)
517 52
                                continue;
518
519 652574
                        vxid = VSL_ID(t->c->rec.ptr);
520 652574
                        data = VSL_CDATA(t->c->rec.ptr);
521 652574
                        len = VSL_LEN(t->c->rec.ptr) - 1;
522 652574
                        type = VSL_CLIENT(t->c->rec.ptr) ? 'c' :
523 203474
                            VSL_BACKEND(t->c->rec.ptr) ? 'b' : '-';
524
525 652574
                        r = logexp_failchk(le, data, vxid, tag, type, len);
526 652574
                        if (r == LEM_FAIL)
527 25
                                return (r);
528 652549
                        if (le->test == NULL) {
529 375
                                assert (r == LEM_OK);
530 375
                                continue;
531
                        }
532
533 652174
                        CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
534
535 1304348
                        r = logexp_match(le, le->test,
536 652174
                            data, vxid, tag, type, len);
537 652174
                        if (r == LEM_FAIL)
538 0
                                return (r);
539 652174
                        if (r == LEM_SKIP) {
540 612049
                                le->skip_cnt++;
541 612049
                                continue;
542
                        }
543 40125
                        assert(r == LEM_OK);
544 40125
                        le->vxid_last = vxid;
545 40125
                        le->tag_last = tag;
546 40125
                        le->skip_cnt = 0;
547 40125
                        logexp_next(le);
548 40125
                        if (logexp_done(le))
549 6425
                                return (1);
550
                }
551 237844
        }
552 236319
        return (0);
553 242769
}
554
555
static void *
556 6262
logexp_thread(void *priv)
557
{
558
        struct logexp *le;
559
        int i;
560
561 6262
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
562 6262
        AN(le->run);
563 6262
        AN(le->vsm);
564 6262
        AN(le->vslq);
565
566 6262
        AZ(le->test);
567 6262
        vtc_log(le->vl, 4, "begin|");
568 6262
        if (le->query != NULL)
569 2850
                vtc_log(le->vl, 4, "qry  | %s", le->query);
570 6262
        logexp_next(le);
571 685892
        while (!logexp_done(le) && !vtc_stop && !vtc_error) {
572 679445
                i = VSLQ_Dispatch(le->vslq, logexp_dispatch, le);
573 679445
                if (i == 2 && le->err_arg) {
574 25
                        vtc_log(le->vl, 4, "done | failed as expected");
575 25
                        return (NULL);
576
                }
577 679420
                if (i == 2)
578 0
                        vtc_fatal(le->vl, "bad  | expectation failed");
579 679420
                else if (i < 0)
580 0
                        vtc_fatal(le->vl, "bad  | dispatch failed (%d)", i);
581 679420
                else if (i == 0 && ! logexp_done(le))
582 193812
                        VTIM_sleep(0.01);
583
        }
584 6475
        if (!logexp_done(le))
585 0
                vtc_fatal(le->vl, "bad  | outstanding expectations");
586 6475
        vtc_log(le->vl, 4, "done |");
587
588 6475
        return (NULL);
589 6500
}
590
591
static void
592 6500
logexp_close(struct logexp *le)
593
{
594
595 6500
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
596 6500
        AN(le->vsm);
597 6500
        if (le->vslq)
598 6500
                VSLQ_Delete(&le->vslq);
599 6500
        AZ(le->vslq);
600 6500
}
601
602
static void
603 6500
logexp_start(struct logexp *le)
604
{
605
        struct VSL_cursor *c;
606
607 6500
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
608 6500
        AN(le->vsl);
609 6500
        AZ(le->vslq);
610
611 6500
        AN(le->vsl);
612 6500
        (void)VSM_Status(le->vsm);
613 13000
        c = VSL_CursorVSM(le->vsl, le->vsm,
614 6500
            (le->d_arg ? 0 : VSL_COPT_TAIL) | VSL_COPT_BATCH);
615 6500
        if (c == NULL)
616 0
                vtc_fatal(le->vl, "VSL_CursorVSM: %s", VSL_Error(le->vsl));
617 6500
        le->vslq = VSLQ_New(le->vsl, &c, le->g_arg, le->query);
618 6500
        if (le->vslq == NULL) {
619 0
                VSL_DeleteCursor(c);
620 0
                vtc_fatal(le->vl, "VSLQ_New: %s", VSL_Error(le->vsl));
621
        }
622 6500
        AZ(c);
623
624 6500
        le->test = NULL;
625 6500
        le->skip_cnt = 0;
626 6500
        le->vxid_last = le->tag_last = -1;
627 6500
        le->run = 1;
628 6500
        PTOK(pthread_create(&le->tp, NULL, logexp_thread, le));
629 6500
}
630
631
static void
632 6500
logexp_wait(struct logexp *le)
633
{
634
        void *res;
635
636 6500
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
637 6500
        vtc_log(le->vl, 2, "Waiting for logexp");
638 6500
        PTOK(pthread_join(le->tp, &res));
639 6500
        logexp_close(le);
640 6500
        if (res != NULL && !vtc_stop)
641 0
                vtc_fatal(le->vl, "logexp returned \"%p\"", (char *)res);
642 6500
        le->run = 0;
643 6500
}
644
645
/* shared by expect and fail: parse from av[2] (vxid) onwards */
646
647
static void
648 40450
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 40450
        if (!strcmp(av[2], "*"))
659 5250
                vxid = LE_ANY;
660 35200
        else if (!strcmp(av[2], "="))
661 21875
                vxid = LE_LAST;
662
        else {
663 13325
                vxid = strtoll(av[2], &end, 10);
664 13325
                if (*end != '\0' || vxid < 0)
665 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[2]);
666
        }
667 40450
        if (!strcmp(av[3], "*"))
668 0
                tag = LE_ANY;
669 40450
        else if (!strcmp(av[3], "="))
670 0
                tag = LE_LAST;
671
        else {
672 40450
                tag = VSL_Name2Tag(av[3], strlen(av[3]));
673 40450
                if (tag < 0)
674 0
                        vtc_fatal(vl, "Unknown tag name: '%s'", av[3]);
675
        }
676 40450
        vre = NULL;
677 40450
        if (av[4]) {
678 36500
                vre = VRE_compile(av[4], 0, &err, &pos, 1);
679 36500
                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 36500
        }
688
689 40450
        ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
690 40450
        AN(test);
691 40450
        test->str = VSB_new_auto();
692 40450
        AN(test->str);
693 40450
        AZ(VSB_printf(test->str, "%s %s %s %s ", av[0], av[1], av[2], av[3]));
694 40450
        if (av[4])
695 36500
                VSB_quote(test->str, av[4], -1, 0);
696 40450
        AZ(VSB_finish(test->str));
697 40450
        test->skip_max = skip_max;
698 40450
        test->vxid = vxid;
699 40450
        test->tag = tag;
700 40450
        test->vre = vre;
701 40450
        VTAILQ_INSERT_TAIL(&le->tests, test, list);
702 40450
}
703
704
static void
705 40125
cmd_logexp_expect(CMD_ARGS)
706
{
707
        struct logexp *le;
708
        int skip_max;
709
        char *end;
710
711 40125
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
712 40125
        if (av[1] == NULL || av[2] == NULL || av[3] == NULL)
713 0
                vtc_fatal(vl, "Syntax error");
714
715 40125
        if (av[4] != NULL && av[5] != NULL)
716 0
                vtc_fatal(vl, "Syntax error");
717
718 40125
        if (!strcmp(av[1], "*"))
719 13125
                skip_max = LE_ANY;
720 27000
        else if (!strcmp(av[1], "?"))
721 550
                skip_max = LE_ALT;
722
        else {
723 26450
                skip_max = (int)strtol(av[1], &end, 10);
724 26450
                if (*end != '\0' || skip_max < 0)
725 0
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[1]);
726
        }
727 40125
        cmd_logexp_common(le, vl, skip_max, av);
728 40125
}
729
730
static void
731 575
cmd_logexp_fail(CMD_ARGS)
732
{
733
        struct logexp *le;
734
        struct logexp_test *test;
735
736 575
        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
737
738 575
        if (av[1] == NULL)
739 0
                vtc_fatal(vl, "Syntax error");
740
741 575
        if (!strcmp(av[1], "clear")) {
742 250
                ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
743 250
                AN(test);
744 250
                test->skip_max = LE_CLEAR;
745 250
                test->str = VSB_new_auto();
746 250
                AN(test->str);
747 250
                AZ(VSB_printf(test->str, "%s %s",
748
                    av[0], av[1]));
749 250
                AZ(VSB_finish(test->str));
750
751 250
                VTAILQ_INSERT_TAIL(&le->tests, test, list);
752 250
                return;
753
        }
754
755 325
        if (strcmp(av[1], "add"))
756 0
                vtc_fatal(vl, "Unknown fail argument '%s'", av[1]);
757
758 325
        if (av[2] == NULL || av[3] == NULL)
759 0
                vtc_fatal(vl, "Syntax error");
760
761 325
        cmd_logexp_common(le, vl, LE_FAIL, av);
762 575
}
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 6450
logexp_spec(struct logexp *le, const char *spec)
778
{
779 6450
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
780
781 6450
        logexp_delete_tests(le);
782
783 6450
        parse_string(le->vl, le, spec);
784 6450
}
785
786
void
787 36125
cmd_logexpect(CMD_ARGS)
788
{
789
        struct logexp *le, *le2;
790
        int i;
791
792 36125
        (void)priv;
793
794 36125
        if (av == NULL) {
795
                /* Reset and free */
796 29500
                VTAILQ_FOREACH_SAFE(le, &logexps, list, le2) {
797 5075
                        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
798 5075
                        VTAILQ_REMOVE(&logexps, le, list);
799 5075
                        if (le->run) {
800 25
                                (void)pthread_cancel(le->tp);
801 25
                                logexp_wait(le);
802 25
                        }
803 5075
                        logexp_delete(le);
804 5075
                }
805 24425
                return;
806
        }
807
808 11700
        AZ(strcmp(av[0], "logexpect"));
809 11700
        av++;
810
811 11700
        VTC_CHECK_NAME(vl, av[0], "Logexpect", 'l');
812 22975
        VTAILQ_FOREACH(le, &logexps, list) {
813 17900
                if (!strcmp(le->name, av[0]))
814 6625
                        break;
815 11275
        }
816 11700
        if (le == NULL) {
817 5075
                if (strcmp(av[1], "-v") || av[2] == NULL)
818 0
                        vtc_fatal(vl, "new logexp lacks -v");
819 5075
                le = logexp_new(av[0], av[2]);
820 5075
                av += 2;
821 5075
        }
822 11700
        av++;
823
824 40550
        for (; *av != NULL; av++) {
825 28850
                if (vtc_error)
826 0
                        break;
827 28850
                if (!strcmp(*av, "-wait")) {
828 5050
                        if (!le->run)
829 0
                                vtc_fatal(le->vl, "logexp not -started '%s'",
830 0
                                        *av);
831 5050
                        logexp_wait(le);
832 5050
                        continue;
833
                }
834
835
                /*
836
                 * We do an implict -wait if people muck about with a
837
                 * running logexp.
838
                 */
839 23800
                if (le->run)
840 0
                        logexp_wait(le);
841 23800
                AZ(le->run);
842
843 23800
                if (!strcmp(*av, "-v")) {
844 450
                        if (av[1] == NULL || strcmp(av[1], le->vname))
845 0
                                vtc_fatal(le->vl, "-v argument cannot change");
846 450
                        av++;
847 450
                        continue;
848
                }
849 23350
                if (!strcmp(*av, "-d")) {
850 2025
                        if (av[1] == NULL)
851 0
                                vtc_fatal(le->vl, "Missing -d argument");
852 2025
                        le->d_arg = atoi(av[1]);
853 2025
                        av++;
854 2025
                        continue;
855
                }
856 21325
                if (!strcmp(*av, "-g")) {
857 5150
                        if (av[1] == NULL)
858 0
                                vtc_fatal(le->vl, "Missing -g argument");
859 5150
                        i = VSLQ_Name2Grouping(av[1], strlen(av[1]));
860 5150
                        if (i < 0)
861 0
                                vtc_fatal(le->vl, "Unknown grouping '%s'",
862 0
                                    av[1]);
863 5150
                        le->g_arg = (enum VSL_grouping_e)i;
864 5150
                        av++;
865 5150
                        continue;
866
                }
867 16175
                if (!strcmp(*av, "-q")) {
868 2600
                        if (av[1] == NULL)
869 0
                                vtc_fatal(le->vl, "Missing -q argument");
870 2600
                        REPLACE(le->query, av[1]);
871 2600
                        av++;
872 2600
                        continue;
873
                }
874 13575
                if (!strcmp(*av, "-m")) {
875 25
                        le->m_arg = !le->m_arg;
876 25
                        continue;
877
                }
878 13550
                if (!strcmp(*av, "-err")) {
879 25
                        le->err_arg = !le->err_arg;
880 25
                        continue;
881
                }
882 13525
                if (!strcmp(*av, "-start")) {
883 5075
                        logexp_start(le);
884 5075
                        continue;
885
                }
886 8450
                if (!strcmp(*av, "-run")) {
887 1425
                        logexp_start(le);
888 1425
                        logexp_wait(le);
889 1425
                        continue;
890
                }
891 7025
                if (**av == '-') {
892 575
                        if (av[1] != NULL) {
893 575
                                if (VSL_Arg(le->vsl, av[0][1], av[1])) {
894 575
                                        av++;
895 575
                                        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 6450
                logexp_spec(le, *av);
902 6450
        }
903 36125
}
904
905
#endif /* VTEST_WITH_VTC_LOGEXPECT */