Runtime context fails to detach token

[jha-hitesh]

Describe your environment
python 3.7
ujson
sanic==20.9.1
opentelemetry-api==1.9.1
opentelemetry-sdk==1.9.1
opentelemetry-propagator-jaeger==1.9.1
opentelemetry-exporter-jaeger-thrift==1.9.1
opentelemetry-instrumentation==0.28b1
opentelemetry-exporter-otlp-proto-http==1.10.0

Steps to reproduce
i have used the opentelemetry-instrumentation to create a middleware for sanic web framework, this middleware allows to trace a request, all seems good but sometimes the error Failed to detach context comes randomly for some request.

What is the expected behavior?
instead of Failed to detach context error , original exception should be logged as exception so that the actual issue can be debugged with proper stacktrace etc.
opentelemetry-python/opentelemetry-api/src/opentelemetry/context/init.py line

here instead of

except Exception:  # pylint: disable=broad-except
        logger.error("Failed to detach context")

it should be

except Exception as e:  # pylint: disable=broad-except
        logger.error(e)

What is the actual behavior?
getting Failed to detach context error message instead of original message.

Additional context

[kasium]

I have the same request. Maybe the code could also be changed to

except Exception as e:  # pylint: disable=broad-except
        logger.exception("Failed to detach context")

Is a PR possible?

[lzchen]

@jha-hitesh
Any idea why the detaching the context would be throwing an exception? We wouldn't want an instrumentation to error out on detaching the context anyways. Maybe make the change locally in the context to debug this. Changing the try except to be not as generic could be a separate issue.

[sihrc]

@lzchen

Traceback (most recent call last):
  File "/project/.venv/lib/python3.10/site-packages/opentelemetry/context/__init__.py", line 153, in detach
    _RUNTIME_CONTEXT.detach(token)  # type: ignore
  File "/project/.venv/lib/python3.10/site-packages/opentelemetry/context/contextvars_context.py", line 56, in detach
    self._current_context.reset(token)  # type: ignore
ValueError: <Token var=<ContextVar name='current_context' default={} at 0x7fa9ac2df380> at 0x7fa9ac341780> was created in a different Context

This kind of exception :)

[lzchen]

@sihrc
Does this not seem like the instrumentation itself has a bug in it? (in which detach is actually called incorrectly)

[kasium]

@lzchen I'm not able to change this locally. Would you accept an exception which changes the log from error to exception?

[lzchen]

@kasium
Feel free to submit a pr :)

[srikanthccv]

This is fixed in #2774

[junli-lyft]

@lzchen

Traceback (most recent call last):
  File "/project/.venv/lib/python3.10/site-packages/opentelemetry/context/__init__.py", line 153, in detach
    _RUNTIME_CONTEXT.detach(token)  # type: ignore
  File "/project/.venv/lib/python3.10/site-packages/opentelemetry/context/contextvars_context.py", line 56, in detach
    self._current_context.reset(token)  # type: ignore
ValueError: <Token var=<ContextVar name='current_context' default={} at 0x7fa9ac2df380> at 0x7fa9ac341780> was created in a different Context

This kind of exception :)

Hi @sihrc, are you able to root cause this issue and fix it? I am having this exception and not sure how to fix it.
I traceback.print_stack() the call stack:

File "/opt/homebrew/Cellar/python-bundle-arm64/0.0.0/brew/opt/python38/Frameworks/Python.framework/Versions/3.8/lib/python3.8/threading.py", line 890, in _bootstrap
    self._bootstrap_inner()
  File "/opt/homebrew/Cellar/python-bundle-arm64/0.0.0/brew/opt/python38/Frameworks/Python.framework/Versions/3.8/lib/python3.8/threading.py", line 932, in _bootstrap_inner
    self.run()
  File "/opt/homebrew/Cellar/python-bundle-arm64/0.0.0/brew/opt/python38/Frameworks/Python.framework/Versions/3.8/lib/python3.8/threading.py", line 870, in run
    self._target(*self._args, **self._kwargs)
  File "/Users/junli/.cache/lyftvenv/v/hello-world/tmp58xgye3z/lib/python3.8/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 268, in worker
    self._export(flush_request)
  File "/Users/junli/.cache/lyftvenv/v/hello-world/tmp58xgye3z/lib/python3.8/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 333, in _export
    self._export_batch()
  File "/Users/junli/.cache/lyftvenv/v/hello-world/tmp58xgye3z/lib/python3.8/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 361, in _export_batch
    detach(token)
  File "/Users/junli/.cache/lyftvenv/v/hello-world/tmp58xgye3z/lib/python3.8/site-packages/opentelemetry/context/__init__.py", line 67, in wrapper
    return func(*args, **kwargs)  # type: ignore[misc]
  File "/Users/junli/.cache/lyftvenv/v/hello-world/tmp58xgye3z/lib/python3.8/site-packages/opentelemetry/context/__init__.py", line 159, in detach

But I am not sure how to troubleshoot further. Any ideas?

[eliatcodecov]

I'm having a similar issue to @junli-lyft regarding hitting this exception in detach and cannot seem to reliably reproduce in development. I would love some insight on how to address this, but in my case this issue appears to occur when _RUNTIME_CONTEXT is None.

Is it an actual error for _RUNTIME_CONTEXT to be None ? If so, how can we troubleshoot this further? If None is a valid state for the _RUNTIME_CONTEXT should detach account for that before throwing the exception?

[srikanthccv]

Since this appears to be an issue for multiple users, I am going to re-open this with a different title. The original issue was about showing the exception with a log instead of a simple message.

Is it an actual error for _RUNTIME_CONTEXT to be None ?

Yes, _RUNTIME_CONTEXT should never be None.