Merge "Tracing: implement span save/restore"

2 files changed, 171 insertions, 10 deletions

diff --git a/tests/otlp_fixture.py b/tests/otlp_fixture.py
index cd2329483..633296fac 100644
--- a/tests/otlp_fixture.py
+++ b/tests/otlp_fixture.py
@@ -11,11 +11,11 @@
 # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
 # License for the specific language governing permissions and limitations
 # under the License.
-
 from concurrent import futures
 
 import fixtures
 import grpc
+from opentelemetry import trace
 from opentelemetry.proto.collector.trace.v1.trace_service_pb2_grpc import (
     TraceServiceServicer,
     add_TraceServiceServicer_to_server
@@ -45,6 +45,9 @@ class OTLPFixture(fixtures.Fixture):
         self.server = grpc.server(self.executor)
         add_TraceServiceServicer_to_server(TraceServer(self), self.server)
         self.port = self.server.add_insecure_port('[::]:0')
+        # Reset global tracer provider
+        trace._TRACER_PROVIDER_SET_ONCE = trace.Once()
+        trace._TRACER_PROVIDER = None
 
     def _setUp(self):
         self.server.start()
diff --git a/tests/unit/test_tracing.py b/tests/unit/test_tracing.py
index ed64c8a7c..3c452dd53 100644
--- a/tests/unit/test_tracing.py
+++ b/tests/unit/test_tracing.py
@@ -12,8 +12,13 @@
 # License for the specific language governing permissions and limitations
 # under the License.
 
+import time
+
 from tests.base import iterate_timeout, ZuulTestCase
 
+import zuul.lib.tracing as tracing
+from opentelemetry import trace
+
 
 def attributes_to_dict(attrlist):
     ret = {}
@@ -26,16 +31,169 @@ class TestTracing(ZuulTestCase):
     config_file = 'zuul-tracing.conf'
     tenant_config_file = "config/single-tenant/main.yaml"
 
-    def test_tracing(self):
-        self.scheds.first.sched.tracing.test()
+    def test_tracing_api(self):
+        tracer = trace.get_tracer("zuul")
+
+        # We have a lot of timestamps stored as floats, so make sure
+        # our root span is a ZuulSpan that can handle that input.
+        span_info = tracing.startSavedSpan('parent-trace',
+                                           start_time=time.time(),
+                                           attributes={'startattr': 'bar'},
+                                           include_attributes=True)
+
+        # Simulate a reconstructed root span
+        span = tracing.restoreSpan(span_info)
+
+        # Within the root span, use the more typical OpenTelemetry
+        # context manager api.
+        with trace.use_span(span):
+            with tracer.start_span('child1-trace') as child1_span:
+                link = trace.Link(child1_span.context,
+                                  attributes={'relationship': 'prev'})
+
+        # Make sure that we can manually start and stop a child span,
+        # and that it is a ZuulSpan as well.
+        with trace.use_span(span):
+            child = tracer.start_span('child2-trace', start_time=time.time(),
+                                      links=[link])
+            child.end(end_time=time.time())
+
+        # Make sure that we can start a child span from a span
+        # context and not a full span:
+        span_context = tracing.getSpanContext(span)
+        with tracing.startSpanInContext(span_context, 'child3-trace') as child:
+            child.end(end_time=time.time())
+
+        # End our root span manually.
+        tracing.endSavedSpan(span_info, end_time=time.time(),
+                             attributes={'endattr': 'baz'})
+
+        for _ in iterate_timeout(60, "request to arrive"):
+            if len(self.otlp.requests) == 4:
+                break
+        req1 = self.otlp.requests[0]
+        self.log.debug("Received:\n%s", req1)
+        attrs = attributes_to_dict(req1.resource_spans[0].resource.attributes)
+        self.assertEqual({"service.name": "zuultest"}, attrs)
+        self.assertEqual("zuul",
+                         req1.resource_spans[0].scope_spans[0].scope.name)
+        span1 = req1.resource_spans[0].scope_spans[0].spans[0]
+        self.assertEqual("child1-trace", span1.name)
+
+        req2 = self.otlp.requests[1]
+        self.log.debug("Received:\n%s", req2)
+        span2 = req2.resource_spans[0].scope_spans[0].spans[0]
+        self.assertEqual("child2-trace", span2.name)
+        self.assertEqual(span2.links[0].span_id, span1.span_id)
+        attrs = attributes_to_dict(span2.links[0].attributes)
+        self.assertEqual({"relationship": "prev"}, attrs)
+
+        req3 = self.otlp.requests[2]
+        self.log.debug("Received:\n%s", req3)
+        span3 = req3.resource_spans[0].scope_spans[0].spans[0]
+        self.assertEqual("child3-trace", span3.name)
+
+        req4 = self.otlp.requests[3]
+        self.log.debug("Received:\n%s", req4)
+        span4 = req4.resource_spans[0].scope_spans[0].spans[0]
+        self.assertEqual("parent-trace", span4.name)
+        attrs = attributes_to_dict(span4.attributes)
+        self.assertEqual({"startattr": "bar",
+                          "endattr": "baz"}, attrs)
+
+        self.assertEqual(span1.trace_id, span4.trace_id)
+        self.assertEqual(span2.trace_id, span4.trace_id)
+        self.assertEqual(span3.trace_id, span4.trace_id)
+
+    def test_tracing_api_null(self):
+        tracer = trace.get_tracer("zuul")
+
+        # Test that restoring spans and span contexts works with
+        # null values.
+
+        span_info = None
+        # Simulate a reconstructed root span from a null value
+        span = tracing.restoreSpan(span_info)
+
+        # Within the root span, use the more typical OpenTelemetry
+        # context manager api.
+        with trace.use_span(span):
+            with tracer.start_span('child1-trace') as child1_span:
+                link = trace.Link(child1_span.context,
+                                  attributes={'relationship': 'prev'})
+
+        # Make sure that we can manually start and stop a child span,
+        # and that it is a ZuulSpan as well.
+        with trace.use_span(span):
+            child = tracer.start_span('child2-trace', start_time=time.time(),
+                                      links=[link])
+            child.end(end_time=time.time())
+
+        # Make sure that we can start a child span from a null span
+        # context:
+        span_context = None
+        with tracing.startSpanInContext(span_context, 'child3-trace') as child:
+            child.end(end_time=time.time())
+
+        # End our root span manually.
+        span.end(end_time=time.time())
+
         for _ in iterate_timeout(60, "request to arrive"):
-            if self.otlp.requests:
+            if len(self.otlp.requests) == 3:
                 break
-        req = self.otlp.requests[0]
-        self.log.debug("Received:\n%s", req)
-        attrs = attributes_to_dict(req.resource_spans[0].resource.attributes)
+        req1 = self.otlp.requests[0]
+        self.log.debug("Received:\n%s", req1)
+        attrs = attributes_to_dict(req1.resource_spans[0].resource.attributes)
         self.assertEqual({"service.name": "zuultest"}, attrs)
         self.assertEqual("zuul",
-                         req.resource_spans[0].scope_spans[0].scope.name)
-        span = req.resource_spans[0].scope_spans[0].spans[0]
-        self.assertEqual("test-trace", span.name)
+                         req1.resource_spans[0].scope_spans[0].scope.name)
+        span1 = req1.resource_spans[0].scope_spans[0].spans[0]
+        self.assertEqual("child1-trace", span1.name)
+
+        req2 = self.otlp.requests[1]
+        self.log.debug("Received:\n%s", req2)
+        span2 = req2.resource_spans[0].scope_spans[0].spans[0]
+        self.assertEqual("child2-trace", span2.name)
+        self.assertEqual(span2.links[0].span_id, span1.span_id)
+        attrs = attributes_to_dict(span2.links[0].attributes)
+        self.assertEqual({"relationship": "prev"}, attrs)
+
+        req3 = self.otlp.requests[2]
+        self.log.debug("Received:\n%s", req3)
+        span3 = req3.resource_spans[0].scope_spans[0].spans[0]
+        self.assertEqual("child3-trace", span3.name)
+
+        self.assertNotEqual(span1.trace_id, span2.trace_id)
+        self.assertNotEqual(span2.trace_id, span3.trace_id)
+        self.assertNotEqual(span1.trace_id, span3.trace_id)
+
+    def test_tracing(self):
+        A = self.fake_gerrit.addFakeChange('org/project', 'master', 'A')
+        A.addApproval('Code-Review', 2)
+        self.fake_gerrit.addEvent(A.addApproval('Approved', 1))
+        self.waitUntilSettled()
+
+        for _ in iterate_timeout(60, "request to arrive"):
+            if len(self.otlp.requests) >= 2:
+                break
+
+        buildset = self.getSpan('BuildSet')
+        self.log.debug("Received:\n%s", buildset)
+        item = self.getSpan('QueueItem')
+        self.log.debug("Received:\n%s", item)
+        self.assertEqual(item.trace_id, buildset.trace_id)
+        self.assertNotEqual(item.span_id, buildset.span_id)
+        self.assertTrue(buildset.start_time_unix_nano >=
+                        item.start_time_unix_nano)
+        self.assertTrue(buildset.end_time_unix_nano <=
+                        item.end_time_unix_nano)
+        item_attrs = attributes_to_dict(item.attributes)
+        self.assertTrue(item_attrs['ref_number'] == "1")
+        self.assertTrue(item_attrs['ref_patchset'] == "1")
+        self.assertTrue('zuul_event_id' in item_attrs)
+
+    def getSpan(self, name):
+        for req in self.otlp.requests:
+            span = req.resource_spans[0].scope_spans[0].spans[0]
+            if span.name == name:
+                return span