Tornado: trace and span ID logging not working when raising HTTPErrors

Describe your environment

• Platform Linux
• Python 3.9.1
• Tornado 6.1
• OTel API + SDK + exporter 1.11.0
• OTel Tornado + logging instrumentation 0.30b0

Steps to reproduce

When raising a Tornado HTTPError, there are no trace or span IDs in the logs. Traces end up in the collector just fine.

I can reproduce the issue with the following example by using these environment variables:

• OTEL_EXPORTER_OTLP_TRACES_ENDPOINT=http://localhost:4317
• OTEL_PYTHON_LOG_CORRELATION=true
• OTEL_TRACES_EXPORTER=otlp

import tornado.ioloop
import tornado.web

from opentelemetry import trace
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.logging import LoggingInstrumentor
from opentelemetry.instrumentation.tornado import TornadoInstrumentor
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor


class MainHandler(tornado.web.RequestHandler):
    def get(self):
        self.set_status(200)

class ErrorHandler(tornado.web.RequestHandler):
    def get(self):
        raise tornado.web.HTTPError(401, "Foo")

def make_app():
    return tornado.web.Application([
        (r"/", MainHandler),
        (r"/error", ErrorHandler),
    ])

if __name__ == "__main__":

    provider = TracerProvider()
    exporter = OTLPSpanExporter()
    processor = BatchSpanProcessor(exporter)
    provider.add_span_processor(processor)
    trace.set_tracer_provider(provider)

    LoggingInstrumentor().instrument()
    TornadoInstrumentor().instrument()

    app = make_app()
    app.listen(8888)
    tornado.ioloop.IOLoop.current().start()

What is the expected behavior?

Logs should include the trace and span IDs for all requests.

What is the actual behavior?

Logs have the IDs for successful requests:

2022-04-20 09:03:37,487 INFO [tornado.access] [web.py:2239] [trace_id=2761d8e6686b29ae94006170d4c2cc1d span_id=e06216539c3d3f8b resource.service.name=unknown_service] - 200 GET / (127.0.0.1) 5.02ms

For anything that raises HTTPError, we get no IDs:

2022-04-20 09:03:45,119 WARNING [tornado.general] [web.py:1787] [trace_id=0 span_id=0 resource.service.name=unknown_service] - 401 GET /error (127.0.0.1): Foo
2022-04-20 09:03:45,120 WARNING [tornado.access] [web.py:2239] [trace_id=0 span_id=0 resource.service.name=unknown_service] - 401 GET /error (127.0.0.1) 5.53ms

Additional context

I worked around the problem to get one of the log lines show the IDs by overriding the Tornado _handle_request_exception private method in my base handler class to set the current span as an attribute, and then later on in the log method checking if there is a span attribute and logging the line within the span's context. I haven't yet figured out a way to show the IDs on both of the log lines produced, though.

Looks like all exceptions suffer from the same issues, not just HTTPError. By doing a division by zero in the error handler, I get the exception logged and added to the trace, but ID's at not present in the logs.

Start by reproducing the example with TornadoInstrumentor and LoggingInstrumentor, then inspect the request exception path around Tornado's _handle_request_exception and the logging calls that produce the general and access lines. Done means requests that raise HTTPError or other exceptions retain their trace and span IDs in both log lines, while successful requests continue to work.