/* EventLog - test facility to verify the occurrence of expected events Copyright (C) Lumiera.org 2018, Hermann Vosseler This program is free software; you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation; either version 2 of the License, or (at your option) any later version. This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with this program; if not, write to the Free Software Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA. * *****************************************************/ /** @file event-log.cpp ** Implementation details of event logging and verification for unit tests. ** The EventLog is a helper for writing tests or for special rigging within ** the test or debugging or mock variant of some common services. It allows ** to log some events to memory and then to build match expressions to verify ** those captured information. ** ** The machinery for matching on the occurrence of some events can be quite ** intricate at implementation level; we use an implementation based on a ** filtering iterator pipeline. This kind of code is template heavy and ** can cause a significant increase of generated code size -- especially ** on debug builds. For that reason, we prefer to call through regular ** (non-inline) functions and package all the actual implementation ** code into this dedicated translation unit. ** ** @see EventLog_test ** @see IterChainSearch_test ** @see iter-explorer.hpp ** */ #include "lib/error.hpp" #include "lib/test/event-log.hpp" namespace lib { namespace test{ namespace error = lumiera::error; using util::stringify; using util::contains; using util::isnil; using lib::Symbol; using std::string; namespace { /* == elementary matchers == */ using Filter = decltype( buildSearchFilter (std::declval()) ); using ArgSeq = lib::diff::RecordSetup::Storage; using RExSeq = std::vector; inline auto find (string match) { return [=](Entry const& entry) { return contains (string(entry), match); }; } inline auto findRegExp (string regExpDef) { std::regex regExp(regExpDef); return [=](Entry const& entry) { return std::regex_search(string(entry), regExp); }; } inline auto findEvent (string match) { return [=](Entry const& entry) { return ( entry.getType() == "event" or entry.getType() == "error" or entry.getType() == "create" or entry.getType() == "destroy" or entry.getType() == "logJoin" ) and not isnil(entry.scope()) and contains (*entry.scope(), match); }; } inline auto findEvent (string classifier, string match) { return [=](Entry const& entry) { return ( entry.getType() == classifier or (entry.hasAttribute("ID") and contains (entry.get("ID"), classifier)) ) and not isnil(entry.scope()) and contains (*entry.scope(), match); }; } inline auto findCall (string match) { return [=](Entry const& entry) { return entry.getType() == "call" and contains (entry.get("fun"), match); }; } /** this filter functor is for refinement of an existing filter * @param argSeq perform a substring match consecutively * for each of the log entry's arguments * @note the match also fails, when the given log entry * has more or less arguments, than the number of * given match expressions in `argSeq` * @see ExtensibleFilterIter::andFilter() */ inline auto matchArguments (ArgSeq&& argSeq) { return [=](Entry const& entry) { auto scope = entry.scope(); for (auto const& match : argSeq) if (isnil (scope) or not contains(*scope, match)) return false; else ++scope; return isnil(scope); // must be exhausted by now }; // otherwise the sizes do not match... } /** refinement filter to match a specific positional argument */ inline auto matchArgument (size_t idx, string match) { return [=](Entry const& entry) { return idx < entry.childSize() and contains (entry.child(idx), match); }; } /** refinement filter, to cover all arguments by regular expression(s) * @param regExpSeq several regular expressions, which, when applied * consecutively until exhaustion, must cover and verify _all_ * arguments of the log entry. * @remarks to explain, we "consume" arguments with a regExp from the list, * and when this one doesn't match anymore, we try the next one. * When we'ver tried all regular expressions, we must have also * consumed all arguments, otherwise we fail. */ inline auto matchArgsRegExp (RExSeq&& regExpSeq) { return [=](Entry const& entry) { auto scope = entry.scope(); for (auto const& rex : regExpSeq) { if (isnil (scope)) return false; while (scope and std::regex_search(*scope, rex)) ++scope; } return isnil(scope); // must be exhausted by now }; // otherwise we didn't get full coverage... } /** refinement filter to match on the given typeID */ inline auto matchType (string typeID) { return [=](Entry const& entry) { return contains (entry.getType(), typeID); }; } /** refinement filter to ensure a specific attribute is present on the log entry */ inline auto ensureAttribute (string key) { return [=](Entry const& entry) { return entry.hasAttribute(key); }; } /** refinement filter to ensure a specific attribute is present on the log entry */ inline auto matchAttribute (string key, string valueMatch) { return [=](Entry const& entry) { return entry.hasAttribute(key) and contains (entry.get(key), valueMatch); }; } /* === configure the underlying search engine === */ enum Direction { FORWARD, BACKWARD, CURRENT }; template inline void attachNextSerchStep (Filter& solution, COND&& searchCond, Direction direction) { if (CURRENT == direction) solution.search (forward (searchCond)); else solution.addStep ([predicate{forward (searchCond)}, direction] (auto& filter) { filter.reverse (BACKWARD == direction); filter.disableFilter(); // deactivate any filtering temporarily ++filter; // move one step in the required direction filter.setNewFilter (predicate); }); } template inline void refineSerach (Filter& solution, COND&& additionalCond) { solution.addStep ([predicate{forward (additionalCond)}] (auto& filter) { filter.andFilter (predicate); }); } }//(End) Elementary Matchers and handling of the search engine EventMatch::EventMatch (Log const& srcSeq) : solution_{buildSearchFilter (srcSeq)} , lastMatch_{"HEAD "+ solution_->get("this")} , look_for_match_{true} , violation_{} { } /** core of the evaluation machinery: * apply a filter predicate and then pull * through the log to find a acceptable entry */ bool EventMatch::foundSolution() { return not isnil (solution_); } /** this is actually called after each refinement of * the filter and matching conditions. The effect is to search * for an (intermediary) solution right away and to mark failure * as soon as some condition can not be satisfied. Rationale is to * indicate the point where a chained match fails * @see ::operator bool() for extracting the result * @param matchSpec diagnostics description of the predicate just being added * @param rel indication of the searching relation / direction */ void EventMatch::evaluateQuery (string matchSpec, Literal rel) { if (look_for_match_ and not isnil (violation_)) return; // already failed, no further check necessary if (foundSolution()) // NOTE this pulls the filter { lastMatch_ = matchSpec+" @ "+string(*solution_) + (isnil(lastMatch_)? "" : "\n.."+rel+" "+lastMatch_); if (not look_for_match_) violation_ = "FOUND at least "+lastMatch_; } else { if (look_for_match_) violation_ = "FAILED to "+matchSpec + "\n.."+rel + " "+lastMatch_; else violation_ = ""; } } /** * basic search function: continue linear lookup over the elements of the * EventLog to find a match (substring match) of the given text. The search begins * at the current position and proceeds in the currently configured direction. * Initially the search starts at the first record and proceeds forward. */ EventMatch& EventMatch::locate (string match) { attachNextSerchStep (solution_, find(match), CURRENT); evaluateQuery ("match(\""+match+"\")"); return *this; } /** * basic search like locate() but with the given regular expression */ EventMatch& EventMatch::locateMatch (string regExp) { attachNextSerchStep (solution_, findRegExp(regExp), CURRENT); evaluateQuery ("find-RegExp(\""+regExp+"\")"); return *this; } /** * basic search for a matching "event" * @param match perform a substring match against the arguments of the event * @see beforeEvent() for a description of possible "events" */ EventMatch& EventMatch::locateEvent (string match) { attachNextSerchStep (solution_, findEvent(match), CURRENT); evaluateQuery ("match-event(\""+match+"\")"); return *this; } EventMatch& EventMatch::locateEvent (string classifier, string match) { attachNextSerchStep (solution_, findEvent(classifier,match), CURRENT); evaluateQuery ("match-event(ID=\""+classifier+"\", \""+match+"\")"); return *this; } /** * basic search for some specific function invocation * @param match perform a substring match against the name of the function invoked */ EventMatch& EventMatch::locateCall (string match) { attachNextSerchStep (solution_, findCall(match), CURRENT); evaluateQuery ("match-call(\""+match+"\")"); return *this; } /** * find a match (substring match) of the given text * in an EventLog entry after the current position * @remarks the name of this junctor might seem counter intuitive; * it was chosen due to expected DSL usage: `log.verify("α").before("β")`. * Operationally this means first to find a Record matching the substring "α" * and then to forward from this point until hitting a record to match "β". */ EventMatch& EventMatch::before (string match) { attachNextSerchStep (solution_, find(match), FORWARD); evaluateQuery ("match(\""+match+"\")"); return *this; } /** * find a match with the given regular expression */ EventMatch& EventMatch::beforeMatch (string regExp) { attachNextSerchStep (solution_, findRegExp(regExp), FORWARD); evaluateQuery ("find-RegExp(\""+regExp+"\")"); return *this; } /** * find a match for an "event" _after_ the current point of reference * @remarks the term "event" designates several types of entries, which * typically capture something happening within the observed entity. * Especially, the following [record types](\ref lib::Record::getType()) * qualify as event: * - `event` * - `error` * - `create` * - `destroy` * - `logJoin` * @param match perform a substring match against the arguments of the event * @see ::findEvent */ EventMatch& EventMatch::beforeEvent (string match) { attachNextSerchStep (solution_, findEvent(match), FORWARD); evaluateQuery ("match-event(\""+match+"\")"); return *this; } EventMatch& EventMatch::beforeEvent (string classifier, string match) { attachNextSerchStep (solution_, findEvent(classifier,match), FORWARD); evaluateQuery ("match-event(ID=\""+classifier+"\", \""+match+"\")"); return *this; } /** * find a match for some function invocation _after_ the current point of reference * @param match perform a substring match against the name of the function invoked * @see ::findCall */ EventMatch& EventMatch::beforeCall (string match) { attachNextSerchStep (solution_, findCall(match), FORWARD); evaluateQuery ("match-call(\""+match+"\")"); return *this; } /** * find a match (substring match) of the given text * in an EventLog entry _before_ the current position, * switching to backwards search direction */ EventMatch& EventMatch::after (string match) { attachNextSerchStep (solution_, find(match), BACKWARD); evaluateQuery ("match(\""+match+"\")", "before"); return *this; } EventMatch& EventMatch::afterMatch (string regExp) { attachNextSerchStep (solution_, findRegExp(regExp), BACKWARD); evaluateQuery ("find-RegExp(\""+regExp+"\")", "before"); return *this; } EventMatch& EventMatch::afterEvent (string match) { attachNextSerchStep (solution_, findEvent(match), BACKWARD); evaluateQuery ("match-event(\""+match+"\")", "before"); return *this; } EventMatch& EventMatch::afterEvent (string classifier, string match) { attachNextSerchStep (solution_, findEvent(classifier,match), BACKWARD); evaluateQuery ("match-event(ID=\""+classifier+"\", \""+match+"\")", "before"); return *this; } /** * find a function invocation backwards, before the current point of reference */ EventMatch& EventMatch::afterCall (string match) { attachNextSerchStep (solution_, findCall(match), BACKWARD); evaluateQuery ("match-call(\""+match+"\")", "before"); return *this; } /** * @internal refine filter condition additionally to match a specific positional call argument. */ void EventMatch::refineSerach_matchArgument (size_t idx, string match) { refineSerach (solution_, matchArgument(idx, match)); evaluateQuery ("match-argument(["+util::toString(idx)+"]="+match+")"); } /** * @internal refine filter condition additionally to match a sequence of call arguments. */ void EventMatch::refineSerach_matchArguments (ArgSeq&& argSeq) { string argList(util::join(argSeq)); refineSerach (solution_, matchArguments(move(argSeq))); evaluateQuery ("match-arguments("+argList+")"); } /** * @internal refine filter condition additionally to cover call arguments by * a sequence of regular expressions. Each regExp is used consecutively, * until it fails to match; at that point, the next regExp is tried. * When reaching the end of the argument sequence, we also expect * to have used up all available regular expressions. */ void EventMatch::refineSerach_matchArgsRegExp (RExSeq&& regExpSeq, string rendered_regExps) { refineSerach (solution_, matchArgsRegExp (move (regExpSeq))); evaluateQuery ("match-args-RegExp("+rendered_regExps+")"); } /** * refine filter to additionally require a matching log entry type */ EventMatch& EventMatch::type (string typeID) { refineSerach (solution_, matchType(typeID)); evaluateQuery ("match-type("+typeID+")"); return *this; } /** * refine filter to additionally require the presence an attribute */ EventMatch& EventMatch::key (string key) { refineSerach (solution_, ensureAttribute(key)); evaluateQuery ("ensure-attribute("+key+")"); return *this; } /** * refine filter to additionally match on a specific attribute */ EventMatch& EventMatch::attrib (string key, string valueMatch) { refineSerach (solution_, matchAttribute(key,valueMatch)); evaluateQuery ("match-attribute("+key+"=\""+valueMatch+"\")"); return *this; } /** * refine filter to additionally match on the ID attribute */ EventMatch& EventMatch::id (string classifier) { refineSerach (solution_, matchAttribute("ID",classifier)); evaluateQuery ("match-ID(\""+classifier+"\")"); return *this; } /** * refine filter to additionally match the `'this'` attribute */ EventMatch& EventMatch::on (string targetID) { refineSerach (solution_, matchAttribute("this",targetID)); evaluateQuery ("match-this(\""+targetID+"\")"); return *this; } EventMatch& EventMatch::on (const char* targetID) { refineSerach (solution_, matchAttribute("this",targetID)); evaluateQuery ("match-this(\""+string(targetID)+"\")"); return *this; } /* ==== EventLog implementation ==== */ EventLog::EventLog (string logID) : log_(new Log) { log({"type=EventLogHeader", "this="+logID}); } /** * @remarks EventLog uses a heap based, sharable log storage, * where the EventLog object is just a front-end (shared ptr). * The `joinInto` operation both integrates this logs contents * into the other log, and then disconnects from the old storage * and connects to the storage of the combined log. * @warning beware of clone copies. Since copying EventLog is always a * shallow copy, all copied handles actually refer to the same * log storage. If you invoke `joinInto` in such a situation, * only the current EventLog front-end handle will be rewritten * to point to the combined log, while any other clone will * continue to point to the original log storage. */ EventLog& EventLog::joinInto (EventLog& otherLog) { Log& target = *otherLog.log_; target.reserve (target.size() + log_->size() + 1); target.emplace_back (log_->front()); auto p = log_->begin(); while (++p != log_->end()) // move our log's content into the other log target.emplace_back (std::move(*p)); this->log_->resize(1); this->log({"type=joined", otherLog.getID()}); // leave a tag to indicate otherLog.log({"type=logJoin", this->getID()}); // where the `joinInto` took place, this->log_ = otherLog.log_; // connect this to the other storage return *this; } EventLog& EventLog::clear() { string originalLogID = this->getID(); return this->clear (originalLogID); } /** purge log contents and also reset Header-ID * @note actually we're starting a new log * and let the previous one go away. * @warning while this also unties any joined logs, * other log front-ends might still hold onto * the existing, combined log. Just we are * detached and writing to a pristine log. */ EventLog& EventLog::clear (string alteredLogID) { log_.reset (new Log); log({"type=EventLogHeader", "this="+alteredLogID}); return *this; } EventLog& EventLog::clear (const char* alteredLogID) { return clear (string{alteredLogID}); } /* ==== Logging API ==== */ EventLog& EventLog::event (string text) { log ("event", ArgSeq{}, ArgSeq{text}); // we use this ctor variant to ensure return *this; // that text is not misinterpreted as attribute, } // which might happen when text contains a '=' EventLog& EventLog::event (string classifier, string text) { log ("event", ArgSeq{"ID="+classifier}, ArgSeq{text}); return *this; } EventLog& EventLog::call (string target, string function) { return call(target, function, ArgSeq()); } EventLog& EventLog::call (string target, string function, ArgSeq&& args) { log ("call", ArgSeq{"fun="+function, "this="+target}, std::forward(args)); return *this; } EventLog& EventLog::call (const char* target, const char* function, ArgSeq&& args) { return call (string(target), string(function), std::forward(args)); } EventLog& EventLog::warn (string text) { log({"type=warn", text}); return *this; } EventLog& EventLog::error (string text) { log({"type=error", text}); return *this; } EventLog& EventLog::fatal (string text) { log({"type=fatal", text}); return *this; } EventLog& EventLog::create (string text) { log({"type=create", text}); return *this; } EventLog& EventLog::destroy (string text) { log({"type=destroy", text}); return *this; } /* ==== Query/Verification API ==== */ EventMatch EventLog::verify (string match) const { EventMatch matcher(*log_); matcher.locate (match); // new matcher starts linear search from first log element return matcher; } EventMatch EventLog::verifyMatch (string regExp) const { EventMatch matcher(*log_); matcher.locateMatch (regExp); return matcher; } EventMatch EventLog::verifyEvent (string match) const { EventMatch matcher(*log_); matcher.locateEvent (match); return matcher; } EventMatch EventLog::verifyEvent (string classifier, string match) const { EventMatch matcher(*log_); matcher.locateEvent (classifier, match); return matcher; } EventMatch EventLog::verifyCall (string match) const { EventMatch matcher(*log_); matcher.locateCall (match); return matcher; } /** * @remarks the query expression is built similar to the other queries, * but the logic of evaluation is flipped: whenever we find any match * the overall result (when evaluating to `bool`) will be `false`. * @note since the chained search involves backtracking, this should perform * an exhaustive negation, searching for a possible match until no * further search options are left. */ EventMatch EventLog::ensureNot (string match) const { EventMatch matcher(*log_); matcher.look_for_match_ = false; // flip logic; fail if match succeeds matcher.locate (match); return matcher; } }} // namespace lib::test