Set status properly on end #358

ocelotl · 2020-01-09T00:33:17Z

Fixes #357

ocelotl · 2020-01-09T00:35:06Z

@condorcet, please give this a try.

codecov-io · 2020-01-09T00:49:32Z

Codecov Report

Merging #358 into master will increase coverage by 0.14%.
The diff coverage is 100%.

@@            Coverage Diff             @@
##           master     #358      +/-   ##
==========================================
+ Coverage   84.82%   84.96%   +0.14%     
==========================================
  Files          38       38              
  Lines        1845     1889      +44     
  Branches      217      217              
==========================================
+ Hits         1565     1605      +40     
- Misses        214      219       +5     
+ Partials       66       65       -1

Impacted Files	Coverage Δ
...emetry-sdk/src/opentelemetry/sdk/trace/__init__.py	`90.12% <100%> (+0.41%)`	⬆️
...ntelemetry-api/src/opentelemetry/trace/__init__.py	`84.56% <0%> (+0.44%)`	⬆️
...elemetry-api/src/opentelemetry/metrics/__init__.py	`87.93% <0%> (+1.93%)`	⬆️

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update f0ba817...eefcaa3. Read the comment docs.

codeboten · 2020-01-09T00:55:10Z

opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py

                self.end_time = end_time if end_time is not None else time_ns()
+
        if has_ended:


should the has_ended check be moved up as well?

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

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.

condorcet · 2020-01-09T09:26:43Z

It's not directly addressing to the PR but I think it's better to consider these improvements:

Enable logging for tests. For example we can add

[pytest]
log_cli = true
log_cli_level = warning

Wrap tests when we expect logs with something like this

...
with self.assertLogs(...):
    # call it a second time
    root.end()
    ...

So we wouldn't spam in stdout about every log, but it can show unexpected warnings in code that mustn't produce warnings, critical, etc.

ocelotl · 2020-01-09T16:13:39Z

It's not directly addressing to the PR but I think it's better to consider these improvements:

Enable logging for tests. For example we can add
[pytest]
log_cli = true
log_cli_level = warning
Wrap tests when we expect logs with something like this
...
with self.assertLogs(...):
    # call it a second time
    root.end()
    ...
So we wouldn't spam in stdout about every log, but it can show unexpected warnings in code that mustn't produce warnings, critical, etc.

Yes! this is a great idea.

toumorokoshi · 2020-01-09T16:40:11Z

opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py

@@ -259,14 +259,15 @@ def end(self, end_time: Optional[int] = None) -> None:
                raise RuntimeError("Calling end() on a not started span.")


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.

toumorokoshi

Nice!

toumorokoshi · 2020-01-09T16:45:20Z

opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py

@@ -259,14 +259,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:
+                if self.status is None:
+                    self.status = Status(canonical_code=StatusCanonicalCode.OK)


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

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.

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.

I am addressing this issue in #363.

ocelotl · 2020-01-09T22:42:44Z

Ok, good, @toumorokoshi and @codeboten have raised important issues related to these changes. I think is better to move them into another PRs to fix this issue now (I say it is pretty urgent since this is a bug, the status is not being set) and to no longer block @condorcet. I have added also @condorcet's logging enhancements in our tests.

opentelemetry-sdk/tests/trace/test_trace.py

opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py

condorcet · 2020-01-11T09:07:50Z

opentelemetry-sdk/tests/trace/test_trace.py

@@ -545,7 +549,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:


@ocelotl Wow! Cool, but looks complicated :) I think this test can be simplified: we can wrap code with assertLogs only once and check how many logs we have at the end. Something like this:

def test_ended_span(self): """"Events, attributes are not allowed after span is ended""" with self.assertLogs(level=WARNING) as _logs: with self.tracer.start_as_current_span("root") as root: ... self.assertEqual(len(_logs.records), 6)

Further if we really need we can check every log in records. But now counting logs is enough in my opinion.
What do you think?

I say we leave it as it is 🙂 . It is more precise to handle each warning individually and even as it is a bit complicated right now, it serves its purpose well.

Wouldn't it be possible to add an independent test just for it avoiding an ad-hoc class?

Maybe, but how? 🤔 The class introduced here is just there to help catch a specific warning without affecting the catching of other warnings. I'm not sure how an independent test can help with this. It would be great if we can come up with a simpler implementation that can handle each warning independently and specifically, but I have no other ideas on how to achieve this 🤷‍♂️.

Based on @condorcet's idea, you could create a specific test case for it:

def test_warning_end_span(self): with self.assertLogs(level=WARNING) as _logs: with self.tracer.start_as_current_span("root") as root: root.end() self.assertEqual(len(_logs.records), 1)

I have a second thought and I think this test can be removed, it's testing if there is a warning when the context goes out, so it calls the span.end(), we already have a test to check if the context calls span.end(). The test if span.end() prints a warning is already present on this PR.

Another way is just using start_span manually instead of wrapping code by start_as_current_span context manager that spam with warning when try to end() span. For testing purpose It will be enough.
Something like this:

def test_ended_span(self): """"Events, attributes are not allowed after span is ended""" root = self.tracer.start_span("root") # everything should be empty at the beginning self.assertEqual(len(root.attributes), 0) ...

Ok, refactored, please let me know what you think now @condorcet, @mauriciovasquezbernal. 👍

Fixes open-telemetry#357

mauriciovasquezbernal · 2020-01-14T16:15:54Z

I think this PR is doing more than simply fixing #357, @ocelotl would you mind adding a description so it is easier to review?
Btw, given that there is some discussion going around this PR, maybe you want to split and provide a quick fix for #357 and then do other changes in a different PR.

ocelotl · 2020-01-14T17:01:22Z

I think this PR is doing more than simply fixing #357, @ocelotl would you mind adding a description so it is easier to review?
Btw, given that there is some discussion going around this PR, maybe you want to split and provide a quick fix for #357 and then do other changes in a different PR.

Well, this PR is actually just fixing #357. The changes to introduced by this PR to fix that issue are very small, just 5 lines here and here.

The rest of the changes are mostly in one test suite. I can't split the fix from the test suite changes because the test suite changes are needed for them to pass again.

mauriciovasquezbernal

Just a comment about a test that I think should be removed, otherwise LGTM.

mauriciovasquezbernal · 2020-01-17T17:37:49Z

opentelemetry-sdk/tests/trace/test_trace.py

-            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


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

opentelemetry-python/opentelemetry-sdk/tests/trace/test_trace.py

Line 243 in ada53ff

self.assertIsNotNone(root.end_time)

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

Ok, I see what you mean, updated.

toumorokoshi · 2020-01-20T17:18:35Z

Great, thanks!

Based on the changes of open-telemetry#358 Signed-off-by: Daniel González Lopes <danielgonzalezlopes@gmail.com>

ocelotl requested a review from a team as a code owner January 9, 2020 00:33

ocelotl self-assigned this Jan 9, 2020

ocelotl added the sdk Affects the SDK package. label Jan 9, 2020

ocelotl force-pushed the issue_357 branch from c27217e to 62b0302 Compare January 9, 2020 00:37

codeboten reviewed Jan 9, 2020

View reviewed changes

toumorokoshi reviewed Jan 9, 2020

View reviewed changes

toumorokoshi approved these changes Jan 9, 2020

View reviewed changes

This was referenced Jan 9, 2020

Couple span's start_time and end_time with start and end methods #361

Closed

Check the protected code in SDK Span methods that use self._lock #362

Closed

ocelotl requested review from codeboten and toumorokoshi January 10, 2020 00:13

condorcet reviewed Jan 10, 2020

View reviewed changes

opentelemetry-sdk/tests/trace/test_trace.py Outdated Show resolved Hide resolved

opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py Outdated Show resolved Hide resolved

opentelemetry-sdk/src/opentelemetry/sdk/trace/__init__.py Outdated Show resolved Hide resolved

condorcet reviewed Jan 11, 2020

View reviewed changes

ocelotl added 8 commits January 13, 2020 16:17

Set status properly on end

36592d3

Fixes open-telemetry#357

Handle warnings

f128646

Some more fixes

3b6fd42

Handle last warning

79ccce9

Catch errors separately

0c7ef7e

Use logging.ERROR

47527ea

Fix isort issues

eecb01c

Use correct attributes

b3472e3

ocelotl force-pushed the issue_357 branch from 6fcfed7 to b3472e3 Compare January 13, 2020 22:25

Fix attribute setting

ab6628b

ocelotl force-pushed the issue_357 branch from 149b40a to ab6628b Compare January 14, 2020 07:13

ocelotl requested a review from mauriciovasquezbernal January 14, 2020 17:09

Refactor test case

a60c24f

mauriciovasquezbernal approved these changes Jan 17, 2020

View reviewed changes

Remove duplicate test

eefcaa3

condorcet approved these changes Jan 18, 2020

View reviewed changes

toumorokoshi merged commit 4f71fba into open-telemetry:master Jan 20, 2020

dgzlopes added a commit to dgzlopes/opentelemetry-python that referenced this pull request Jan 22, 2020

Fix Jaeger status

583279c

Based on the changes of open-telemetry#358 Signed-off-by: Daniel González Lopes <danielgonzalezlopes@gmail.com>

srikanthccv pushed a commit to srikanthccv/opentelemetry-python that referenced this pull request Nov 1, 2020

chore: add development guide (open-telemetry#358)

ab8f3c1

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Set status properly on end #358

Set status properly on end #358

ocelotl commented Jan 9, 2020

ocelotl commented Jan 9, 2020

codecov-io commented Jan 9, 2020 •

edited

Loading

codeboten Jan 9, 2020 •

edited

Loading

ocelotl Jan 9, 2020

ocelotl Jan 9, 2020

condorcet commented Jan 9, 2020

ocelotl commented Jan 9, 2020

toumorokoshi Jan 9, 2020

toumorokoshi left a comment

toumorokoshi Jan 9, 2020

ocelotl Jan 9, 2020

ocelotl Jan 9, 2020

ocelotl Jan 10, 2020

ocelotl commented Jan 9, 2020

condorcet Jan 11, 2020

ocelotl Jan 13, 2020

mauriciovasquezbernal Jan 14, 2020

ocelotl Jan 14, 2020

mauriciovasquezbernal Jan 14, 2020

mauriciovasquezbernal Jan 14, 2020

condorcet Jan 15, 2020

ocelotl Jan 17, 2020

mauriciovasquezbernal commented Jan 14, 2020

ocelotl commented Jan 14, 2020

mauriciovasquezbernal left a comment

mauriciovasquezbernal Jan 17, 2020

ocelotl Jan 17, 2020

toumorokoshi commented Jan 20, 2020

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

		if has_ended:

		@@ -259,14 +259,15 @@ def end(self, end_time: Optional[int] = None) -> None:
		raise RuntimeError("Calling end() on a not started span.")

Set status properly on end #358

Set status properly on end #358

Conversation

ocelotl commented Jan 9, 2020

ocelotl commented Jan 9, 2020

codecov-io commented Jan 9, 2020 • edited Loading

Codecov Report

codeboten Jan 9, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

condorcet commented Jan 9, 2020

ocelotl commented Jan 9, 2020

Choose a reason for hiding this comment

toumorokoshi left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ocelotl commented Jan 9, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mauriciovasquezbernal commented Jan 14, 2020

ocelotl commented Jan 14, 2020

mauriciovasquezbernal left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

toumorokoshi commented Jan 20, 2020

codecov-io commented Jan 9, 2020 •

edited

Loading

codeboten Jan 9, 2020 •

edited

Loading