From 36592d3779d915beda670334fc54a73cff54ffd1 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Wed, 8 Jan 2020 18:31:52 -0600 Subject: [PATCH 01/11] Set status properly on end Fixes #357 --- .../src/opentelemetry/sdk/trace/__init__.py | 14 +++++++------- opentelemetry-sdk/tests/trace/test_trace.py | 5 ++++- 2 files changed, 11 insertions(+), 8 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index b969587eeb0..98ec9065ac6 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -66,7 +66,8 @@ def on_end(self, span: "Span") -> None: """ def shutdown(self) -> None: - """Called when a :class:`opentelemetry.sdk.trace.Tracer` is shutdown.""" + """Called when a :class:`opentelemetry.sdk.trace.Tracer` is shutdown. + """ class MultiSpanProcessor(SpanProcessor): @@ -267,16 +268,15 @@ def end(self, end_time: Optional[int] = None) -> None: raise RuntimeError("Calling end() on a not started span.") has_ended = self.end_time is not None if not has_ended: - self._end_time = ( - end_time if end_time is not None else time_ns() - ) + if self.status is None: + self.status = Status(canonical_code=StatusCanonicalCode.OK) + + self.end_time = end_time if end_time is not None else time_ns() + if has_ended: logger.warning("Calling end() on an ended span.") return - if self.status is None: - self.set_status(Status(canonical_code=StatusCanonicalCode.OK)) - self.span_processor.on_end(self) def update_name(self, name: str) -> None: diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 98a7bb100e7..3f88943091a 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -574,7 +574,10 @@ def test_ended_span(self): "Test description", ) root.set_status(new_status) - self.assertIs(root.status, None) + self.assertEqual( + root.status.canonical_code, + trace_api.status.StatusCanonicalCode.OK, + ) def test_error_status(self): try: From f128646671606780766a7b210ce24a6a9649c70a Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Thu, 9 Jan 2020 16:29:49 -0600 Subject: [PATCH 02/11] Handle warnings --- .../src/opentelemetry/sdk/trace/__init__.py | 4 ++-- opentelemetry-sdk/tests/trace/test_trace.py | 23 ++++++++++++------- pytest.ini | 2 ++ 3 files changed, 19 insertions(+), 10 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index 98ec9065ac6..28ea41450c6 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -265,7 +265,7 @@ def end(self, end_time: Optional[int] = None) -> None: if not self.is_recording_events(): return if self.start_time is None: - raise RuntimeError("Calling end() on a not started span.") + raise RuntimeError("Calling end() on an ended span.") has_ended = self.end_time is not None if not has_ended: if self.status is None: @@ -505,7 +505,7 @@ def use_span( span_snapshot ) finally: - if end_on_exit: + if end_on_exit and span.end_time is None: span.end() diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 3f88943091a..3c8ddf309c9 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -167,8 +167,9 @@ def test_instrumentation_info(self): def test_invalid_instrumentation_info(self): tracer_source = trace.TracerSource() - tracer1 = tracer_source.get_tracer("") - tracer2 = tracer_source.get_tracer(None) + with self.assertLogs(level="ERROR"): + tracer1 = tracer_source.get_tracer("") + tracer2 = tracer_source.get_tracer(None) self.assertEqual( tracer1.instrumentation_info, tracer2.instrumentation_info ) @@ -516,7 +517,8 @@ def test_start_span(self): span.start() start_time = span.start_time - span.start() + with self.assertLogs(level="WARNING"): + span.start() self.assertEqual(start_time, span.start_time) self.assertIs(span.status, None) @@ -556,24 +558,29 @@ def test_ended_span(self): end_time0 = root.end_time # call it a second time - root.end() + with self.assertLogs(level="WARNING"): + root.end() # end time shouldn't be changed self.assertEqual(end_time0, root.end_time) - root.set_attribute("component", "http") + with self.assertLogs(level="WARNING"): + root.set_attribute("component", "http") self.assertEqual(len(root.attributes), 0) - root.add_event("event1") + with self.assertLogs(level="WARNING"): + root.add_event("event1") self.assertEqual(len(root.events), 0) - root.update_name("xxx") + with self.assertLogs(level="WARNING"): + root.update_name("xxx") self.assertEqual(root.name, "root") new_status = trace_api.status.Status( trace_api.status.StatusCanonicalCode.CANCELLED, "Test description", ) - root.set_status(new_status) + with self.assertLogs(level="WARNING"): + root.set_status(new_status) self.assertEqual( root.status.canonical_code, trace_api.status.StatusCanonicalCode.OK, diff --git a/pytest.ini b/pytest.ini index a71d000b560..013d2c555c3 100644 --- a/pytest.ini +++ b/pytest.ini @@ -1,2 +1,4 @@ [pytest] addopts = -rs -v +log_cli = true +log_cli_level = warning From 3b6fd42afec86ab3d82e8cc1a71166fce063cc90 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 10 Jan 2020 11:04:46 -0600 Subject: [PATCH 03/11] Some more fixes --- .../src/opentelemetry/sdk/trace/__init__.py | 2 +- opentelemetry-sdk/tests/trace/test_trace.py | 13 +++++++------ 2 files changed, 8 insertions(+), 7 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index 28ea41450c6..0cf4ac81e82 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -265,7 +265,7 @@ def end(self, end_time: Optional[int] = None) -> None: if not self.is_recording_events(): return if self.start_time is None: - raise RuntimeError("Calling end() on an ended span.") + raise RuntimeError("Calling end() on a not started span.") has_ended = self.end_time is not None if not has_ended: if self.status is None: diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 3c8ddf309c9..e06c32fcda8 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -15,6 +15,7 @@ import shutil import subprocess import unittest +from logging import WARNING from unittest import mock from opentelemetry import trace as trace_api @@ -517,7 +518,7 @@ def test_start_span(self): span.start() start_time = span.start_time - with self.assertLogs(level="WARNING"): + with self.assertLogs(level=WARNING): span.start() self.assertEqual(start_time, span.start_time) @@ -558,20 +559,20 @@ def test_ended_span(self): end_time0 = root.end_time # call it a second time - with self.assertLogs(level="WARNING"): + with self.assertLogs(level=WARNING): root.end() # end time shouldn't be changed self.assertEqual(end_time0, root.end_time) - with self.assertLogs(level="WARNING"): + with self.assertLogs(level=WARNING): root.set_attribute("component", "http") self.assertEqual(len(root.attributes), 0) - with self.assertLogs(level="WARNING"): + with self.assertLogs(level=WARNING): root.add_event("event1") self.assertEqual(len(root.events), 0) - with self.assertLogs(level="WARNING"): + with self.assertLogs(level=WARNING): root.update_name("xxx") self.assertEqual(root.name, "root") @@ -579,7 +580,7 @@ def test_ended_span(self): trace_api.status.StatusCanonicalCode.CANCELLED, "Test description", ) - with self.assertLogs(level="WARNING"): + with self.assertLogs(level=WARNING): root.set_status(new_status) self.assertEqual( root.status.canonical_code, From 79ccce9b8698972e7177e3cd263a962f6ee34a43 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 10 Jan 2020 12:32:03 -0600 Subject: [PATCH 04/11] Handle last warning --- .../src/opentelemetry/sdk/trace/__init__.py | 2 +- opentelemetry-sdk/tests/trace/test_trace.py | 25 ++++++++++++++++++- 2 files changed, 25 insertions(+), 2 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index 0cf4ac81e82..98ec9065ac6 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -505,7 +505,7 @@ def use_span( span_snapshot ) finally: - if end_on_exit and span.end_time is None: + if end_on_exit: span.end() diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index e06c32fcda8..462cf36d34a 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -548,7 +548,29 @@ def test_span_override_start_and_end_time(self): def test_ended_span(self): """"Events, attributes are not allowed after span is ended""" - with self.tracer.start_as_current_span("root") as root: + class ContextWrapper: + # This auxiliary class is added here just to make it possible to + # handle the warning raised in the __exit__ method of the context + # manager in self.span_context. This class makes it possible to + # catch just that warning specifically with self.test.assertLogs. + # This is done to avoid having the whole test in a self.assertLogs + # context that would catch any warning raised. + test = self + + def __init__(self): + self.span_context = self.test.tracer.start_as_current_span( + "root" + ) + + def __enter__(self): + return self.span_context.__enter__() + + def __exit__(self, *args): + with self.test.assertLogs(level=WARNING): + self.span_context.__exit__(*args) + + with ContextWrapper() as root: + # everything should be empty at the beginning self.assertEqual(len(root.attributes), 0) self.assertEqual(len(root.events), 0) @@ -580,6 +602,7 @@ def test_ended_span(self): trace_api.status.StatusCanonicalCode.CANCELLED, "Test description", ) + with self.assertLogs(level=WARNING): root.set_status(new_status) self.assertEqual( From 0c7ef7e04b8495666b8fe113177bd4b8ef0ae2b9 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 10 Jan 2020 12:35:29 -0600 Subject: [PATCH 05/11] Catch errors separately --- opentelemetry-sdk/tests/trace/test_trace.py | 1 + 1 file changed, 1 insertion(+) diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 462cf36d34a..052490e7d0a 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -170,6 +170,7 @@ def test_invalid_instrumentation_info(self): tracer_source = trace.TracerSource() with self.assertLogs(level="ERROR"): tracer1 = tracer_source.get_tracer("") + with self.assertLogs(level="ERROR"): tracer2 = tracer_source.get_tracer(None) self.assertEqual( tracer1.instrumentation_info, tracer2.instrumentation_info From 47527ead932de6cf42020ef08c10e7742d7372a4 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 10 Jan 2020 12:36:51 -0600 Subject: [PATCH 06/11] Use logging.ERROR --- opentelemetry-sdk/tests/trace/test_trace.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 052490e7d0a..e724e1c3960 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -15,7 +15,7 @@ import shutil import subprocess import unittest -from logging import WARNING +from logging import WARNING, ERROR from unittest import mock from opentelemetry import trace as trace_api @@ -168,9 +168,9 @@ def test_instrumentation_info(self): def test_invalid_instrumentation_info(self): tracer_source = trace.TracerSource() - with self.assertLogs(level="ERROR"): + with self.assertLogs(level=ERROR): tracer1 = tracer_source.get_tracer("") - with self.assertLogs(level="ERROR"): + with self.assertLogs(level=ERROR): tracer2 = tracer_source.get_tracer(None) self.assertEqual( tracer1.instrumentation_info, tracer2.instrumentation_info From eecb01ccefe2f8fd8fee9dc2625598f04ab78b98 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 10 Jan 2020 12:38:40 -0600 Subject: [PATCH 07/11] Fix isort issues --- opentelemetry-sdk/tests/trace/test_trace.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index e724e1c3960..4bfef0de377 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -15,7 +15,7 @@ import shutil import subprocess import unittest -from logging import WARNING, ERROR +from logging import ERROR, WARNING from unittest import mock from opentelemetry import trace as trace_api From b3472e3a6844a6d13aafe5207807037760ec5732 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 10 Jan 2020 12:41:58 -0600 Subject: [PATCH 08/11] Use correct attributes --- opentelemetry-sdk/tests/trace/test_trace.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 4bfef0de377..46dba4ec289 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -566,9 +566,9 @@ def __init__(self): def __enter__(self): return self.span_context.__enter__() - def __exit__(self, *args): + def __exit__(self, type_, value, traceback): with self.test.assertLogs(level=WARNING): - self.span_context.__exit__(*args) + self.span_context.__exit__(type_, value, traceback) with ContextWrapper() as root: From ab6628b35a5a3b6832d5a20ee90e8f786e0f434f Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Mon, 13 Jan 2020 17:36:10 -0600 Subject: [PATCH 09/11] Fix attribute setting --- opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index 98ec9065ac6..bb4432b9ed0 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -271,7 +271,9 @@ def end(self, end_time: Optional[int] = None) -> None: if self.status is None: self.status = Status(canonical_code=StatusCanonicalCode.OK) - self.end_time = end_time if end_time is not None else time_ns() + self._end_time = ( + end_time if end_time is not None else time_ns() + ) if has_ended: logger.warning("Calling end() on an ended span.") From a60c24f76f4e59ba8bac8be785399497b04e8562 Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 17 Jan 2020 10:38:36 -0600 Subject: [PATCH 10/11] Refactor test case --- opentelemetry-sdk/tests/trace/test_trace.py | 85 +++++++++------------ 1 file changed, 34 insertions(+), 51 deletions(-) diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 46dba4ec289..ba8eb35efd4 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -549,67 +549,50 @@ def test_span_override_start_and_end_time(self): def test_ended_span(self): """"Events, attributes are not allowed after span is ended""" - class ContextWrapper: - # This auxiliary class is added here just to make it possible to - # handle the warning raised in the __exit__ method of the context - # manager in self.span_context. This class makes it possible to - # catch just that warning specifically with self.test.assertLogs. - # This is done to avoid having the whole test in a self.assertLogs - # context that would catch any warning raised. - test = self - - def __init__(self): - self.span_context = self.test.tracer.start_as_current_span( - "root" - ) - - def __enter__(self): - return self.span_context.__enter__() + # Test that end() is called when the context manager is exited + with self.assertLogs(level=WARNING): + with self.tracer.start_as_current_span("root") as root: + root.end() - def __exit__(self, type_, value, traceback): - with self.test.assertLogs(level=WARNING): - self.span_context.__exit__(type_, value, traceback) + root = self.tracer.start_span("root") - with ContextWrapper() as root: + # everything should be empty at the beginning + self.assertEqual(len(root.attributes), 0) + self.assertEqual(len(root.events), 0) + self.assertEqual(len(root.links), 0) - # everything should be empty at the beginning - self.assertEqual(len(root.attributes), 0) - self.assertEqual(len(root.events), 0) - self.assertEqual(len(root.links), 0) + # call end first time + root.end() + end_time0 = root.end_time - # call end first time + # call it a second time + with self.assertLogs(level=WARNING): root.end() - end_time0 = root.end_time + # end time shouldn't be changed + self.assertEqual(end_time0, root.end_time) - # call it a second time - with self.assertLogs(level=WARNING): - root.end() - # end time shouldn't be changed - self.assertEqual(end_time0, root.end_time) - - with self.assertLogs(level=WARNING): - root.set_attribute("component", "http") - self.assertEqual(len(root.attributes), 0) + with self.assertLogs(level=WARNING): + root.set_attribute("component", "http") + self.assertEqual(len(root.attributes), 0) - with self.assertLogs(level=WARNING): - root.add_event("event1") - self.assertEqual(len(root.events), 0) + with self.assertLogs(level=WARNING): + root.add_event("event1") + self.assertEqual(len(root.events), 0) - with self.assertLogs(level=WARNING): - root.update_name("xxx") - self.assertEqual(root.name, "root") + with self.assertLogs(level=WARNING): + root.update_name("xxx") + self.assertEqual(root.name, "root") - new_status = trace_api.status.Status( - trace_api.status.StatusCanonicalCode.CANCELLED, - "Test description", - ) + new_status = trace_api.status.Status( + trace_api.status.StatusCanonicalCode.CANCELLED, "Test description", + ) - with self.assertLogs(level=WARNING): - root.set_status(new_status) - self.assertEqual( - root.status.canonical_code, - trace_api.status.StatusCanonicalCode.OK, - ) + with self.assertLogs(level=WARNING): + root.set_status(new_status) + self.assertEqual( + root.status.canonical_code, + trace_api.status.StatusCanonicalCode.OK, + ) def test_error_status(self): try: From eefcaa386950fdcd65684c52fc5a2beeb530571e Mon Sep 17 00:00:00 2001 From: Diego Hurtado Date: Fri, 17 Jan 2020 13:36:59 -0600 Subject: [PATCH 11/11] Remove duplicate test --- opentelemetry-sdk/tests/trace/test_trace.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index ba8eb35efd4..a7c7ee05286 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -549,11 +549,6 @@ def test_span_override_start_and_end_time(self): def test_ended_span(self): """"Events, attributes are not allowed after span is ended""" - # Test that end() is called when the context manager is exited - with self.assertLogs(level=WARNING): - with self.tracer.start_as_current_span("root") as root: - root.end() - root = self.tracer.start_span("root") # everything should be empty at the beginning