open-telemetry / open-telemetry/opentelemetry-python-contrib
Tornado integration raises `KeyError` when xsrf check fails
Nobody has claimed this yet.
- Dominant language
- Python
- Stars
- 1.1k
- Forks
- 1.1k
- Avg merge
- 4d 15h
- Merged PRs (30d)
- 16
Description
Describe your environment
- Python 3.10
- opentelemetry-instrumentation-tornado 0.41b0
- tornado 6.1.0
Steps to reproduce
- Create a Tornado app with
xsrf_cookiesenabled - Make a
POSTrequest to an endpoint without axsrfheader - Check server logs to see
KeyErrorexception being logged
What is the expected behavior?
Tornado warns that there is a missing xsrf cookie but does not raise an execption.
What is the actual behavior?
2023-10-13 13:48:02,233:web.py:1757:MainThread:ERROR: - Error in exception logger
Traceback (most recent call last):
File "/tmp/plz_sandbox/tornado_test.pex/third_party/python3/tornado/web.py", line 1679, in _execute
self.check_xsrf_cookie()
File "/tmp/plz_sandbox/tornado_test.pex/third_party/python3/tornado/web.py", line 1519, in check_xsrf_cookie
raise HTTPError(403, "'_xsrf' argument missing from POST")
tornado.web.HTTPError: HTTP 403: Forbidden ('_xsrf' argument missing from POST)
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/tmp/plz_sandbox/tornado_test.pex/third_party/python3/tornado/web.py", line 1753, in _handle_request_exception
self.log_exception(*sys.exc_info())
File "/tmp/plz_sandbox/tornado_test.pex/third_party/python3/opentelemetry/instrumentation/tornado/__init__.py", line 400, in _log_exception
_record_on_finish_metrics(server_histograms, handler, error)
File "/tmp/plz_sandbox/tornado_test.pex/third_party/python3/opentelemetry/instrumentation/tornado/__init__.py", line 586, in _record_on_finish_metrics
(default_timer() - server_histograms[_START_TIME]) * 1000
KeyError: 'start_time'
Additional context
The issues seems to be that Tornado does the xsrf checking before the prepare statement is run so the opentelemetry integration doesn't have the chance to initialise the _START_TIME value: https://github.com/open-telemetry/opentelemetry-python-contrib/blob/v1.16.0/instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/__init__.py#L371
As far as I can tell this issue still exists in the latest versions of Tornado and this library.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Read instrumentation/opentelemetry-instrumentation-tornado/src/opentelemetry/instrumentation/tornado/init.py, especially _log_exception and _record_on_finish_metrics near the referenced line. Reproduce a POST without an xsrf header and verify that the failed check logs Tornado's warning without a KeyError for the missing start_time value.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- observability
- Issue type
- Bug
- Difficulty
- 2/5
- Estimated time
- 1-3 hours
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 55/100