Merge pull request #451 from ianco/trace_reports_3

Trace reports - exchange-specific tracing; proof exchange tracing

aries_cloudagent/config/argparse.py

@@ -622,14 +622,17 @@ def get_settings(self, args: Namespace) -> dict:
             settings["trace.label"] = args.label
         else:
             settings["trace.label"] = "aca-py.agent"
-        if settings.get("trace.enabled"):
+        if settings.get("trace.enabled") or settings.get("trace.target"):
+            # make sure we can trace to the configured target
+            # (target can be set even if tracing is off)
             try:
                 trace_event(
                     settings,
                     None,
                     handler="ArgParse",
-                    outcome="Successfully configured aca-py",
-                    raise_errors=True
+                    outcome="Successfully_configured_aca-py",
+                    raise_errors=True,
+                    force_trace=True
                 )
             except Exception as e:
                 raise ArgsParseError(

aries_cloudagent/messaging/agent_message.py

@@ -19,6 +19,10 @@
 from .decorators.default import DecoratorSet
 from .decorators.signature_decorator import SignatureDecorator
 from .decorators.thread_decorator import ThreadDecorator
+from .decorators.trace_decorator import (
+    TraceDecorator, TraceReport,
+    TRACE_MESSAGE_TARGET, TRACE_LOG_TARGET
+)
 from .models.base import (
     BaseModel,
     BaseModelError,
@@ -291,6 +295,84 @@ def assign_thread_id(self, thid: str, pthid: str = None):
         """
         self._thread = ThreadDecorator(thid=thid, pthid=pthid)
 
+    @property
+    def _trace(self) -> TraceDecorator:
+        """
+        Accessor for the message's trace decorator.
+
+        Returns:
+            The TraceDecorator for this message
+
+        """
+        return self._decorators.get("trace")
+
+    @_trace.setter
+    def _trace(self, val: Union[TraceDecorator, dict]):
+        """
+        Setter for the message's trace decorator.
+
+        Args:
+            val: TraceDecorator or dict to set as the trace
+        """
+        self._decorators["trace"] = val
+
+    def assign_trace_from(self, msg: "AgentMessage"):
+        """
+        Copy trace information from a previous message.
+
+        Args:
+            msg: The received message containing optional trace information
+        """
+        if msg and msg._trace:
+            # ignore if not a valid type
+            if (isinstance(msg._trace, TraceDecorator) or
+                    isinstance(msg._trace, dict)):
+                self._trace = msg._trace
+
+    def assign_trace_decorator(self, context, trace):
+        """
+        Copy trace from a json structure.
+
+        Args:
+            trace: string containing trace json stucture
+        """
+        if trace:
+            self.add_trace_decorator(
+                target=context.get("trace.target") if context else TRACE_LOG_TARGET,
+                full_thread=True,
+            )
+
+    def add_trace_decorator(
+        self,
+        target: str = TRACE_LOG_TARGET,
+        full_thread: bool = True
+    ):
+        """
+        Create a new trace decorator.
+
+        Args:
+            target: The trace target
+            full_thread: Full thread flag
+        """
+        if self._trace:
+            # don't replace if there is already a trace decorator
+            # (potentially holding trace reports already)
+            self._trace._target = target
+            self._trace._full_thread = full_thread
+        else:
+            self._trace = TraceDecorator(target=target, full_thread=full_thread)
+
+    def add_trace_report(self, val: Union[TraceReport, dict]):
+        """
+        Append a new trace report.
+
+        Args:
+            val: The trace target
+        """
+        if not self._trace:
+            self.add_trace_decorator(target=TRACE_MESSAGE_TARGET, full_thread=True)
+        self._trace.append_trace_report(val)
+
 
 class AgentMessageSchema(BaseModelSchema):
     """AgentMessage schema."""

aries_cloudagent/messaging/decorators/default.py

@@ -5,13 +5,15 @@
 from .localization_decorator import LocalizationDecorator
 from .signature_decorator import SignatureDecorator
 from .thread_decorator import ThreadDecorator
+from .trace_decorator import TraceDecorator
 from .timing_decorator import TimingDecorator
 from .transport_decorator import TransportDecorator
 
 DEFAULT_MODELS = {
     "l10n": LocalizationDecorator,
     "sig": SignatureDecorator,
     "thread": ThreadDecorator,
+    "trace": TraceDecorator,
     "timing": TimingDecorator,
     "transport": TransportDecorator,
 }

aries_cloudagent/messaging/decorators/tests/test_trace_decorator.py

@@ -0,0 +1,158 @@
+from ..trace_decorator import TraceDecorator, TraceReport, TRACE_MESSAGE_TARGET
+
+from unittest import TestCase
+
+
+class TestTraceDecorator(TestCase):
+
+    target_api = "http://example.com/api/trace/"
+    full_thread_api = False
+    target_msg = TRACE_MESSAGE_TARGET
+    full_thread_msg = True
+
+    msg_id = "msg-001"
+    thread_id = "thid-001"
+    traced_type = "msg-001/my_type"
+    timestamp = "123456789.123456"
+    str_time = "2018-03-27 18:23:45.123Z"
+    handler = "agent name"
+    ellapsed_milli = 27
+    outcome = "OK ..."
+
+
+    def test_init_api(self):
+
+        decorator = TraceDecorator(
+            target=self.target_api,
+            full_thread=self.full_thread_api,
+        )
+        assert decorator.target == self.target_api
+        assert decorator.full_thread == self.full_thread_api
+
+    def test_init_message(self):
+
+        x_msg_id = self.msg_id
+        x_thread_id = self.thread_id
+        x_trace_report = TraceReport(
+            msg_id=x_msg_id,
+            thread_id=x_thread_id,
+            traced_type=self.traced_type,
+            timestamp=self.timestamp,
+            str_time=self.str_time,
+            handler=self.handler,
+            ellapsed_milli=self.ellapsed_milli,
+            outcome=self.outcome,
+        )
+
+        decorator = TraceDecorator(
+            target=self.target_msg,
+            full_thread=self.full_thread_msg,
+            trace_reports=[x_trace_report,],
+        )
+        assert decorator.target == self.target_msg
+        assert decorator.full_thread == self.full_thread_msg
+        assert len(decorator.trace_reports) == 1
+        trace_report = decorator.trace_reports[0]
+        assert trace_report.msg_id == self.msg_id
+        assert trace_report.thread_id == self.thread_id
+        assert trace_report.traced_type == self.traced_type
+        assert trace_report.timestamp == self.timestamp
+        assert trace_report.str_time == self.str_time
+        assert trace_report.handler == self.handler
+        assert trace_report.ellapsed_milli == self.ellapsed_milli
+        assert trace_report.outcome == self.outcome
+
+    def test_serialize_load(self):
+
+        x_msg_id = self.msg_id
+        x_thread_id = self.thread_id
+        x_trace_report = TraceReport(
+            msg_id=x_msg_id,
+            thread_id=x_thread_id,
+            traced_type=self.traced_type,
+            timestamp=self.timestamp,
+            str_time=self.str_time,
+            handler=self.handler,
+            ellapsed_milli=self.ellapsed_milli,
+            outcome=self.outcome,
+        )
+
+        decorator = TraceDecorator(
+            target=self.target_msg,
+            full_thread=self.full_thread_msg,
+            trace_reports=[x_trace_report,x_trace_report,],
+        )
+
+        dumped = decorator.serialize()
+        loaded = TraceDecorator.deserialize(dumped)
+
+        assert loaded.target == decorator.target
+        assert loaded.full_thread == decorator.full_thread
+        assert len(loaded.trace_reports) == 2
+        trace_report = loaded.trace_reports[0]
+        assert trace_report.msg_id == x_trace_report.msg_id
+        assert trace_report.thread_id == x_trace_report.thread_id
+        assert trace_report.traced_type == x_trace_report.traced_type
+        assert trace_report.timestamp == x_trace_report.timestamp
+        assert trace_report.str_time == x_trace_report.str_time
+        assert trace_report.handler == x_trace_report.handler
+        assert trace_report.ellapsed_milli == x_trace_report.ellapsed_milli
+        assert trace_report.outcome == x_trace_report.outcome
+
+    def test_trace_reports(self):
+        decorator = TraceDecorator(
+            target=self.target_msg,
+            full_thread=self.full_thread_msg,
+        )
+        assert len(decorator.trace_reports) == 0
+
+        x_msg_id = self.msg_id
+        x_thread_id = self.thread_id
+        x_trace_report = TraceReport(
+            msg_id=x_msg_id,
+            thread_id=x_thread_id,
+            traced_type=self.traced_type,
+            timestamp=self.timestamp,
+            str_time=self.str_time,
+            handler=self.handler,
+            ellapsed_milli=self.ellapsed_milli,
+            outcome=self.outcome,
+        )
+        decorator.append_trace_report(x_trace_report)
+        assert len(decorator.trace_reports) == 1
+
+        y_msg_id = self.msg_id
+        y_thread_id = self.thread_id
+        y_trace_report = TraceReport(
+            msg_id=y_msg_id,
+            thread_id=y_thread_id,
+            traced_type=self.traced_type,
+            timestamp=self.timestamp,
+            str_time=self.str_time,
+            handler=self.handler,
+            ellapsed_milli=self.ellapsed_milli,
+            outcome=self.outcome,
+        )
+        decorator.append_trace_report(y_trace_report)
+        assert len(decorator.trace_reports) == 2
+        trace_report = decorator.trace_reports[1]
+        assert trace_report.msg_id == x_trace_report.msg_id
+        assert trace_report.thread_id == x_trace_report.thread_id
+
+        z_msg_id = self.msg_id+"-z"
+        z_thread_id = self.thread_id+"-z"
+        z_trace_report = TraceReport(
+            msg_id=z_msg_id,
+            thread_id=z_thread_id,
+            traced_type=self.traced_type,
+            timestamp=self.timestamp,
+            str_time=self.str_time,
+            handler=self.handler,
+            ellapsed_milli=self.ellapsed_milli,
+            outcome=self.outcome,
+        )
+        decorator.append_trace_report(z_trace_report)
+        assert len(decorator.trace_reports) == 3
+        trace_report = decorator.trace_reports[2]
+        assert trace_report.msg_id == self.msg_id+"-z"
+        assert trace_report.thread_id == self.thread_id+"-z"