Skip to content

Set status properly on end #358

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 11 commits into from
Jan 20, 2020
Merged
Show file tree
Hide file tree
Changes from 10 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 6 additions & 4 deletions opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down Expand Up @@ -267,16 +268,17 @@ def end(self, end_time: Optional[int] = None) -> None:
raise RuntimeError("Calling end() on a not started span.")
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

a random aside, but there's a lot of stuff in this lock that we can probably move out (e.g. the check to see if we're recording traces).

Not sure what sort of contention we'll see here, but keeping the locks tight is a good thing.

has_ended = self.end_time is not None
if not has_ended:
if self.status is None:
self.status = Status(canonical_code=StatusCanonicalCode.OK)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is it possible for a status to be none, even if an end_time exists?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we should not permit that. I think that self.end_time is a fine indicator that the span has ended (we might want to have a more clear attribute, like self.is_ended). The idea here is that every ended span should have a status. I'll look into this to make sure that I am not leaving a loophole where that situation (having an ended span with None status) can happen.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, end_time is part of our public API. What we don't want is a user setting this manually to some value while leaving the span status being None in an unended weird state. I'll move this into a property so that it can only be set by calling end (same thing with start_time). I'll move this into another PR.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am addressing this issue in #363.


self._end_time = (
end_time if end_time is not None else time_ns()
)

if has_ended:
Copy link
Contributor

@codeboten codeboten Jan 9, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should the has_ended check be moved up as well?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it was outside of the lock originally, I'll look into this.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have noticed a few unusual things regarding the things we have in self._lock (like this). I suggest we handle them in a separate PR.

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:
Expand Down
62 changes: 40 additions & 22 deletions opentelemetry-sdk/tests/trace/test_trace.py
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
import shutil
import subprocess
import unittest
from logging import ERROR, WARNING
from unittest import mock

from opentelemetry import trace as trace_api
Expand Down Expand Up @@ -167,8 +168,10 @@ 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("")
with self.assertLogs(level=ERROR):
tracer2 = tracer_source.get_tracer(None)
self.assertEqual(
tracer1.instrumentation_info, tracer2.instrumentation_info
)
Expand Down Expand Up @@ -516,7 +519,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)
Expand Down Expand Up @@ -545,36 +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"""

with self.tracer.start_as_current_span("root") 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)
# Test that end() is called when the context manager is exited

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this test is duplicated.
Test that a span is ended by the context manager is done here

self.assertIsNotNone(root.end_time)

Test that ends() prints a warning when called twice is handled in this PR.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, I see what you mean, updated.

with self.assertLogs(level=WARNING):
with self.tracer.start_as_current_span("root") as root:
root.end()

# call end first time
root.end()
end_time0 = root.end_time
root = self.tracer.start_span("root")

# call it a second time
# 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 it a second time
with self.assertLogs(level=WARNING):
root.end()
# end time shouldn't be changed
self.assertEqual(end_time0, root.end_time)
# 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)
self.assertEqual(len(root.attributes), 0)

with self.assertLogs(level=WARNING):
root.add_event("event1")
self.assertEqual(len(root.events), 0)
self.assertEqual(len(root.events), 0)

with self.assertLogs(level=WARNING):
root.update_name("xxx")
self.assertEqual(root.name, "root")
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.assertIs(root.status, None)
self.assertEqual(
root.status.canonical_code,
trace_api.status.StatusCanonicalCode.OK,
)

def test_error_status(self):
try:
Expand Down
2 changes: 2 additions & 0 deletions pytest.ini
Original file line number Diff line number Diff line change
@@ -1,2 +1,4 @@
[pytest]
addopts = -rs -v
log_cli = true
log_cli_level = warning