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

LoggingInstrumentor and AWS Lambda Python RIC are duplicating logs

Open
#2,417 0 comments 4 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

I'm not sure if this fits under Bug or Feature Request.

Describe your environment
AWS Lambda function with Otel Python lambda layer, Python 3.8 in x86_64.

Steps to reproduce
I have an AWS Lambda function equipped with the OpenTelemetry Python lambda layer 0.5.0 and have set the env var OTEL_PYTHON_LOG_CORRELATION: true. The function calls logger.getLogger(__name__) and logger.warning(<msg>), without adding any handlers. Invocation results in duplicate logs, for example:

2024-04-12 23:44:40,808 WARNING [root] [lambda_function.py:32] [trace_id=XXXX span_id=XXXX resource.service.name=lambda_function trace_sampled=XX] - My log inside lambda

[WARNING] 2024-04-12T23:44:40.808Z XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX My log inside lambda

The first log is what I expect for OTEL_PYTHON_LOG_CORRELATION (I've just X'd out the context IDs). The second log has a different format where the long ID is the AWS function invocation request ID. This comes from the aws-lambda-python-runtime-interface-client: this formatting by _setup_logging and always with a Lambda-specific handler. The AWS logging does not seem to be configurable.

What is the expected behavior?
Ideally: it would be great if there was a single set of logs that had the best of both kinds, something like:

2024-04-12 23:44:40,808 WARNING [root] [lambda_function.py:32] [request_id=XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX] [trace_id=XXXX span_id=XXXX resource.service.name=lambda_function trace_sampled=XX] - My log inside lambda

What is the actual behavior?
Duplicate logs for the same messages, in 2 different formats.

Additional context

This might relate to how LoggingInstrumentor does a single logging.basicConfig call as others have already pointed out:

Maybe the explicit setting of handler formats in this PR could add span context fields to the lambda runtime-set logging handler, by adaptor or filter: https://github.com/open-telemetry/opentelemetry-python-contrib/pull/1939

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

Reproduce the duplicate output with the AWS Lambda Python layer and OTEL_PYTHON_LOG_CORRELATION enabled. Read LoggingInstrumentor's logging.basicConfig behavior alongside awslambdaric/bootstrap.py lines 444-455 and 480, and review PR 1939. Done means one log entry retains both the Lambda request ID and OpenTelemetry context without duplicate messages.

Written by the indexing model from the issue text.

Assessment

Tech stack
aws, python
Domain
cloud, observability
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.