open-telemetry / open-telemetry/opentelemetry-python-contrib

Tornado integration raises `KeyError` when xsrf check fails

Open
#2,006 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug
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_cookies enabled
  • Make a POST request to an endpoint without a xsrf header
  • Check server logs to see KeyError exception 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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.