GCOV - Varnish Cache


/*-
 * Copyright (c) 2008-2015 Varnish Software AS
 * All rights reserved.
 *
 * Author: Martin Blix Grydeland <martin@varnish-software.com>
 *
 * SPDX-License-Identifier: BSD-2-Clause
 *
 * Redistribution and use in source and binary forms, with or without
 * modification, are permitted provided that the following conditions
 * are met:
 * 1. Redistributions of source code must retain the above copyright
 *    notice, this list of conditions and the following disclaimer.
 * 2. Redistributions in binary form must reproduce the above copyright
 *    notice, this list of conditions and the following disclaimer in the
 *    documentation and/or other materials provided with the distribution.
 *
 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
 * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
 * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
 * ARE DISCLAIMED.  IN NO EVENT SHALL AUTHOR OR CONTRIBUTORS BE LIABLE
 * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
 * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
 * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
 * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
 * SUCH DAMAGE.
 */

#ifdef VTEST_WITH_VTC_LOGEXPECT

/* SECTION: logexpect logexpect
 *
 * Reads the VSL and looks for records matching a given specification. It will
 * process records trying to match the first pattern, and when done, will
 * continue processing, trying to match the following pattern. If a pattern
 * isn't matched, the test will fail.
 *
 * logexpect threads are declared this way::
 *
 *         logexpect lNAME -v <id> [-g <grouping>] [-d 0|1] [-q query] \
 *                 [vsl arguments] {
 *                         expect <skip> <vxid> <tag> <regex>
 *                         expect <skip> <vxid> <tag> <regex>
 *                         fail add <vxid> <tag> <regex>
 *                         fail clear
 *                         abort
 *                         ...
 *                 } [-start|-wait|-run]
 *
 * And once declared, you can start them, or wait on them::
 *
 *         logexpect lNAME <-start|-wait>
 *
 * With:
 *
 * lNAME
 *         Name the logexpect thread, it must start with 'l'.
 *
 * \-v id
 *         Specify the vinyl instance to use (most of the time, id=v1).
 *
 * \-g <session|request|vxid|raw
 *         Decide how records are grouped, see -g in ``man vinyllog`` for more
 *         information.
 *
 * \-d <0|1>
 *         Start processing log records at the head of the log instead of the
 *         tail.
 *
 * \-q query
 *         Filter records using a query expression, see ``man vsl-query`` for
 *         more information. Multiple -q options are not supported.
 *
 * \-m
 *         Also emit log records for misses (only for debugging)
 *
 * \-err
 *         Invert the meaning of success. Usually called once to expect the
 *         logexpect to fail
 *
 * \-start
 *         Start the logexpect thread in the background.
 *
 * \-wait
 *         Wait for the logexpect thread to finish
 *
 * \-run
 *        Equivalent to "-start -wait".
 *
 * VSL arguments (similar to the vinyllog options):
 *
 * \-C
 *         Use caseless regex
 *
 * \-i <taglist>
 *         Include tags
 *
 * \-I <[taglist:]regex>
 *         Include by regex
 *
 * \-T <seconds>
 *         Transaction end timeout
 *
 * expect specification:
 *
 * skip: [uint|*|?]
 *         Max number of record to skip
 *
 * vxid: [uint|*|=]
 *         vxid to match
 *
 * tag:  [tagname|*|=]
 *         Tag to match against
 *
 * regex:
 *         regular expression to match against (optional)
 *
 * For skip, vxid and tag, '*' matches anything, '=' expects the value of the
 * previous matched record. The '?' marker is equivalent to zero, expecting a
 * match on the next record. The difference is that '?' can be used when the
 * order of individual consecutive logs is not deterministic. In other words,
 * lines from a block of alternatives marked by '?' can be matched in any order,
 * but all need to match eventually.
 *
 * fail specification:
 *
 * add: Add to the fail list
 *
 *      Arguments are equivalent to expect, except for skip missing
 *
 * clear: Clear the fail list
 *
 * Any number of fail specifications can be active during execution of
 * a logexpect. All active fail specifications are matched against every
 * log line and, if any match, the logexpect fails immediately.
 *
 * For a logexpect to end successfully, there must be no specs on the fail list,
 * so logexpects should always end with
 *
 *      expect <skip> <vxid> <tag> <termination-condition>
 *      fail clear
 *
 * .. XXX can we come up with a better solution which is still safe?
 *
 * abort specification:
 *
 * abort(3) vinyltest, intended to help debugging of the VSL client library
 * itself.
 */

#include "config.h"

#include <pthread.h>
#include <signal.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>

#include "vapi/vsm.h"
#include "vapi/vsl.h"

#include "vdef.h"

#include "vas.h"
#include "miniobj.h"
#include "vqueue.h"
#include "vre.h"
#include "vsb.h"
#include "vtim.h"

#include <vtest_api.h>
#include "vtest_ext_vinyl.h"

#define LE_ANY   (-1)
#define LE_LAST  (-2)
#define LE_ALT   (-3)
#define LE_SEEN  (-4)
#define LE_FAIL  (-5)
#define LE_CLEAR (-6)   // clear fail list
#define LE_ABORT (-7)

struct logexp_test {
        unsigned                        magic;
#define LOGEXP_TEST_MAGIC               0x6F62B350
        VTAILQ_ENTRY(logexp_test)       list;
        VTAILQ_ENTRY(logexp_test)       faillist;

        struct vsb                      *str;
        int64_t                         vxid;
        int                             tag;
        vre_t                           *vre;
        int                             skip_max;
};

VTAILQ_HEAD(tests_head,logexp_test);

struct logexp {
        unsigned                        magic;
#define LOGEXP_MAGIC                    0xE81D9F1B
        VTAILQ_ENTRY(logexp)            list;

        char                            *name;
        char                            *vname;
        struct vtclog                   *vl;
        char                            run;
        struct tests_head               tests;

        struct logexp_test              *test;
        int                             skip_cnt;
        int64_t                         vxid_last;
        int                             tag_last;

        struct tests_head               fail;

        int                             m_arg;
        int                             err_arg;
        int                             d_arg;
        enum VSL_grouping_e             g_arg;
        char                            *query;

        struct vsm                      *vsm;
        struct VSL_data                 *vsl;
        struct VSLQ                     *vslq;
        pthread_t                       tp;
};

static VTAILQ_HEAD(, logexp)            logexps =
        VTAILQ_HEAD_INITIALIZER(logexps);

static cmd_f cmd_logexp_expect;
static cmd_f cmd_logexp_fail;
static cmd_f cmd_logexp_abort;

static const struct cmds logexp_cmds[] = {
        { CMDS_MAGIC, "expect",         cmd_logexp_expect },
        { CMDS_MAGIC, "fail",           cmd_logexp_fail },
        { CMDS_MAGIC, "abort",          cmd_logexp_abort },
        { CMDS_MAGIC, NULL,             NULL },
};

static void
logexp_delete_tests(struct logexp *le)
{
        struct logexp_test *test;

        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
        while (!VTAILQ_EMPTY(&le->tests)) {
                test = VTAILQ_FIRST(&le->tests);
                CHECK_OBJ_NOTNULL(test, LOGEXP_TEST_MAGIC);
                VTAILQ_REMOVE(&le->tests, test, list);
                VSB_destroy(&test->str);
                if (test->vre)
                        VRE_free(&test->vre);
                FREE_OBJ(test);
        }
}

static void
logexp_delete(struct logexp *le)
{
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
        AZ(le->run);
        AN(le->vsl);
        VSL_Delete(le->vsl);
        AZ(le->vslq);
        logexp_delete_tests(le);
        free(le->name);
        free(le->vname);
        free(le->query);
        VSM_Destroy(&le->vsm);
        vtc_logclose(le->vl);
        FREE_OBJ(le);
}

static struct logexp *
logexp_new(const char *name, const char *varg)
{
        struct logexp *le;
        struct vsb *n_arg;

        ALLOC_OBJ(le, LOGEXP_MAGIC);
        AN(le);
        REPLACE(le->name, name);
        le->vl = vtc_logopen("%s", name);
        vtc_log_set_cmd(le->vl, logexp_cmds);
        VTAILQ_INIT(&le->tests);

        le->d_arg = 0;
        le->g_arg = VSL_g_vxid;
        le->vsm = VSM_New();
        le->vsl = VSL_New();
        AN(le->vsm);
        AN(le->vsl);

        VTAILQ_INSERT_TAIL(&logexps, le, list);

        REPLACE(le->vname, varg);

        n_arg = macro_expandf(le->vl, "${tmpdir}/%s", varg);
        if (n_arg == NULL)
                vtc_fatal(le->vl, "-v argument problems");
        if (VSM_Arg(le->vsm, 'n', VSB_data(n_arg)) <= 0)
                vtc_fatal(le->vl, "-v argument error: %s",
                    VSM_Error(le->vsm));
        VSB_destroy(&n_arg);
        if (VSM_Attach(le->vsm, -1))
                vtc_fatal(le->vl, "VSM_Attach: %s", VSM_Error(le->vsm));
        return (le);
}

static void
logexp_clean(const struct tests_head *head)
{
        struct logexp_test *test;

        VTAILQ_FOREACH(test, head, list)
                if (test->skip_max == LE_SEEN)
                        test->skip_max = LE_ALT;
}

static struct logexp_test *
logexp_alt(struct logexp_test *test)
{
        assert(test->skip_max == LE_ALT);

        do
                test = VTAILQ_NEXT(test, list);
        while (test != NULL && test->skip_max == LE_SEEN);

        if (test == NULL || test->skip_max != LE_ALT)
                return (NULL);

        return (test);
}

static void
logexp_next(struct logexp *le)
{
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);

        if (le->test && le->test->skip_max == LE_ALT) {
                /*
                 * if an alternative was not seen, continue at this expection
                 * with the next vsl
                 */
                (void)0;
        } else if (le->test) {
                CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
                le->test = VTAILQ_NEXT(le->test, list);
        } else {
                logexp_clean(&le->tests);
                VTAILQ_INIT(&le->fail);
                le->test = VTAILQ_FIRST(&le->tests);
        }

        if (le->test == NULL)
                return;

        CHECK_OBJ(le->test, LOGEXP_TEST_MAGIC);

        switch (le->test->skip_max) {
        case LE_SEEN:
                logexp_next(le);
                return;
        case LE_CLEAR:
                vtc_log(le->vl, 3, "cond | fail clear");
                VTAILQ_INIT(&le->fail);
                logexp_next(le);
                return;
        case LE_FAIL:
                vtc_log(le->vl, 3, "cond | %s", VSB_data(le->test->str));
                VTAILQ_INSERT_TAIL(&le->fail, le->test, faillist);
                logexp_next(le);
                return;
        case LE_ABORT:
                abort();
                NEEDLESS(return);
        default:
                vtc_log(le->vl, 3, "test | %s", VSB_data(le->test->str));
        }
}

enum le_match_e {
        LEM_OK,
        LEM_SKIP,
        LEM_FAIL
};

static enum le_match_e
logexp_match(const struct logexp *le, struct logexp_test *test,
    const char *data, int64_t vxid, int tag, int type, int len)
{
        const char *legend;
        int ok = 1, skip = 0, alt, fail, vxid_ok = 0;

        AN(le);
        AN(test);
        assert(test->skip_max != LE_SEEN);
        assert(test->skip_max != LE_CLEAR);

        if (test->vxid == LE_LAST) {
                if (le->vxid_last != vxid)
                        ok = 0;
                vxid_ok = ok;
        } else if (test->vxid >= 0) {
                if (test->vxid != vxid)
                        ok = 0;
                vxid_ok = ok;
        }
        if (test->tag == LE_LAST) {
                if (le->tag_last != tag)
                        ok = 0;
        } else if (test->tag >= 0) {
                if (test->tag != tag)
                        ok = 0;
        }
        if (test->vre &&
            test->tag >= 0 &&
            test->tag == tag &&
            VRE_ERROR_NOMATCH == VRE_match(test->vre, data, len, 0, NULL))
                ok = 0;

        alt = (test->skip_max == LE_ALT);
        fail = (test->skip_max == LE_FAIL);

        if (!ok && !alt && (test->skip_max == LE_ANY ||
                    test->skip_max > le->skip_cnt))
                skip = 1;

        if (skip && vxid_ok && tag == SLT_End)
                fail = 1;

        if (fail) {
                if (ok) {
                        legend = "fail";
                } else if (skip) {
                        legend = "end";
                        skip = 0;
                } else if (le->m_arg) {
                        legend = "fmiss";
                } else {
                        legend = NULL;
                }
        }
        else if (ok)
                legend = "match";
        else if (skip && le->m_arg)
                legend = "miss";
        else if (skip || alt)
                legend = NULL;
        else
                legend = "err";

        if (legend != NULL)
                vtc_log(le->vl, 4, "%-5s| %10ju %-15s %c %.*s",
                    legend, (intmax_t)vxid, VSL_tags[tag], type, len,
                    data);

        if (ok) {
                if (alt)
                        test->skip_max = LE_SEEN;
                return (LEM_OK);
        }
        if (alt) {
                test = logexp_alt(test);
                if (test == NULL)
                        return (LEM_FAIL);
                vtc_log(le->vl, 3, "alt  | %s", VSB_data(test->str));
                return (logexp_match(le, test, data, vxid, tag, type, len));
        }
        if (skip)
                return (LEM_SKIP);
        return (LEM_FAIL);
}

static enum le_match_e
logexp_failchk(const struct logexp *le,
    const char *data, int64_t vxid, int tag, int type, int len)
{
        struct logexp_test *test;
        static enum le_match_e r;

        if (VTAILQ_FIRST(&le->fail) == NULL)
                return (LEM_SKIP);

        VTAILQ_FOREACH(test, &le->fail, faillist) {
                r = logexp_match(le, test, data, vxid, tag, type, len);
                if (r == LEM_OK)
                        return (LEM_FAIL);
                assert (r == LEM_FAIL);
        }
        return (LEM_OK);
}

static int
logexp_done(const struct logexp *le)
{
        return ((VTAILQ_FIRST(&le->fail) == NULL) && le->test == NULL);
}

static int v_matchproto_(VSLQ_dispatch_f)
logexp_dispatch(struct VSL_data *vsl, struct VSL_transaction * const pt[],
    void *priv)
{
        struct logexp *le;
        struct VSL_transaction *t;
        int i;
        enum le_match_e r;
        int64_t vxid;
        int tag, type, len;
        const char *data;

        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);

        for (i = 0; (t = pt[i]) != NULL; i++) {
                while (1 == VSL_Next(t->c)) {
                        if (!VSL_Match(vsl, t->c))
                                continue;

                        AN(t->c->rec.ptr);
                        tag = VSL_TAG(t->c->rec.ptr);

                        if (tag == SLT__Batch || tag == SLT_Witness)
                                continue;

                        vxid = VSL_ID(t->c->rec.ptr);
                        data = VSL_CDATA(t->c->rec.ptr);
                        len = VSL_LEN(t->c->rec.ptr) - 1;
                        type = VSL_CLIENT(t->c->rec.ptr) ? 'c' :
                            VSL_BACKEND(t->c->rec.ptr) ? 'b' : '-';

                        r = logexp_failchk(le, data, vxid, tag, type, len);
                        if (r == LEM_FAIL)
                                return (r);
                        if (le->test == NULL) {
                                assert (r == LEM_OK);
                                continue;
                        }

                        CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);

                        r = logexp_match(le, le->test,
                            data, vxid, tag, type, len);
                        if (r == LEM_FAIL)
                                return (r);
                        if (r == LEM_SKIP) {
                                le->skip_cnt++;
                                continue;
                        }
                        assert(r == LEM_OK);
                        le->vxid_last = vxid;
                        le->tag_last = tag;
                        le->skip_cnt = 0;
                        logexp_next(le);
                        if (logexp_done(le))
                                return (1);
                }
        }
        return (0);
}

static void *
logexp_thread(void *priv)
{
        struct logexp *le;
        int i;

        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
        AN(le->run);
        AN(le->vsm);
        AN(le->vslq);

        AZ(le->test);
        vtc_log(le->vl, 4, "begin|");
        if (le->query != NULL)
                vtc_log(le->vl, 4, "qry  | %s", le->query);
        logexp_next(le);
        while (!logexp_done(le) && !vtc_stop && !vtc_error) {
                i = VSLQ_Dispatch(le->vslq, logexp_dispatch, le);
                if (i == 2 && le->err_arg) {
                        vtc_log(le->vl, 4, "done | failed as expected");
                        return (NULL);
                }
                if (i == 2)
                        vtc_fatal(le->vl, "bad  | expectation failed");
                else if (i < 0)
                        vtc_fatal(le->vl, "bad  | dispatch failed (%d)", i);
                else if (i == 0 && ! logexp_done(le))
                        VTIM_sleep(0.01);
        }
        if (!logexp_done(le))
                vtc_fatal(le->vl, "bad  | outstanding expectations");
        vtc_log(le->vl, 4, "done |");

        return (NULL);
}

static void
logexp_close(struct logexp *le)
{

        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
        AN(le->vsm);
        if (le->vslq)
                VSLQ_Delete(&le->vslq);
        AZ(le->vslq);
}

static void
logexp_start(struct logexp *le)
{
        struct VSL_cursor *c;

        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
        AN(le->vsl);
        AZ(le->vslq);

        AN(le->vsl);
        (void)VSM_Status(le->vsm);
        c = VSL_CursorVSM(le->vsl, le->vsm,
            (le->d_arg ? 0 : VSL_COPT_TAIL) | VSL_COPT_BATCH);
        if (c == NULL)
                vtc_fatal(le->vl, "VSL_CursorVSM: %s", VSL_Error(le->vsl));
        le->vslq = VSLQ_New(le->vsl, &c, le->g_arg, le->query);
        if (le->vslq == NULL) {
                VSL_DeleteCursor(c);
                vtc_fatal(le->vl, "VSLQ_New: %s", VSL_Error(le->vsl));
        }
        AZ(c);

        le->test = NULL;
        le->skip_cnt = 0;
        le->vxid_last = le->tag_last = -1;
        le->run = 1;
        PTOK(pthread_create(&le->tp, NULL, logexp_thread, le));
}

static void
logexp_wait(struct logexp *le)
{
        void *res;

        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
        vtc_log(le->vl, 2, "Waiting for logexp");
        PTOK(pthread_join(le->tp, &res));
        logexp_close(le);
        if (res != NULL && !vtc_stop)
                vtc_fatal(le->vl, "logexp returned \"%p\"", (char *)res);
        le->run = 0;
}

/* shared by expect and fail: parse from av[2] (vxid) onwards */

static void
cmd_logexp_common(struct logexp *le, struct vtclog *vl,
    int skip_max, char * const *av)
{
        vre_t *vre;
        struct vsb vsb[1];
        int64_t vxid;
        int err, pos, tag;
        struct logexp_test *test;
        char *end, errbuf[VRE_ERROR_LEN];

        if (!vstrcmp(av[2], "*"))
                vxid = LE_ANY;
        else if (!vstrcmp(av[2], "="))
                vxid = LE_LAST;
        else {
                vxid = strtoll(av[2], &end, 10);
                if (*end != '\0' || vxid < 0)
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[2]);
        }
        if (!vstrcmp(av[3], "*"))
                tag = LE_ANY;
        else if (!vstrcmp(av[3], "="))
                tag = LE_LAST;
        else {
                tag = VSL_Name2Tag(av[3], vstrlen(av[3]));
                if (tag < 0)
                        vtc_fatal(vl, "Unknown tag name: '%s'", av[3]);
        }
        vre = NULL;
        if (av[4]) {
                vre = VRE_compile(av[4], 0, &err, &pos, 1);
                if (vre == NULL) {
                        AN(VSB_init(vsb, errbuf, sizeof errbuf));
                        AZ(VRE_error(vsb, err));
                        AZ(VSB_finish(vsb));
                        VSB_fini(vsb);
                        vtc_fatal(vl, "Regex error (%s): '%s' pos %d",
                            errbuf, av[4], pos);
                }
        }

        ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
        AN(test);
        test->str = VSB_new_auto();
        AN(test->str);
        AZ(VSB_printf(test->str, "%s %s %s %s ", av[0], av[1], av[2], av[3]));
        if (av[4])
                VSB_quote(test->str, av[4], -1, 0);
        AZ(VSB_finish(test->str));
        test->skip_max = skip_max;
        test->vxid = vxid;
        test->tag = tag;
        test->vre = vre;
        VTAILQ_INSERT_TAIL(&le->tests, test, list);
}

static void
cmd_logexp_expect(CMD_ARGS)
{
        struct logexp *le;
        int skip_max;
        char *end;

        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);
        if (av[1] == NULL || av[2] == NULL || av[3] == NULL)
                vtc_fatal(vl, "Syntax error");

        if (av[4] != NULL && av[5] != NULL)
                vtc_fatal(vl, "Syntax error");

        if (!vstrcmp(av[1], "*"))
                skip_max = LE_ANY;
        else if (!vstrcmp(av[1], "?"))
                skip_max = LE_ALT;
        else {
                skip_max = (int)strtol(av[1], &end, 10);
                if (*end != '\0' || skip_max < 0)
                        vtc_fatal(vl, "Not a positive integer: '%s'", av[1]);
        }
        cmd_logexp_common(le, vl, skip_max, av);
}

static void
cmd_logexp_fail(CMD_ARGS)
{
        struct logexp *le;
        struct logexp_test *test;

        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);

        if (av[1] == NULL)
                vtc_fatal(vl, "Syntax error");

        if (!vstrcmp(av[1], "clear")) {
                ALLOC_OBJ(test, LOGEXP_TEST_MAGIC);
                AN(test);
                test->skip_max = LE_CLEAR;
                test->str = VSB_new_auto();
                AN(test->str);
                AZ(VSB_printf(test->str, "%s %s",
                    av[0], av[1]));
                AZ(VSB_finish(test->str));

                VTAILQ_INSERT_TAIL(&le->tests, test, list);
                return;
        }

        if (vstrcmp(av[1], "add"))
                vtc_fatal(vl, "Unknown fail argument '%s'", av[1]);

        if (av[2] == NULL || av[3] == NULL)
                vtc_fatal(vl, "Syntax error");

        cmd_logexp_common(le, vl, LE_FAIL, av);
}

/* aid vsl debugging */
static void
cmd_logexp_abort(CMD_ARGS)
{

        struct logexp *le;

        CAST_OBJ_NOTNULL(le, priv, LOGEXP_MAGIC);

        cmd_logexp_common(le, vl, LE_ABORT, av);
}

static void
logexp_spec(struct logexp *le, const char *spec)
{
        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);

        logexp_delete_tests(le);

        parse_string(le->vl, le, spec);
}

void
cmd_logexpect(CMD_ARGS)
{
        struct logexp *le, *le2;
        int i;

        (void)priv;

        if (av == NULL) {
                /* Reset and free */
                VTAILQ_FOREACH_SAFE(le, &logexps, list, le2) {
                        CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
                        VTAILQ_REMOVE(&logexps, le, list);
                        if (le->run) {
                                (void)pthread_cancel(le->tp);
                                logexp_wait(le);
                        }
                        logexp_delete(le);
                }
                return;
        }

        AZ(vstrcmp(av[0], "logexpect"));
        av++;

        VTC_CHECK_NAME(vl, av[0], "Logexpect", 'l');
        VTAILQ_FOREACH(le, &logexps, list) {
                if (!vstrcmp(le->name, av[0]))
                        break;
        }
        if (le == NULL) {
                if (vstrcmp(av[1], "-v") || av[2] == NULL)
                        vtc_fatal(vl, "new logexp lacks -v");
                le = logexp_new(av[0], av[2]);
                av += 2;
        }
        av++;

        for (; *av != NULL; av++) {
                if (vtc_error)
                        break;
                if (!vstrcmp(*av, "-wait")) {
                        if (!le->run)
                                vtc_fatal(le->vl, "logexp not -started '%s'",
                                        *av);
                        logexp_wait(le);
                        continue;
                }

                /*
                 * We do an implicit -wait if people muck about with a
                 * running logexp.
                 */
                if (le->run)
                        logexp_wait(le);
                AZ(le->run);

                if (!vstrcmp(*av, "-v")) {
                        if (av[1] == NULL || vstrcmp(av[1], le->vname))
                                vtc_fatal(le->vl, "-v argument cannot change");
                        av++;
                        continue;
                }
                if (!vstrcmp(*av, "-d")) {
                        if (av[1] == NULL)
                                vtc_fatal(le->vl, "Missing -d argument");
                        le->d_arg = atoi(av[1]);
                        av++;
                        continue;
                }
                if (!vstrcmp(*av, "-g")) {
                        if (av[1] == NULL)
                                vtc_fatal(le->vl, "Missing -g argument");
                        i = VSLQ_Name2Grouping(av[1], vstrlen(av[1]));
                        if (i < 0)
                                vtc_fatal(le->vl, "Unknown grouping '%s'",
                                    av[1]);
                        le->g_arg = (enum VSL_grouping_e)i;
                        av++;
                        continue;
                }
                if (!vstrcmp(*av, "-q")) {
                        if (av[1] == NULL)
                                vtc_fatal(le->vl, "Missing -q argument");
                        REPLACE(le->query, av[1]);
                        av++;
                        continue;
                }
                if (!vstrcmp(*av, "-m")) {
                        le->m_arg = !le->m_arg;
                        continue;
                }
                if (!vstrcmp(*av, "-err")) {
                        le->err_arg = !le->err_arg;
                        continue;
                }
                if (!vstrcmp(*av, "-start")) {
                        logexp_start(le);
                        continue;
                }
                if (!vstrcmp(*av, "-run")) {
                        logexp_start(le);
                        logexp_wait(le);
                        continue;
                }
                if (**av == '-') {
                        if (av[1] != NULL) {
                                if (VSL_Arg(le->vsl, av[0][1], av[1])) {
                                        av++;
                                        continue;
                                }
                                vtc_fatal(le->vl, "%s", VSL_Error(le->vsl));
                        }
                        vtc_fatal(le->vl, "Unknown logexp argument: %s", *av);
                }
                logexp_spec(le, *av);
        }
}

#endif /* VTEST_WITH_VTC_LOGEXPECT */

		vinyl-cache/bin/vinyltest/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 vinyl 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 vinyllog`` 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 vinyllog 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) vinyltest, intended to help debugging of the VSL client library
149		* itself.
150		*/
151
152		#include "config.h"
153
154		#include <pthread.h>
155		#include <signal.h>
156		#include <stdint.h>
157		#include <stdio.h>
158		#include <stdlib.h>
159		#include <string.h>
160
161		#include "vapi/vsm.h"
162		#include "vapi/vsl.h"
163
164		#include "vdef.h"
165
166		#include "vas.h"
167		#include "miniobj.h"
168		#include "vqueue.h"
169		#include "vre.h"
170		#include "vsb.h"
171		#include "vtim.h"
172
173		#include <vtest_api.h>
174		#include "vtest_ext_vinyl.h"
175
176		#define LE_ANY (-1)
177		#define LE_LAST (-2)
178		#define LE_ALT (-3)
179		#define LE_SEEN (-4)
180		#define LE_FAIL (-5)
181		#define LE_CLEAR (-6) // clear fail list
182		#define LE_ABORT (-7)
183
184		struct logexp_test {
185		unsigned magic;
186		#define LOGEXP_TEST_MAGIC 0x6F62B350
187		VTAILQ_ENTRY(logexp_test) list;
188		VTAILQ_ENTRY(logexp_test) faillist;
189
190		struct vsb *str;
191		int64_t vxid;
192		int tag;
193		vre_t *vre;
194		int skip_max;
195		};
196
197		VTAILQ_HEAD(tests_head,logexp_test);
198
199		struct logexp {
200		unsigned magic;
201		#define LOGEXP_MAGIC 0xE81D9F1B
202		VTAILQ_ENTRY(logexp) list;
203
204		char *name;
205		char *vname;
206		struct vtclog *vl;
207		char run;
208		struct tests_head tests;
209
210		struct logexp_test *test;
211		int skip_cnt;
212		int64_t vxid_last;
213		int tag_last;
214
215		struct tests_head fail;
216
217		int m_arg;
218		int err_arg;
219		int d_arg;
220		enum VSL_grouping_e g_arg;
221		char *query;
222
223		struct vsm *vsm;
224		struct VSL_data *vsl;
225		struct VSLQ *vslq;
226		pthread_t tp;
227		};
228
229		static VTAILQ_HEAD(, logexp) logexps =
230		VTAILQ_HEAD_INITIALIZER(logexps);
231
232		static cmd_f cmd_logexp_expect;
233		static cmd_f cmd_logexp_fail;
234		static cmd_f cmd_logexp_abort;
235
236		static const struct cmds logexp_cmds[] = {
237		{ CMDS_MAGIC, "expect", cmd_logexp_expect },
238		{ CMDS_MAGIC, "fail", cmd_logexp_fail },
239		{ CMDS_MAGIC, "abort", cmd_logexp_abort },
240		{ CMDS_MAGIC, NULL, NULL },
241		};
242
243		static void
244	13671	logexp_delete_tests(struct logexp *le)
245		{
246		struct logexp_test *test;
247
248	13671	CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
249	58002	while (!VTAILQ_EMPTY(&le->tests)) {
250	44331	test = VTAILQ_FIRST(&le->tests);
251	44331	CHECK_OBJ_NOTNULL(test, LOGEXP_TEST_MAGIC);
252	44331	VTAILQ_REMOVE(&le->tests, test, list);
253	44331	VSB_destroy(&test->str);
254	44331	if (test->vre)
255	36750	VRE_free(&test->vre);
256	44331	FREE_OBJ(test);
257		}
258	13671	}
259
260		static void
261	6237	logexp_delete(struct logexp *le)
262		{
263	6237	CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
264	6237	AZ(le->run);
265	6237	AN(le->vsl);
266	6237	VSL_Delete(le->vsl);
267	6237	AZ(le->vslq);
268	6237	logexp_delete_tests(le);
269	6237	free(le->name);
270	6237	free(le->vname);
271	6237	free(le->query);
272	6237	VSM_Destroy(&le->vsm);
273	6237	vtc_logclose(le->vl);
274	6237	FREE_OBJ(le);
275	6237	}
276
277		static struct logexp *
278	6237	logexp_new(const char name, const char varg)
279		{
280		struct logexp *le;
281		struct vsb *n_arg;
282
283	6237	ALLOC_OBJ(le, LOGEXP_MAGIC);
284	6237	AN(le);
285	6237	REPLACE(le->name, name);
286	6237	le->vl = vtc_logopen("%s", name);
287	6237	vtc_log_set_cmd(le->vl, logexp_cmds);
288	6237	VTAILQ_INIT(&le->tests);
289
290	6237	le->d_arg = 0;
291	6237	le->g_arg = VSL_g_vxid;
292	6237	le->vsm = VSM_New();
293	6237	le->vsl = VSL_New();
294	6237	AN(le->vsm);
295	6237	AN(le->vsl);
296
297	6237	VTAILQ_INSERT_TAIL(&logexps, le, list);
298
299	6237	REPLACE(le->vname, varg);
300
301	6237	n_arg = macro_expandf(le->vl, "${tmpdir}/%s", varg);
302	6237	if (n_arg == NULL)
303	0	vtc_fatal(le->vl, "-v argument problems");
304	6237	if (VSM_Arg(le->vsm, 'n', VSB_data(n_arg)) <= 0)
305	0	vtc_fatal(le->vl, "-v argument error: %s",
306	0	VSM_Error(le->vsm));
307	6237	VSB_destroy(&n_arg);
308	6237	if (VSM_Attach(le->vsm, -1))
309	0	vtc_fatal(le->vl, "VSM_Attach: %s", VSM_Error(le->vsm));
310	6237	return (le);
311		}
312
313		static void
314	7518	logexp_clean(const struct tests_head *head)
315		{
316		struct logexp_test *test;
317
318	51933	VTAILQ_FOREACH(test, head, list)
319	44415	if (test->skip_max == LE_SEEN)
320	0	test->skip_max = LE_ALT;
321	7518	}
322
323		static struct logexp_test *
324	105	logexp_alt(struct logexp_test *test)
325		{
326	105	assert(test->skip_max == LE_ALT);
327
328	105	do
329	231	test = VTAILQ_NEXT(test, list);
330	126	while (test != NULL && test->skip_max == LE_SEEN);
331
332	105	if (test == NULL \|\| test->skip_max != LE_ALT)
333	0	return (NULL);
334
335	105	return (test);
336	105	}
337
338		static void
339	51996	logexp_next(struct logexp *le)
340		{
341	51996	CHECK_OBJ_NOTNULL(le, LOGEXP_MAGIC);
342
343	51996	if (le->test && le->test->skip_max == LE_ALT) {
344		/*
345		* if an alternative was not seen, continue at this expection
346		* with the next vsl
347		*/
348		(void)0;
349	51996	} else if (le->test) {
350	44415	CHECK_OBJ_NOTNULL(le->test, LOGEXP_TEST_MAGIC);
351	44415	le->test = VTAILQ_NEXT(le->test, list);
352	44415	} else {
353	7518	logexp_clean(&le->tests);
354	7518	VTAILQ_INIT(&le->fail);
355	7518	le->test = VTAILQ_FIRST(&le->tests);
356		}
357
358	51996	if (le->test == NULL)
359	7518	return;
360
361	44478	CHECK_OBJ(le->test, LOGEXP_TEST_MAGIC);
362
363	44478	switch (le->test->skip_max) {
364		case LE_SEEN:
365	63	logexp_next(le);
366	63	return;
367		case LE_CLEAR:
368	2079	vtc_log(le->vl, 3, "cond \| fail clear");
369	2079	VTAILQ_INIT(&le->fail);
370	2079	logexp_next(le);
371	2079	return;
372		case LE_FAIL:
373	2373	vtc_log(le->vl, 3, "cond \| %s", VSB_data(le->test->str));
374	2373	VTAILQ_INSERT_TAIL(&le->fail, le->test, faillist);
375	2373	logexp_next(le);
376	2373	return;
377		case LE_ABORT:
378	0	abort();
379		NEEDLESS(return);
380		default:
381	39963	vtc_log(le->vl, 3, "test \| %s", VSB_data(le->test->str));
382	39963	}
383	51996	}
384
385		enum le_match_e {
386		LEM_OK,
387		LEM_SKIP,
388		LEM_FAIL
389		};
390
391		static enum le_match_e
392	741654	logexp_match(const struct logexp le, struct logexp_test test,
393		const char *data, int64_t vxid, int tag, int type, int len)
394		{
395		const char *legend;
396	741654	int ok = 1, skip = 0, alt, fail, vxid_ok = 0;
397
398	741654	AN(le);
399	741654	AN(test);
400	741654	assert(test->skip_max != LE_SEEN);
401	741654	assert(test->skip_max != LE_CLEAR);
402
403	741654	if (test->vxid == LE_LAST) {
404	106251	if (le->vxid_last != vxid)
405	7480	ok = 0;
406	106251	vxid_ok = ok;
407	741654	} else if (test->vxid >= 0) {
408	197471	if (test->vxid != vxid)
409	136029	ok = 0;
410	197471	vxid_ok = ok;
411	197471	}
412	741654	if (test->tag == LE_LAST) {
413	13	if (le->tag_last != tag)
414	0	ok = 0;
415	741654	} else if (test->tag >= 0) {
416	741641	if (test->tag != tag)
417	668365	ok = 0;
418	741641	}
419	811409	if (test->vre &&
420	639184	test->tag >= 0 &&
421	639184	test->tag == tag &&
422	69755	VRE_ERROR_NOMATCH == VRE_match(test->vre, data, len, 0, NULL))
423	33089	ok = 0;
424
425	741644	alt = (test->skip_max == LE_ALT);
426	741644	fail = (test->skip_max == LE_FAIL);
427
428	741644	if (!ok && !alt && (test->skip_max == LE_ANY \|\|
429	128243	test->skip_max > le->skip_cnt))
430	577034	skip = 1;
431
432	741644	if (skip && vxid_ok && tag == SLT_End)
433	0	fail = 1;
434
435	741644	if (fail) {
436	124547	if (ok) {
437	21	legend = "fail";
438	124547	} else if (skip) {
439	0	legend = "end";
440	0	skip = 0;
441	124526	} else if (le->m_arg) {
442	0	legend = "fmiss";
443	0	} else {
444	124526	legend = NULL;
445		}
446	124547	}
447	617097	else if (ok)
448	39963	legend = "match";
449	577134	else if (skip && le->m_arg)
450	483	legend = "miss";
451	576651	else if (skip \|\| alt)
452	576651	legend = NULL;
453		else
454	0	legend = "err";
455
456	741644	if (legend != NULL)
457	80934	vtc_log(le->vl, 4, "%-5s\| %10ju %-15s %c %.*s",
458	40467	legend, (intmax_t)vxid, VSL_tags[tag], type, len,
459	40467	data);
460
461	741644	if (ok) {
462	39985	if (alt)
463	462	test->skip_max = LE_SEEN;
464	39985	return (LEM_OK);
465		}
466	701659	if (alt) {
467	105	test = logexp_alt(test);
468	105	if (test == NULL)
469	0	return (LEM_FAIL);
470	105	vtc_log(le->vl, 3, "alt \| %s", VSB_data(test->str));
471	105	return (logexp_match(le, test, data, vxid, tag, type, len));
472		}
473	701554	if (skip)
474	577028	return (LEM_SKIP);
475	124526	return (LEM_FAIL);
476	741644	}
477
478		static enum le_match_e
479	617302	logexp_failchk(const struct logexp *le,
480		const char *data, int64_t vxid, int tag, int type, int len)
481		{
482		struct logexp_test *test;
483		static enum le_match_e r;
484
485	617302	if (VTAILQ_FIRST(&le->fail) == NULL)
486	535551	return (LEM_SKIP);
487
488	206277	VTAILQ_FOREACH(test, &le->fail, faillist) {
489	124547	r = logexp_match(le, test, data, vxid, tag, type, len);
490	124547	if (r == LEM_OK)
491	21	return (LEM_FAIL);
492	124526	assert (r == LEM_FAIL);
493	124526	}
494	81730	return (LEM_OK);
495	617302	}
496
497		static int
498	992184	logexp_done(const struct logexp *le)
499		{