Skip to content
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

Not properly set status on exception #377

Closed
GoPavel opened this issue Jan 24, 2020 · 3 comments · Fixed by #381
Closed

Not properly set status on exception #377

GoPavel opened this issue Jan 24, 2020 · 3 comments · Fixed by #381
Assignees
Labels
bug Something isn't working sdk Affects the SDK package. tracing

Comments

@GoPavel
Copy link
Contributor

GoPavel commented Jan 24, 2020

Exception handling from PR#297 have misbehavior in straightforward case:

    def test2_error_status(self):
        try:
            with trace.Tracer("test_error_status").start_as_current_span("root") as root:
                raise Exception("unknown")
        except Exception:  # pylint: disable=broad-except
            pass

        # Fail: root.status.canonical_code is StatusCanonicalCode.OK
        self.assertIs(root.status.canonical_code, StatusCanonicalCode.UNKNOWN)
        self.assertEqual(root.status.description, "Exception: unknown")

I find that Span's method __exist__ can set status on exception, but it is not used here.

@GoPavel GoPavel added the bug Something isn't working label Jan 24, 2020
@GoPavel GoPavel changed the title Not properly set status on end Not properly set status on exception Jan 24, 2020
@ocelotl
Copy link
Contributor

ocelotl commented Jan 24, 2020

Hello @GoPavel

I just checked out the latest master code and ran this test case specifically with tox -e py37-test-sdk -- -k test_error_status:

py37-test-sdk installed: aiocontextvars==0.2.2,attrs==19.3.0,fancycompleter==0.8,importlib-metadata==1.4.0,more-itertools==8.1.0,opentelemetry-api==0.4.dev0,opentelemetry-sdk==0.4.dev0,packaging==20.0,pdbpp==0.10.2,pluggy==0.13.1,py==1.8.1,Pygments==2.5.2,pyparsing==2.4.6,pytest==5.3.2,six==1.13.0,wcwidth==0.1.8,wmctrl==0.3,zipp==1.0.0
py37-test-sdk run-test-pre: PYTHONHASHSEED='2779660199'
py37-test-sdk run-test-pre: commands[0] | python -m pip install -U pip setuptools wheel
Requirement already up-to-date: pip in /home/ocelotl/lightstep/opentelemetry-python/.tox/py37-test-sdk/lib/python3.7/site-packages (20.0.2)
Requirement already up-to-date: setuptools in /home/ocelotl/lightstep/opentelemetry-python/.tox/py37-test-sdk/lib/python3.7/site-packages (45.1.0)
Requirement already up-to-date: wheel in /home/ocelotl/lightstep/opentelemetry-python/.tox/py37-test-sdk/lib/python3.7/site-packages (0.33.6)
py37-test-sdk run-test-pre: commands[1] | pip install /home/ocelotl/lightstep/opentelemetry-python/opentelemetry-api
Processing /home/ocelotl/lightstep/opentelemetry-python/opentelemetry-api
Building wheels for collected packages: opentelemetry-api
  Building wheel for opentelemetry-api (setup.py): started
  Building wheel for opentelemetry-api (setup.py): finished with status 'done'
  Created wheel for opentelemetry-api: filename=opentelemetry_api-0.4.dev0-py3-none-any.whl size=39493 sha256=05e101eec846153c12af05548248444ae6cfbd5e87eb542addd93e770b05a1e5
  Stored in directory: /home/ocelotl/.cache/pip/wheels/2d/91/d8/43202637d9763d249681ba5d0f590e81c462e257e6638ec94a
Successfully built opentelemetry-api
Installing collected packages: opentelemetry-api
  Attempting uninstall: opentelemetry-api
    Found existing installation: opentelemetry-api 0.4.dev0
    Uninstalling opentelemetry-api-0.4.dev0:
      Successfully uninstalled opentelemetry-api-0.4.dev0
Successfully installed opentelemetry-api-0.4.dev0
py37-test-sdk run-test-pre: commands[2] | pip install /home/ocelotl/lightstep/opentelemetry-python/opentelemetry-sdk
Processing /home/ocelotl/lightstep/opentelemetry-python/opentelemetry-sdk
Requirement already satisfied: opentelemetry-api==0.4.dev0 in /home/ocelotl/lightstep/opentelemetry-python/.tox/py37-test-sdk/lib/python3.7/site-packages (from opentelemetry-sdk==0.4.dev0) (0.4.dev0)
Building wheels for collected packages: opentelemetry-sdk
  Building wheel for opentelemetry-sdk (setup.py): started
  Building wheel for opentelemetry-sdk (setup.py): finished with status 'done'
  Created wheel for opentelemetry-sdk: filename=opentelemetry_sdk-0.4.dev0-py3-none-any.whl size=20803 sha256=c2bcc3909a1f52c8013f7ea3883b3493770dc351d71e2b3ac7aa541824fc730a
  Stored in directory: /home/ocelotl/.cache/pip/wheels/bb/f3/17/7bb1ea254ec5a11835a19c45251a34897de2d3b9b8a51180b2
Successfully built opentelemetry-sdk
Installing collected packages: opentelemetry-sdk
  Attempting uninstall: opentelemetry-sdk
    Found existing installation: opentelemetry-sdk 0.4.dev0
    Uninstalling opentelemetry-sdk-0.4.dev0:
      Successfully uninstalled opentelemetry-sdk-0.4.dev0
Successfully installed opentelemetry-sdk-0.4.dev0
py37-test-sdk run-test: commands[0] | pytest -k test_error_status
============================= test session starts ==============================
platform linux -- Python 3.7.5rc1, pytest-5.3.2, py-1.8.1, pluggy-0.13.1 -- /home/ocelotl/lightstep/opentelemetry-python/.tox/py37-test-sdk/bin/python
cachedir: .tox/py37-test-sdk/.pytest_cache
rootdir: /home/ocelotl/lightstep/opentelemetry-python, inifile: pytest.ini
collecting ... collected 90 items / 89 deselected / 1 selected

trace/test_trace.py::TestSpan::test_error_status PASSED                  [100%]

======================= 1 passed, 89 deselected in 0.08s =======================
___________________________________ summary ____________________________________
  py37-test-sdk: commands succeeded
  congratulations :)

I even inspected __exit__ with set_trace and checked that the status was being set as should and it is.

Please let us know this:

  1. The expected result for this test case
  2. The actual result for this test case
  3. How to reproduce this issue

Thanks!

@GoPavel
Copy link
Contributor Author

GoPavel commented Jan 27, 2020

Sorry, we have a misunderstanding. I should have made more effort to explain the problem.

I find a bug with setting span status. Specifically, when I use start_as_current_span and exception is raised, span status is set to OK.
So I read source code of sdk.trace.__init__.py and find that properly exceptions handling contains in method Span.__exit__, but the new span isn't used as context manager during call start_as_current_span. I expected to see something like with span: in Tracer.use_span, but I didn't.
I check tests and find relative test. But it doesn't check the case when we get span from start_as_current_span. So I a little bit modify this test case:

def test_error_status_modified(self, tracer):
        try:
           # with trace.start_span("root") as root # OLD equivalent
           with trace.start_as_current_span("root") as root: # NEW
                raise Exception("unknown")
        except Exception:  # pylint: disable=broad-except
            pass

        # root.status.canonical_code is StatusCanonicalCode.OK !!!
        self.assertIs(root.status.canonical_code, StatusCanonicalCode.UNKNOWN) # Assertion Failed         
        self.assertEqual(root.status.description, "Exception: unknown")

The test above fail because Span.__exist__ isn't used here.
I expect that after try-except root.status.canonical_code is set to UNKNOWN, but I observe that status is OK

Now correct using start_as_current_span required manually use span as a context manager.
Workaround looks like:

        try:
           with trace.start_as_current_span("root") as root:
                with root: # WORKAROUND!!!
                   raise Exception("unknown")
        except Exception:  # pylint: disable=broad-except
            pass

I think it's a mistake and with trace.start_as_current_span(..): must to be responsible for exception handling and set corresponding span status like with start_span(..):.

@ocelotl
Copy link
Contributor

ocelotl commented Jan 27, 2020

Sorry, we have a misunderstanding. I should have made more effort to explain the problem.

I find a bug with setting span status. Specifically, when I use start_as_current_span and exception is raised, span status is set to OK.
So I read source code of sdk.trace.__init__.py and find that properly exceptions handling contains in method Span.__exit__, but the new span isn't used as context manager during call start_as_current_span. I expected to see something like with span: in Tracer.use_span, but I didn't.
I check tests and find relative test. But it doesn't check the case when we get span from start_as_current_span. So I a little bit modify this test case:

def test_error_status_modified(self, tracer):
        try:
           # with trace.start_span("root") as root # OLD equivalent
           with trace.start_as_current_span("root") as root: # NEW
                raise Exception("unknown")
        except Exception:  # pylint: disable=broad-except
            pass

        # root.status.canonical_code is StatusCanonicalCode.OK !!!
        self.assertIs(root.status.canonical_code, StatusCanonicalCode.UNKNOWN) # Assertion Failed         
        self.assertEqual(root.status.description, "Exception: unknown")

The test above fail because Span.__exist__ isn't used here.
I expect that after try-except root.status.canonical_code is set to UNKNOWN, but I observe that status is OK

Now correct using start_as_current_span required manually use span as a context manager.
Workaround looks like:

        try:
           with trace.start_as_current_span("root") as root:
                with root: # WORKAROUND!!!
                   raise Exception("unknown")
        except Exception:  # pylint: disable=broad-except
            pass

I think it's a mistake and with trace.start_as_current_span(..): must to be responsible for exception handling and set corresponding span status like with start_span(..):.

Ah, much clearer now, thanks! 👍

I'll get to work on this right away.

ocelotl added a commit to ocelotl/opentelemetry-python that referenced this issue Jan 28, 2020
@mauriciovasquezbernal mauriciovasquezbernal added tracing sdk Affects the SDK package. labels Jan 28, 2020
@ocelotl ocelotl self-assigned this Jan 28, 2020
@c24t c24t closed this as completed in #381 Jan 30, 2020
c24t pushed a commit that referenced this issue Jan 30, 2020
toumorokoshi pushed a commit to toumorokoshi/opentelemetry-python that referenced this issue Feb 17, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working sdk Affects the SDK package. tracing
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants