From 25fa67e3c9abbadfb7f82a26a57664a14fc1c50f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Fri, 8 Nov 2019 13:35:22 -0500 Subject: [PATCH 1/8] sdk: shut down span processors automatically The BatchExportSpanProcessor is an asynchronous span processor that uses a worker thread to call the different exporters. Before this commit applications had to shut down the span processor explicitely to guarantee that all the spans were summited to the exporters, this was not very intuitive for the users. This commit removes that limitation by implementing the tracer's __del__ method and an atexit hook. According to __del__'s documentation [1] it is possible that sometimes it's not called, for that reason the atexit hook is also used to guarantee that the processor is shut down in all the cases. [1] https://docs.python.org/3/reference/datamodel.html#object.__del__ --- examples/trace/client.py | 1 - examples/trace/server.py | 1 - ext/opentelemetry-ext-azure-monitor/examples/client.py | 1 - ext/opentelemetry-ext-azure-monitor/examples/server.py | 1 - ext/opentelemetry-ext-jaeger/README.rst | 4 ---- .../examples/jaeger_exporter_example.py | 4 ---- opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py | 8 ++++++++ 7 files changed, 8 insertions(+), 12 deletions(-) diff --git a/examples/trace/client.py b/examples/trace/client.py index 662cea8d969..d25fa60c9b7 100755 --- a/examples/trace/client.py +++ b/examples/trace/client.py @@ -39,4 +39,3 @@ tracer.add_span_processor(span_processor) response = requests.get(url="http://127.0.0.1:5000/") -span_processor.shutdown() diff --git a/examples/trace/server.py b/examples/trace/server.py index 3632540e213..0ce5a99c2c7 100755 --- a/examples/trace/server.py +++ b/examples/trace/server.py @@ -52,4 +52,3 @@ def hello(): if __name__ == "__main__": app.run(debug=True) - span_processor.shutdown() diff --git a/ext/opentelemetry-ext-azure-monitor/examples/client.py b/ext/opentelemetry-ext-azure-monitor/examples/client.py index ff954788e66..044050322f8 100644 --- a/ext/opentelemetry-ext-azure-monitor/examples/client.py +++ b/ext/opentelemetry-ext-azure-monitor/examples/client.py @@ -27,4 +27,3 @@ tracer.add_span_processor(span_processor) response = requests.get(url="http://127.0.0.1:5000/") -span_processor.shutdown() diff --git a/ext/opentelemetry-ext-azure-monitor/examples/server.py b/ext/opentelemetry-ext-azure-monitor/examples/server.py index 9374c986a4a..9b4e9ab8324 100644 --- a/ext/opentelemetry-ext-azure-monitor/examples/server.py +++ b/ext/opentelemetry-ext-azure-monitor/examples/server.py @@ -41,4 +41,3 @@ def hello(): if __name__ == "__main__": app.run(debug=True) - span_processor.shutdown() diff --git a/ext/opentelemetry-ext-jaeger/README.rst b/ext/opentelemetry-ext-jaeger/README.rst index 04ccdfac4ac..b4493f6174e 100644 --- a/ext/opentelemetry-ext-jaeger/README.rst +++ b/ext/opentelemetry-ext-jaeger/README.rst @@ -54,10 +54,6 @@ gRPC is still not supported by this implementation. with tracer.start_as_current_span('foo'): print('Hello world!') - # shutdown the span processor - # TODO: this has to be improved so user doesn't need to call it manually - span_processor.shutdown() - The `examples <./examples>`_ folder contains more elaborated examples. References diff --git a/ext/opentelemetry-ext-jaeger/examples/jaeger_exporter_example.py b/ext/opentelemetry-ext-jaeger/examples/jaeger_exporter_example.py index 5cf57bfccad..d557f3fc258 100644 --- a/ext/opentelemetry-ext-jaeger/examples/jaeger_exporter_example.py +++ b/ext/opentelemetry-ext-jaeger/examples/jaeger_exporter_example.py @@ -45,7 +45,3 @@ time.sleep(0.2) time.sleep(0.1) - -# shutdown the span processor -# TODO: this has to be improved so user doesn't need to call it manually -span_processor.shutdown() diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index d06d34d93bc..3c71e74f186 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -13,6 +13,7 @@ # limitations under the License. +import atexit import logging import random import threading @@ -333,6 +334,13 @@ def __init__( self._current_span_slot = Context.register_slot(slot_name) self._active_span_processor = MultiSpanProcessor() self.sampler = sampler + self._atexit_hanlder = atexit.register( + self._active_span_processor.shutdown + ) + + def __del__(self): + atexit.unregister(self._atexit_hanlder) + self._active_span_processor.shutdown() def get_current_span(self): """See `opentelemetry.trace.Tracer.get_current_span`.""" From 5375741eb1ab241431c1ab7477a5d4ca22d9a21d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Tue, 12 Nov 2019 21:05:06 -0500 Subject: [PATCH 2/8] don't use __del__ and implement Tracer.shutdown --- .../src/opentelemetry/sdk/trace/__init__.py | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index 3c71e74f186..79a2e9c3d20 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -321,12 +321,15 @@ class Tracer(trace_api.Tracer): Args: name: The name of the tracer. + shutdown_on_exit: Register an atexit hook to shutdown the tracer when + the application exits. """ def __init__( self, name: str = "", sampler: sampling.Sampler = trace_api.sampling.ALWAYS_ON, + shutdown_on_exit: bool = True, ) -> None: slot_name = "current_span" if name: @@ -334,13 +337,8 @@ def __init__( self._current_span_slot = Context.register_slot(slot_name) self._active_span_processor = MultiSpanProcessor() self.sampler = sampler - self._atexit_hanlder = atexit.register( - self._active_span_processor.shutdown - ) - - def __del__(self): - atexit.unregister(self._atexit_hanlder) - self._active_span_processor.shutdown() + if shutdown_on_exit: + self._atexit_handler = atexit.register(self.shutdown) def get_current_span(self): """See `opentelemetry.trace.Tracer.get_current_span`.""" @@ -462,5 +460,11 @@ def add_span_processor(self, span_processor: SpanProcessor) -> None: # thread safe self._active_span_processor.add_span_processor(span_processor) + def shutdown(self): + """Shutdown the span processors added to the tracer.""" + self._active_span_processor.shutdown() + if hasattr(self, "_atexit_handler"): + atexit.unregister(self._atexit_handler) + tracer = Tracer() From 981f2ba27855b7b6b80e8e19b9cb5de81449dab1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Wed, 13 Nov 2019 18:03:03 -0500 Subject: [PATCH 3/8] tests: add tests for shutdown - test that span processor (Simple and Batch) shut down exporters - test that trace shuts down span processor - test atexit hook in Tracer.shutdown() --- .../tests/trace/export/test_export.py | 9 +++ opentelemetry-sdk/tests/trace/test_trace.py | 70 +++++++++++++++++++ 2 files changed, 79 insertions(+) diff --git a/opentelemetry-sdk/tests/trace/export/test_export.py b/opentelemetry-sdk/tests/trace/export/test_export.py index d45afc299a2..9ad65aea881 100644 --- a/opentelemetry-sdk/tests/trace/export/test_export.py +++ b/opentelemetry-sdk/tests/trace/export/test_export.py @@ -27,6 +27,7 @@ class MySpanExporter(export.SpanExporter): def __init__(self, destination, max_export_batch_size=None): self.destination = destination self.max_export_batch_size = max_export_batch_size + self.is_shutdown = False def export(self, spans: trace.Span) -> export.SpanExportResult: if ( @@ -37,6 +38,9 @@ def export(self, spans: trace.Span) -> export.SpanExportResult: self.destination.extend(span.name for span in spans) return export.SpanExportResult.SUCCESS + def shutdown(self): + self.is_shutdown = True + class TestSimpleExportSpanProcessor(unittest.TestCase): def test_simple_span_processor(self): @@ -55,6 +59,9 @@ def test_simple_span_processor(self): self.assertListEqual(["xxx", "bar", "foo"], spans_names_list) + span_processor.shutdown() + self.assertTrue(my_exporter.is_shutdown) + def test_simple_span_processor_no_context(self): """Check that we process spans that are never made active. @@ -102,6 +109,8 @@ def test_batch_span_processor(self): span_processor.shutdown() self.assertListEqual(span_names, spans_names_list) + self.assertTrue(my_exporter.is_shutdown) + def test_batch_span_processor_lossless(self): """Test that no spans are lost when sending max_queue_size spans""" spans_names_list = [] diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index 50249479a7e..6938f464d87 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -12,6 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import subprocess import unittest from unittest import mock @@ -26,6 +27,75 @@ def test_extends_api(self): tracer = trace.Tracer() self.assertIsInstance(tracer, trace_api.Tracer) + def test_shutdown(self): + tracer = trace.Tracer() + + mock_processor1 = mock.Mock(spec=trace.SpanProcessor) + tracer.add_span_processor(mock_processor1) + + mock_processor2 = mock.Mock(spec=trace.SpanProcessor) + tracer.add_span_processor(mock_processor2) + + tracer.shutdown() + + mock_processor1.shutdown.assert_called_once() + mock_processor2.shutdown.assert_called_once() + + shutdown_python_code = """ +import atexit +from unittest import mock + +from opentelemetry.sdk import trace + +mock_processor = mock.Mock(spec=trace.SpanProcessor) + +def print_shutdown_count(): + print(mock_processor.shutdown.call_count) + +# atexit hooks are called in inverse order they are added, so do this before +# creating the tracer +atexit.register(print_shutdown_count) + +tracer = trace.Tracer({tracer_parameters}) +tracer.add_span_processor(mock_processor) + +{tracer_shutdown} +""" + + def run_general_code(shutdown_on_exit, explicit_shutdown): + tracer_parameters = "" + tracer_shutdown = "" + + if not shutdown_on_exit: + tracer_parameters = "shutdown_on_exit=False" + + if explicit_shutdown: + tracer_shutdown = "tracer.shutdown()" + + return subprocess.check_output( + [ + "python", + "-c", + shutdown_python_code.format( + tracer_parameters=tracer_parameters, + tracer_shutdown=tracer_shutdown, + ), + ] + ) + + # test default shutdown_on_exit (True) + out = run_general_code(True, False) + self.assertTrue(out.startswith(b"1")) + + # test that shutdown is called only once even if Tracer.shutdown is + # called explicitely + out = run_general_code(True, True) + self.assertTrue(out.startswith(b"1")) + + # test shutdown_on_exit=False + out = run_general_code(False, False) + self.assertTrue(out.startswith(b"0")) + class TestTracerSampling(unittest.TestCase): def test_default_sampler(self): From e1bb7987b9bf306ebfc1678404d839817c8bd79f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Wed, 13 Nov 2019 18:09:58 -0500 Subject: [PATCH 4/8] replace assert_called_once() no available in python < 3.6 --- 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 6938f464d87..6dda56ec1a9 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -38,8 +38,8 @@ def test_shutdown(self): tracer.shutdown() - mock_processor1.shutdown.assert_called_once() - mock_processor2.shutdown.assert_called_once() + self.assertEqual(mock_processor1.shutdown.call_count, 1) + self.assertEqual(mock_processor2.shutdown.call_count, 1) shutdown_python_code = """ import atexit From 1fda442de9489af81a6f27702e34b0bf3f7f702c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Fri, 15 Nov 2019 22:07:44 -0500 Subject: [PATCH 5/8] remove shutdown from example --- examples/basic_tracer/tracer.py | 1 - 1 file changed, 1 deletion(-) diff --git a/examples/basic_tracer/tracer.py b/examples/basic_tracer/tracer.py index c99141f5aac..514bf74405e 100755 --- a/examples/basic_tracer/tracer.py +++ b/examples/basic_tracer/tracer.py @@ -49,4 +49,3 @@ with tracer.start_as_current_span("baz"): print(Context) -span_processor.shutdown() From 7453436311f1d7847863d498843af161085fd5d1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Mon, 18 Nov 2019 07:01:15 -0500 Subject: [PATCH 6/8] make link happy --- examples/basic_tracer/tracer.py | 1 - 1 file changed, 1 deletion(-) diff --git a/examples/basic_tracer/tracer.py b/examples/basic_tracer/tracer.py index 514bf74405e..69ee0a1602d 100755 --- a/examples/basic_tracer/tracer.py +++ b/examples/basic_tracer/tracer.py @@ -48,4 +48,3 @@ with tracer.start_as_current_span("bar"): with tracer.start_as_current_span("baz"): print(Context) - From 41b6cb4f7627c7952a6689a3d5b7647715a04f5a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Tue, 19 Nov 2019 19:18:35 -0500 Subject: [PATCH 7/8] handle feedback - avoid using hasattr and assign member to None instead - use shutil.which to overcome problem in windows --- opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py | 4 +++- opentelemetry-sdk/tests/trace/test_trace.py | 5 ++++- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index 7076d1e20e9..b38de80b83c 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -313,6 +313,7 @@ def __init__( self._current_span_slot = Context.register_slot(slot_name) self._active_span_processor = MultiSpanProcessor() self.sampler = sampler + self._atexit_handler = None if shutdown_on_exit: self._atexit_handler = atexit.register(self.shutdown) @@ -453,8 +454,9 @@ def add_span_processor(self, span_processor: SpanProcessor) -> None: def shutdown(self): """Shutdown the span processors added to the tracer.""" self._active_span_processor.shutdown() - if hasattr(self, "_atexit_handler"): + if self._atexit_handler is not None: atexit.unregister(self._atexit_handler) + self._atexit_handler = None tracer = Tracer() diff --git a/opentelemetry-sdk/tests/trace/test_trace.py b/opentelemetry-sdk/tests/trace/test_trace.py index c6cc575133f..7d3f9dec4f6 100644 --- a/opentelemetry-sdk/tests/trace/test_trace.py +++ b/opentelemetry-sdk/tests/trace/test_trace.py @@ -12,6 +12,7 @@ # See the License for the specific language governing permissions and # limitations under the License. +import shutil import subprocess import unittest from unittest import mock @@ -74,7 +75,9 @@ def run_general_code(shutdown_on_exit, explicit_shutdown): return subprocess.check_output( [ - "python", + # use shutil to avoid calling python outside the + # virtualenv on windows. + shutil.which("python"), "-c", shutdown_python_code.format( tracer_parameters=tracer_parameters, From 1827ed05d158cbbbbda9915d0a4c36401384dbea Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mauricio=20V=C3=A1squez?= Date: Mon, 25 Nov 2019 20:00:52 -0500 Subject: [PATCH 8/8] fix docstrings --- opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py index b38de80b83c..8cae310b1e0 100644 --- a/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py +++ b/opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py @@ -297,8 +297,8 @@ class Tracer(trace_api.Tracer): Args: name: The name of the tracer. - shutdown_on_exit: Register an atexit hook to shutdown the tracer when - the application exits. + shutdown_on_exit: Register an atexit hook to shut down the tracer when + the application exits. """ def __init__( @@ -452,7 +452,7 @@ def add_span_processor(self, span_processor: SpanProcessor) -> None: self._active_span_processor.add_span_processor(span_processor) def shutdown(self): - """Shutdown the span processors added to the tracer.""" + """Shut down the span processors added to the tracer.""" self._active_span_processor.shutdown() if self._atexit_handler is not None: atexit.unregister(self._atexit_handler)