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.

Sign up for GitHub

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

Set status properly on end #358

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
11 commits
Select commit Hold shift + click to select a range
36592d3
Set status properly on end
ocelotl Jan 9, 2020
f128646
Handle warnings
ocelotl Jan 9, 2020
3b6fd42
Some more fixes
ocelotl Jan 10, 2020
79ccce9
Handle last warning
ocelotl Jan 10, 2020
0c7ef7e
Catch errors separately
ocelotl Jan 10, 2020
47527ea
Use logging.ERROR
ocelotl Jan 10, 2020
eecb01c
Fix isort issues
ocelotl Jan 10, 2020
b3472e3
Use correct attributes
ocelotl Jan 10, 2020
ab6628b
Fix attribute setting
ocelotl Jan 13, 2020
a60c24f
Refactor test case
ocelotl Jan 17, 2020
eefcaa3
Remove duplicate test
ocelotl Jan 17, 2020
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
View file
Open in desktop
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 •
edited
Loading

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
57 changes: 35 additions & 22 deletions opentelemetry-sdk/tests/trace/test_trace.py
View file
Open in desktop
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,45 @@ 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)
root = self.tracer.start_span("root")

# call end first time
root.end()
end_time0 = root.end_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 it a second time
# 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
View file
Open in desktop
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