LUMIERA.clone/src/lib/test/event-log.hpp

/*
  EVENT-LOG.hpp  -  test facility to verify the occurrence of expected events

  Copyright (C)         Lumiera.org
    2015,               Hermann Vosseler <Ichthyostega@web.de>

  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.hpp
 ** Support for verifying the occurrence of events from unit tests.
 ** Typically used within special rigging and instrumentation for tests,
 ** the [EventLog] allows to record invocations and similar events. It is
 ** implemented as a "PImpl" to allow sharing of logs, which helps to trace
 ** events from transient UI elements and from destructor code. The front-end
 ** used for access offers a query facility, so the test code may express some
 ** expected patterns of incidence and verify match or non-match.
 ** 
 ** Failure of match prints a detailed trace message to `STDERR`, in order to
 ** deliver a precise indication what part of the condition failed.
 ** 
 ** @todo as of 11/2015 this is complete WIP-WIP-WIP
 ** 
 ** @see ////TODO_test usage example
 ** 
 */


#ifndef LIB_TEST_EVENT_LOG_H
#define LIB_TEST_EVENT_LOG_H


#include "lib/error.hpp"
#include "lib/idi/entry-id.hpp"
#include "lib/iter-adapter.hpp"
#include "lib/iter-cursor.hpp"
#include "lib/format-string.hpp"
#include "lib/format-util.hpp"
#include "lib/diff/record.hpp"
#include "lib/symbol.hpp"
#include "lib/util.hpp"

//#include <boost/lexical_cast.hpp>
#include <iostream>
#include <memory>
#include <vector>
#include <string>



namespace lib {
namespace test{
  namespace error = lumiera::error;
  
//  using lib::Literal;
  using std::string;
  using util::stringify;
  using util::contains;
  using util::isnil;
  using util::_Fmt;
  using lib::Symbol;
//  using std::rand;
  
  
  
  /**
   * @internal ongoing evaluation and match within an [EventLog].
   * @throws error::Fatal when the expected match fails (error::LUMIERA_ERROR_ASSERTION)
   */
  class EventMatch
    {
      using Entry = lib::diff::Record<string>;
      using Log   = std::vector<Entry>;
      using Iter  = lib::IterCursor<Log::const_iterator>;
      using Filter = ExtensibleFilterIter<Iter>;
      
      using ArgSeq = lib::diff::RecordSetup<string>::Storage;
      
      
      /** match predicate evaluator */
      Filter solution_;
      
      /** record last match for diagnostics */
      string lastMatch_;
      
      /** support for positive and negative queries.
       * @note negative queries enforced in dtor */
      bool look_for_match_;
      
      string violation_;
      
      /** core of the evaluation machinery:
       * apply a filter predicate and then pull
       * through the log to find a acceptable entry
       */
      bool
      foundSolution()
        {
          return !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
       * @par matchSpec diagnostics description of the predicate just being added
       * @par rel indication of the searching relation / direction
       */
      void
      evaluateQuery (string matchSpec, Literal rel = "after")
        {
          if (look_for_match_ and not isnil (violation_)) return;
             // already failed, no further check necessary
          
          if (foundSolution())
            {
              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_ = "";
            }
        }
      
      
      /** @internal for creating EventLog matchers */
      EventMatch(Log const& srcSeq)
        : solution_(Iter(srcSeq))
        , lastMatch_("HEAD "+ solution_->get("ID"))
        , look_for_match_(true)
        , violation_()
        { }
      
      friend class EventLog;
      
      
      /* == elementary matchers == */
      
      auto
      find (string match)
        {
          return [=](Entry const& entry)
                    {
                      return contains (string(entry), match);
                    };
        }
      
      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 contains (*entry.scope(), match);
                    };
        }
      
      auto
      findEvent (string classifier, 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"
                             or entry.getType() == classifier
                             or (entry.hasAttribute("ID") and contains (entry.get("ID"), classifier))
                             )
                         and contains (*entry.scope(), match);
                    };
        }
      
      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()
       */
      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 on the given typeID */
      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 */
      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 */
      auto
      matchAttribute (string key, string valueMatch)
        {
          return [=](Entry const& entry)
                    {
                      return entry.hasAttribute(key)
                         and contains (entry.get(key), valueMatch);
                    };
        }
      
    public:
      /** final evaluation of the match query,
       *  usually triggered from the unit test `CHECK()`.
       * @note failure cause is printed to STDERR.
       */
      operator bool()  const
        {
          if (!isnil (violation_))
            {
              std::cerr << "__Log_condition_violated__\n"+violation_ <<"\n";
              return false;
            }
          return true;
        }
      
      
      /**
       * 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&
      before (string match)
        {
          solution_.underlying().switchForwards();
          solution_.setNewFilter(find(match));
          evaluateQuery ("match(\""+match+"\")");
          return *this;
        }
      
      EventMatch&
      beforeMatch (string regExp)
        {
          UNIMPLEMENTED("process combined relational regular expression match");
        }
      
      /** 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][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&
      beforeEvent (string match)
        {
          solution_.underlying().switchForwards();
          solution_.setNewFilter(findEvent(match));
          evaluateQuery ("match-event(\""+match+"\")");
          return *this;
        }
      
      EventMatch&
      beforeEvent (string classifier, string match)
        {
          solution_.underlying().switchForwards();
          solution_.setNewFilter(findEvent(classifier,match));
          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&
      beforeCall (string match)
        {
          solution_.underlying().switchForwards();
          solution_.setNewFilter(findCall(match));
          evaluateQuery ("match-call(\""+match+"\")");
          return *this;
        }
      
      EventMatch&
      after (string match)
        {
          solution_.underlying().switchBackwards();
          solution_.setNewFilter(find(match));
          evaluateQuery ("match(\""+match+"\")", "before");
          return *this;
        }
      
      EventMatch&
      afterMatch (string regExp)
        {
          UNIMPLEMENTED("process combined relational regular expression match backwards");
        }
      
      EventMatch&
      afterEvent (string match)
        {
          solution_.underlying().switchBackwards();
          solution_.setNewFilter(findEvent(match));
          evaluateQuery ("match-event(\""+match+"\")", "before");
          return *this;
        }
      
      EventMatch&
      afterEvent (string classifier, string match)
        {
          solution_.underlying().switchBackwards();
          solution_.setNewFilter(findEvent(classifier,match));
          evaluateQuery ("match-event(ID=\""+classifier+"\", \""+match+"\")", "before");
          return *this;
        }
      
      /** find a function invocation backwards, before the current point of reference */
      EventMatch&
      afterCall (string match)
        {
          solution_.underlying().switchBackwards();
          solution_.setNewFilter(findCall(match));
          evaluateQuery ("match-call(\""+match+"\")", "before");
          return *this;
        }
      
      /** refine filter to additionally require specific arguments
       * @remarks the refined filter works on each record qualified by the
       *          query expression established thus far; it additionally
       *          looks into the arguments (children list) of the log entry.
       * @warning match is processed by comparision of string representation.
       */
      template<typename...ARGS>
      EventMatch&
      arg (ARGS const& ...args)
        {
          ArgSeq argSeq(stringify<ArgSeq> (args...));
          string argList(util::join(argSeq));
          
          solution_.andFilter (matchArguments(move(argSeq)));
          evaluateQuery ("match-arguments("+argList+")");
          return *this;
        }
      
      template<typename...ARGS>
      EventMatch&
      argMatch (ARGS const& ...regExps)
        {
          stringify<ArgSeq> (regExps...);
          
          UNIMPLEMENTED("process regular expression match on call argument list");
        }
      
      /** refine filter to additionally require a matching log entry type */
      EventMatch&
      type (string typeID)
        {
          solution_.andFilter (matchType(typeID));
          evaluateQuery ("match-type("+typeID+")");
          return *this;
        }
      
      /** refine filter to additionally require the presence an attribute */
      EventMatch&
      key (string key)
        {
          solution_.andFilter (ensureAttribute(key));
          evaluateQuery ("ensure-attribute("+key+")");
          return *this;
        }
      
      /** refine filter to additionally match on a specific attribute */
      EventMatch&
      attrib (string key, string valueMatch)
        {
          solution_.andFilter (matchAttribute(key,valueMatch));
          evaluateQuery ("match-attribute("+key+"=\""+valueMatch+"\")");
          return *this;
        }
      
      /** refine filter to additionally match on the ID attribute */
      EventMatch&
      id (string classifier)
        {
          solution_.andFilter (matchAttribute("ID",classifier));
          evaluateQuery ("match-ID(\""+classifier+"\")");
          return *this;
        }
      
      /** refine filter to additionally match the `'this'` attribute */
      EventMatch&
      on (string targetID)
        {
          solution_.andFilter (matchAttribute("this",targetID));
          evaluateQuery ("match-this(\""+targetID+"\")");
          return *this;
        }
      
      EventMatch&
      on (const char* targetID)
        {
          solution_.andFilter (matchAttribute("this",targetID));
          evaluateQuery ("match-this(\""+string(targetID)+"\")");
          return *this;
        }
      
      template<typename X>
      EventMatch&
      on (const X *const targetObj)
        {
          string targetID = idi::instanceTypeID (targetObj);
          solution_.andFilter (matchAttribute("this",targetID));
          evaluateQuery ("match-this(\""+targetID+"\")");
          return *this;
        }
    };
  
  
  
  /**
   * Helper to log and verify the occurrence of events.
   * The EventLog object is a front-end handle, logging flexible
   * [information records][lib::Record] into a possibly shared (vector)
   * buffer in heap storage. An extended query DSL allows to write
   * assertions to cover the occurrence of events in unit tests.
   * @see TestEventLog_test
   */
  class EventLog
    {
      using Entry = lib::diff::Record<string>;
      using Log   = std::vector<Entry>;
      using Iter  = lib::RangeIter<Log::const_iterator>;
      
      std::shared_ptr<Log> log_;
      
      void
      log (std::initializer_list<string> const& ili)
        {
          log_->emplace_back(ili);
        }
      
      template<typename ATTR, typename ARGS>
      void
      log (Symbol typeID, ATTR&& attribs, ARGS&& args)
        {
          log_->emplace_back(typeID, std::forward<ATTR>(attribs)
                                   , std::forward<ARGS>(args));
        }
      
      string
      getID()  const
        {
          return log_->front().get("ID");
        }
      
    public:
      explicit
      EventLog (string logID)
        : log_(new Log)
        {
          log({"type=EventLogHeader", "ID="+logID});
        }
      
      explicit
      EventLog (const char* logID)
        : EventLog(string(logID))
        { }
      
      template<class X>
      explicit
      EventLog (const X *const obj)
        : EventLog(idi::instanceTypeID (obj))
        { }
      
      
      // standard copy operations acceptable
      
      
      /** Merge this log into another log, forming a combined log
       * @param otherLog target to integrate this log's contents into.
       * @return reference to the merged new log instance
       * @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.
       * @see TestEventLog_test::verify_logJoining()
       */
      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;
        }
      
      
      
      /* ==== Logging API ==== */
      
      using ArgSeq = lib::diff::RecordSetup<string>::Storage;
      
      EventLog&
      event (string text)
        {
          log({"type=event", text});
          return *this;
        }
      
      /** log some event, with additional ID or classifier
       * @param classifier info to be saved into the `ID` attribute
       * @param text actual payload info, to be logged as argument
       */
      EventLog&
      event (string classifier, string text)
        {
          log({"type=event", "ID="+classifier, text});
          return *this;
        }
      
      /** Log occurrence of a function call with no arguments.
       * @param target the object or scope on which the function is invoked
       * @param function name of the function being invoked
       */
      EventLog&
      call (string target, string function)
        {
          return call(target, function, ArgSeq());
        }
      
      /** Log a function call with a sequence of stringified arguments */
      EventLog&
      call (string target, string function, ArgSeq&& args)
        {
          log ("call", ArgSeq{"fun="+function, "this="+target}, std::forward<ArgSeq>(args));
          return *this;
        }
      
      /** Log a function call with arbitrary arguments */
      template<typename...ARGS>
      EventLog&
      call (string target, string function, ARGS const& ...args)
        {
          return call (target, function, stringify<ArgSeq>(args...));
        }
      
      /** Log a function call on given object ("`this`")... */
      template<class X, typename...ARGS>
      EventLog&
      call (const X *const targetObj, string function, ARGS const& ...args)
        {
          return call (idi::instanceTypeID (targetObj), function, args...);
        }
      
      template<typename...ARGS>
      EventLog&
      call (const char* target, string function, ARGS const& ...args)
        {
          return call (string(target), function, args...);
        }
      
      template<typename...ELMS>
      EventLog&
      note (ELMS const& ...initialiser)
        {
          log_->emplace_back(stringify<ArgSeq> (initialiser...));
          return *this;
        }

      
      /** Log a warning entry */
      EventLog&
      warn (string text)
        {
          log({"type=warn", text});
          return *this;
        }

      
      /** Log an error note */
      EventLog&
      error (string text)
        {
          log({"type=error", text});
          return *this;
        }

      
      /** Log a fatal failure */
      EventLog&
      fatal (string text)
        {
          log({"type=fatal", text});
          return *this;
        }

      
      /** Log the creation of an object.
       *  Such an entry can be [matched as event][::verifyEvent] */
      EventLog&
      create (string text)
        {
          log({"type=create", text});
          return *this;
        }

      
      /** Log the destruction of an object.
       *  Can be matched as event. */
      EventLog&
      destroy (string text)
        {
          log({"type=destroy", text});
          return *this;
        }
      
      
      
      /* ==== Iteration ==== */
      
      bool
      empty()  const
        {
          return 1 >= log_->size();
        }
      
      
      typedef Iter const_iterator;
      typedef const Entry value_type;
      
      const_iterator begin() const { return Iter(log_->begin(), log_->end()); }
      const_iterator end()   const { return Iter(); }
      
      friend const_iterator begin (EventLog const& log) { return log.begin(); }
      friend const_iterator end   (EventLog const& log) { return log.end(); }
      
      
      
      
      /* ==== Query/Verification API ==== */
      
      /** start a query to match for some substring.
       *  The resulting matcher object will qualify on any log entry
       *  containing the given string. By adding subsequent further
       *  query expressions on the returned [matcher object][EventMatch],
       *  the query can be refined. Refining a query might induce backtracking.
       *  The final result can be retrieved by `bool` conversion
       */
      EventMatch
      verify (string match)  const
        {
          EventMatch matcher(*log_);
          matcher.before (match);   // "the start of the log is before the match"
          return matcher;
        }
      
      EventMatch
      verifyMatch (string regExp)  const
        {
          UNIMPLEMENTED("start matching sequence for regular expression match");
        }
      
      /** start a query to match for some event.
       * @remarks only a subset of all log entries is treated as "event",
       *          any other log entry will not be considered for this query.
       *          Besides the regular [events][::event()], also errors,
       *          creation and destruction of objects count as "event".
       * @param match text to (substring)match against the argument logged as event
       */
      EventMatch
      verifyEvent (string match)  const
        {
          EventMatch matcher(*log_);
          matcher.beforeEvent (match);
          return matcher;
        }
      
      EventMatch
      verifyEvent (string classifier, string match)  const
        {
          EventMatch matcher(*log_);
          matcher.beforeEvent (classifier, match);
          return matcher;
        }
      
      /** start a query to match especially a function call
       * @param match text to match against the function name
       */
      EventMatch
      verifyCall (string match)  const
        {
          EventMatch matcher(*log_);
          matcher.beforeCall (match);
          return matcher;
        }
      
      /** start a query to ensure the given expression does \em not match.
       * @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`.
       */
      EventMatch
      ensureNot (string match)  const
        {
          EventMatch matcher(*log_);
          matcher.look_for_match_ = false; // flip logic; fail if match succeeds
          matcher.before (match);
          return matcher;
        }
      
      
      /** equality comparison is based on the actual log contents */
      friend bool
      operator== (EventLog const& l1, EventLog const& l2)
      {
        return l1.log_ == l2.log_
            or (l1.log_ and l2.log_
                and *l1.log_ == *l2.log_);
      }
      friend bool
      operator!= (EventLog const& l1, EventLog const& l2)
      {
        return not (l1 == l2);
      }
    };
  
  
  
}} // namespace lib::test
#endif /*LIB_TEST_EVENT_LOG_H*/