Improve tracing (#180)

* WIP

* Update trace logs

* Release v0.9.2 (#176)

* implement planPool

* start implementation of tracing

* implement IAlicaTrace and IAlicaTraceFactory, add tracing for behaviours init/terminate

* replace tracecontext with string, change methods to pure virtual

* add getter for traceFactory

* replace getter for traceContext with getter for trace

* use setLog for init/terminate traces, use factory to create traces

* remove amr_interfaces dependency

* add default constructor, make create pure virtual

* return ptr to traceFactory

* return ptr to traceFactory

* add trace tag for run methods, check if trace / tracefactory exists before usage

* add name to basicPlan, use name for tag

* remove member variable and constructors

* destroy traces after setting terminate tag

* add comment to getTraceFactory method

* use setLog, log run once, make getTrace() protected

* Fixes in creating traces

- Create traces in the execution context during init.
- Provide the option to enable/disable tracing

* Check if trace factory is setting before using it

* Set basicplan name

* Bug fixes

- check if basic plan exists before accessing the trace context
- if no parent is found create a root trace
- remove hack to create basic plan

* Fix alica engine termination

Do the following in order to correctly terminate the engine:
1. Stop the plan base thread. This prevents any more changes to the
running plan.
2. Deactivate the running plan in plan base stop(). This ensures the
plans/behaviours are scheduled for termination in the correct order.
3. Stop all behaviours & plans that may be running. There should not
be any since (2) ensures this taken care of
4. Execute all pending non repeatable jobs in the scheduler thread.
This ensures the plan/behaviour init/terminates are actually executed.
5. Stop the scheduler thread

Add a trace log that indicates if the trace is for a behaviour or a
plan.

Note: the master plan trace is not reported because the master plan does
not have a corresponding basic plan attached to it. This is a bug &
the reason for it is because there is no ConfAbstractPlanWrapper for the
master plan due to which it is not in the plan pool. This has to be fixed
in a separate PR.

* Bring back scheduler null check in engine terminate

* Avoid unused variable warning

* Create BasicPlan object for the master plan

There is no ConfAbstractPlanWrapper corresponding to the master plan.
Therefore get the master plan details by calling getPlans() on the
PlanRepository which includes the master plan details.

* Fix ci

Co-authored-by: bjoernschroeder <[email protected]>

* Revert "Merge branch 'rr-devel' into vsk_improve_tracing"

This reverts commit deab530, reversing
changes made to 29616d2.

* Remove misleading comment

* No need for optional when returning the trace

* Reset the trace after terminate

* Pass a const ptr to the trace context getter

* Add ability to create root custom trace

By making the context returned from custom tracing optional the app
can choose to create a root trace in cases where no suitable context
is available. This can happen when the environment changes before
the trace context is retreived but after the behaviour/plan is scheduled
to start

* Use upper case for alica tag names

* Add comments

Co-authored-by: bjoernschroeder <[email protected]>

alica_engine/include/engine/BasicBehaviour.h

@@ -78,7 +78,10 @@ class BasicBehaviour
     bool isEventDriven() const { return _behaviour->isEventDriven(); }
 
     // This is not thread safe. Should only be called by the scheduler thread. TODO: make this private
-    std::optional<std::string> getTraceContext() const;
+    std::optional<std::string> getTraceContext() const
+    {
+        return _trace ? std::optional<std::string>(_trace->context()) : std::nullopt;
+    }
 
 protected:
     essentials::IdentifierConstPtr getOwnId() const;
@@ -88,8 +91,30 @@ class BasicBehaviour
     void setSuccess();
     void setFailure();
 
-    std::optional<IAlicaTrace*> getTrace() const;
-    void disableTracing() { clearFlags(Flags::TRACING_ENABLED); };
+    enum class TracingType : uint8_t
+    {
+        // Use the trace context of the lowest ancestor plan for which tracing is not skipped
+        DEFAULT,
+        // Skip tracing
+        SKIP,
+        // Create a root trace
+        ROOT,
+        // Provide a custom trace context
+        CUSTOM
+    };
+
+    // Set the tracing type for this behaviour. customTraceContextGetter is required for custom tracing
+    // & this method will be called to get the parent trace context before initialiseParameters is called
+    void setTracing(TracingType type, std::function<std::optional<std::string>(const BasicBehaviour*)> customTraceContextGetter = {})
+    {
+        _tracingType = type;
+        _customTraceContextGetter = std::move(customTraceContextGetter);
+    }
+
+    IAlicaTrace* getTrace() const
+    {
+        return _trace ? _trace.get() : nullptr;
+    }
 
     /**
      * Called whenever a basic behaviour is started, i.e., when the corresponding state is entered.
@@ -148,6 +173,8 @@ class BasicBehaviour
         return sc == ec && isActive(sc);
     }
 
+    void startTrace();
+
     /**
      * The name of this behaviour.
      */
@@ -176,23 +203,12 @@ class BasicBehaviour
 
     int64_t _activeRunJobId;
     std::atomic<bool> _triggeredJobRunning;
-    std::unique_ptr<IAlicaTrace> _trace;
 
-    enum class Flags : uint8_t
-    {
-        // For Optimization: The behaviour may skip initialiseParameters if it is already gone out of execution context & this boolean is
-        // used to track this. In such a case we should not be calling onTermination either
-        INIT_EXECUTED = 1u,
-        // Is tracing enabled for this behaviour?
-        TRACING_ENABLED = 1u << 1,
-        // We only want to trace the first run call
-        RUN_TRACED = 1u << 2
-    };
-
-    uint8_t _flags;
+    TracingType _tracingType;
+    std::function<std::optional<std::string>(const BasicBehaviour*)> _customTraceContextGetter;
+    std::unique_ptr<IAlicaTrace> _trace;
+    bool _runTraced;
 
-    void setFlags(Flags flags) { _flags |= static_cast<uint8_t>(flags); }
-    void clearFlags(Flags flags) { _flags &= ~static_cast<uint8_t>(flags); }
-    bool areFlagsSet(Flags flags) { return (static_cast<uint8_t>(flags) & _flags) == static_cast<uint8_t>(flags); }
+    bool _initExecuted;
 };
 } /* namespace alica */

alica_engine/include/engine/BasicPlan.h

@@ -4,6 +4,7 @@
 #include "engine/IAlicaTrace.h"
 #include <string>
 #include <atomic>
+#include <functional>
 
 namespace alica
 {
@@ -28,11 +29,15 @@ class BasicPlan
     void setConfiguration(const Configuration* conf) { _configuration = conf; }
     // TODO: get the name in the constructor
     void setName(const std::string& name) { _name = name; }
+    void setAsMasterPlan() { _isMasterPlan = true; };
 
     AlicaTime getInterval() const { return _msInterval; }
     void setInterval(int32_t msInterval) { _msInterval = AlicaTime::milliseconds(msInterval); }
 
-    std::optional<std::string> getTraceContext() const;
+    std::optional<std::string> getTraceContext() const
+    {
+        return _trace ? std::optional<std::string>(_trace->context()) : std::nullopt;
+    }
 
 protected:
     ThreadSafePlanInterface getPlanContext() const;
@@ -41,8 +46,24 @@ class BasicPlan
     virtual void run(void* msg){};
     virtual void onTerminate(){};
 
-    std::optional<IAlicaTrace*> getTrace() const;
-    void disableTracing() { clearFlags(Flags::TRACING_ENABLED); };
+    enum class TracingType : uint8_t
+    {
+        DEFAULT,
+        SKIP,
+        ROOT,
+        CUSTOM
+    };
+
+    void setTracing(TracingType type, std::function<std::optional<std::string>(const BasicPlan*)> customTraceContextGetter = {})
+    {
+        _tracingType = type;
+        _customTraceContextGetter = std::move(customTraceContextGetter);
+    }
+
+    IAlicaTrace* getTrace() const
+    {
+        return _trace ? _trace.get() : nullptr;
+    }
 
 private:
     using Counter = uint64_t;
@@ -60,31 +81,27 @@ class BasicPlan
         return sc == ec && isActive(sc);
     }
 
+    void startTrace();
+
     static constexpr int DEFAULT_MS_INTERVAL = 100;
 
     alica::AlicaEngine* _ae;
     const Configuration* _configuration;
     AlicaTime _msInterval;
     int64_t _activeRunJobId;
-    std::unique_ptr<IAlicaTrace> _trace;
     std::string _name;
+    bool _isMasterPlan;
 
     std::atomic<RunningPlan*> _signalContext;
     std::atomic<RunningPlan*> _execContext;
     std::atomic<Counter> _signalState;
     std::atomic<Counter> _execState;
 
-    enum class Flags : uint8_t
-    {
-        INIT_EXECUTED = 1u,
-        TRACING_ENABLED = 1u << 1,
-        RUN_TRACED = 1u << 2
-    };
-
-    uint8_t _flags;
+    TracingType _tracingType;
+    std::function<std::optional<std::string>(const BasicPlan*)> _customTraceContextGetter;
+    std::unique_ptr<IAlicaTrace> _trace;
+    bool _runTraced;
 
-    void setFlags(Flags flags) { _flags |= static_cast<uint8_t>(flags); }
-    void clearFlags(Flags flags) { _flags &= ~static_cast<uint8_t>(flags); }
-    bool areFlagsSet(Flags flags) { return (static_cast<uint8_t>(flags) & _flags) == static_cast<uint8_t>(flags); }
+    bool _initExecuted;
 };
 } // namespace alica

alica_engine/include/engine/IAlicaTrace.h

@@ -13,6 +13,8 @@ class IAlicaTrace
     virtual void setTag(const std::string& key, const std::string& value) = 0;
     virtual void setLog(std::pair<std::string, std::string> fields) = 0;
     virtual void markError(const std::string& description) = 0;
+    virtual void finish() = 0;
+    // Note: the context should be valid even after finish() is called on the trace
     virtual std::string context() const = 0;
 };
 

alica_engine/src/engine/BasicBehaviour.cpp

@@ -40,7 +40,11 @@ BasicBehaviour::BasicBehaviour(const std::string& name)
         , _behResult(BehResult::UNKNOWN)
         , _activeRunJobId(-1)
         , _triggeredJobRunning(false)
-        , _flags(static_cast<uint8_t>(Flags::TRACING_ENABLED))
+        , _tracingType(TracingType::DEFAULT)
+        , _customTraceContextGetter()
+        , _trace()
+        , _runTraced(false)
+        , _initExecuted(false)
 {
 }
 
@@ -114,6 +118,39 @@ bool BasicBehaviour::isTriggeredRunFinished()
     return !_triggeredJobRunning.load();
 }
 
+void BasicBehaviour::startTrace()
+{
+    if (!_engine->getTraceFactory()) {
+        return;
+    }
+
+    switch (_tracingType) {
+    case TracingType::DEFAULT: {
+        auto parent = _execContext.load()->getParent();
+        for (; parent && (!parent->getBasicPlan() || !parent->getBasicPlan()->getTraceContext().has_value()); parent = parent->getParent());
+        _trace = _engine->getTraceFactory()->create(_name, parent ? parent->getBasicPlan()->getTraceContext() : std::nullopt);
+        break;
+    }
+    case TracingType::SKIP: {
+        break;
+    }
+    case TracingType::ROOT: {
+        _trace = _engine->getTraceFactory()->create(_name);
+        break;
+    }
+    case TracingType::CUSTOM: {
+        if (!_customTraceContextGetter) {
+            ALICA_ERROR_MSG("[BasicBehaviour] Custom tracing type specified, but no getter for the trace context is provided. Switching to default tracing type instead");
+            _tracingType = TracingType::DEFAULT;
+            startTrace();
+            break;
+        }
+        _trace = _engine->getTraceFactory()->create(_name, _customTraceContextGetter(this));
+        break;
+    }
+    }
+}
+
 void BasicBehaviour::initJob()
 {
     assert(_behResult.load() == BehResult::UNKNOWN);
@@ -122,26 +159,22 @@ void BasicBehaviour::initJob()
     if (!isExecutingInContext()) {
         return;
     }
-    setFlags(Flags::INIT_EXECUTED);
+    _initExecuted = true;
 
     // There is a possible race condition here in the sense that the _execState can be behind the _signalState
     // and yet this behaviour can execute in the _signalState's RunningPlan context. However this is harmless
-    // since all methods are guarded by isExecutingInContext() which will return false in all such cases.
+    // except for creating a superflous trace, since all other methods are guarded by isExecutingInContext()
+    // which will return false in all such cases.
     // Atomically set the signal context to nullptr so that the RunningPlan instance can be deleted
     // when the behaviour is terminated
     _execContext = _signalContext.exchange(nullptr);
 
-    // Get closest parent that has a trace
-    if (areFlagsSet(Flags::TRACING_ENABLED) && _engine->getTraceFactory()) {
-        auto parent = _execContext.load()->getParent();
-        for (; parent && (!parent->getBasicPlan() || !parent->getBasicPlan()->getTraceContext().has_value()); parent = parent->getParent());
-        _trace = _engine->getTraceFactory()->create(_name, parent ? parent->getBasicPlan()->getTraceContext() : std::nullopt);
-    }
+    startTrace();
 
     try {
         if (_trace) {
-            _trace->setLog({"Behaviour", "true"});
-            _trace->setLog({"Init", "true"});
+            _trace->setTag("Type", "behaviour");
+            _trace->setLog({"status", "initializing"});
         }
         initialiseParameters();
     } catch (const std::exception& e) {
@@ -159,9 +192,9 @@ void BasicBehaviour::runJob(void* msg)
 {
     // TODO: get rid of msg
     try {
-        if (_trace && !areFlagsSet(Flags::RUN_TRACED)) {
-            _trace->setLog({"Run", "true"});
-            setFlags(Flags::RUN_TRACED);
+        if (_trace && !_runTraced) {
+            _trace->setLog({"status", "running"});
+            _runTraced = true;
         }
         run(msg);
     } catch (const std::exception& e) {
@@ -191,21 +224,21 @@ void BasicBehaviour::terminateJob()
     _behResult.store(BehResult::UNKNOWN);
     ++_execState;
 
-    clearFlags(Flags::RUN_TRACED);
-    if (!areFlagsSet(Flags::INIT_EXECUTED)) {
+    _runTraced = false;
+    if (!_initExecuted) {
         // Reset the execution context so that the RunningPlan instance can be deleted
         _execContext.store(nullptr);
         return;
     }
-    clearFlags(Flags::INIT_EXECUTED);
+    _initExecuted = false;
 
     // Intentionally call onTermination() at the end. This prevents setting success/failure from this method
     try {
         if (_trace) {
-            _trace->setLog({"Terminate", "true"});
-            _trace.reset();
+            _trace->setLog({"status", "terminating"});
         }
         onTermination();
+        _trace.reset();
     } catch (const std::exception& e) {
         ALICA_ERROR_MSG("[BasicBehaviour] Exception in Behaviour-TERMINATE of: " << getName() << std::endl << e.what());
     }
@@ -236,14 +269,4 @@ bool BasicBehaviour::getParameter(const std::string& key, std::string& valueOut)
     }
 }
 
-std::optional<IAlicaTrace*> BasicBehaviour::getTrace() const
-{
-    return _trace ? std::optional<IAlicaTrace*>(_trace.get()) : std::nullopt;
-}
-
-std::optional<std::string> BasicBehaviour::getTraceContext() const
-{
-    return _trace ? std::optional<std::string>(_trace->context()) : std::nullopt;
-}
-
 } /* namespace alica */