Logging AutoInstrumentation does not support capturing INFO logs

[kuza55]

Describe your environment
Python 3.10.12

Steps to reproduce

Using the code here, but with a logging.info rather than logging.warning: https://github.com/kuza55/pants_debug_otel/blob/main/src/no_configuration.py

I would expect setting OTEL_PYTHON_LOG_LEVEL=INFO to let me see info logs

What is the expected behavior?

I would expect to use the OTEL_PYTHON_LOG_LEVEL env variable mentioned in the docs to let me see info logs.

What is the actual behavior?

Environment variable has no impact

Additional context

Calling LoggingInstrumentor().instrument(set_logging_format=True, log_level="INFO") can resolve this, but is not compatible with auto-instrumentation, even when the auto-instrumentation env variable is set to false:

$ OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=false opentelemetry-instrument python3 no_configuration.py
Attempting to instrument while already instrumented

[kuza55]

I think this could be resolved by setting the log level here based on an env variable, but I'm not totally sure:

opentelemetry-python/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py

Line 250 in 5986c25

handler = LoggingHandler(level=logging.NOTSET, logger_provider=provider)

I am not clear on why the already instrumented error crops up.

[diaconori]

Basic sample usage even results in the same error as well:

`
from logging import getLogger
import logging

from azure.monitor.opentelemetry import configure_azure_monitor

configure_azure_monitor(
connection_string="",
)

logger = getLogger(name)
logger.setLevel(logging.INFO)
logger.info("test info log")
logger.warning("test warning log")
logger.error("test error log")
`

INFO does not show.

[npuichigo]

any updates here?

[npuichigo]

According to Python doc of debug for example, this function (as well as info(), warning(), error() and critical()) will call basicConfig() if the root logger doesn’t have any handler attached.

handler = LoggingHandler(level=logging.NOTSET, logger_provider=provider) 
logging.getLogger().addHandler(handler)

These lines attach a handler to the root which makes BasicConfig useless

[dhofstetter]

I think this could be resolved by setting the log level here based on an env variable, but I'm not totally sure:

opentelemetry-python/opentelemetry-sdk/src/opentelemetry/sdk/_configuration/__init__.py

Line 250 in 5986c25

handler = LoggingHandler(level=logging.NOTSET, logger_provider=provider)

I am not clear on why the already instrumented error crops up.

Are you sure, @kuza55 ? I tried it out locally but it had no effect for me.

This is definitely an error to be addressed, as this makes auto instrumentation in combination with logs kind of useless :(
If one performs manual config (see here then it works perfectly fine. But this not the preferable solution

BR

[dhofstetter]

If anyone has a suggestion to resolve this issue, I will create a pull request to get changes working

[kuza55]

I poked at this for a second and you're right, changing the code there didn't help.

I had some partial success with other approaches:

Adding logging.getLogger().setLevel(logging.INFO) to the top of my python script caused the log to show up

Setting force=True on this line caused a formatted log line to be printed, but not connected to OTLP: https://github.com/open-telemetry/opentelemetry-python-contrib/blob/37aba928d45713842941c7efc992726a79ea7d8a/instrumentation/opentelemetry-instrumentation-logging/src/opentelemetry/instrumentation/logging/__init__.py#L147C13-L147C32

[dhofstetter]

Ok @kuza55 I guess this is not to be considered as a bug, but more likely to be intended behavior.

The reason is that opentelemetry-instrument only tries to add a LogHandler with an unset log level (see here what this means). So basically there is a new destination where to put logs to (e.g. a otel capable server). Letting level unset means that this handler basically ships every log message it receives to its destination.

The thing to keep in mind is that in fact all loggers (e.g. the ones you create by using logging.getLogger(<name>) can have their own loglevel, specifying which log messages should be omitted. In case of not being explicitly set, the loglevel of a logger is the level set to loggers higher in the hierarchy. Lastly if no log level was ever set, the default is WARNING (see here.

That means as long as the loglevel is not configured for specific loggers or the root logger, only warnings and errors will be handled as expected.

Why does it make sense to separate the loglevel for handlers and loggers?

Because that makes it possible to explicitly define which log messages should transmitted to which destination (e.g. printing debugs in the console, while pushing only errors to a persistent log file).

Why doesn't opentelemetry-instrument doesn't modify the global loglevel?

That's open for discussion, but I think the reason is to ensure that using the automatic instrumentation won't mess up specific configuration for logging in a users application. Meaning that you still have full control which log levels to use in every situation, but ensure that log messages get transmitted to otel whenever possible.

How to resolve

There is an Environment setting that seems to control the loglevel (see here - OTEL_PYTHON_LOG_LEVEL) but it seems that it works only conditionally (see here.

That means, that imho you need to specify at least three ENV variables, to adjust your application log level as expected and start with log exporting

# tell the python contrib repos log instrumentation how to configure your loging env
export OTEL_PYTHON_LOG_LEVEL=info
# -> the latter is required to apply loglevel because it makes instrumentation call logging.basicConfig(...)
export OTEL_PYTHON_LOG_CORRELATION=true
# Tell the opentelmetry-instrument process to enable log exporting (adding appropriate handlers)
export OTEL_PYTHON_LOGGING_AUTO_INSTRUMENTATION_ENABLED=true

Would be nice if some maintainers here can put light in the dark, and help us understanding better what is exactly going on.

Edit:

Probably the error is here, but I'm not sure what the side effect of using force=True is

logging.basicConfig(format=log_format, level=log_level)   # consider adding force=True here

Edit2

force=Trueis a bad idea, the Otel handler then gets removed. That means basically the format and log level of. the app are then are expected, but nothing gets sent to otel anymore ;)

[dhofstetter]

The pull request that addresses - indirectly - this issue , and would resolve it is already there (see here

[lzchen]

@dhofstetter

Thanks so much for looking into this and apologize for the delayed response.

Why doesn't opentelemetry-instrument doesn't modify the global loglevel?
That's open for discussion, but I think the reason is to ensure that using the automatic instrumentation won't mess up specific configuration for logging in a users application. Meaning that you still have full control which log levels to use in every situation, but ensure that log messages get transmitted to otel whenever possible.

This is correct, we want to be as non-intrusive as possible to the configuration settings of the user's application.

That means, that imho you need to specify at least three ENV variables, to adjust your application log level as expected and start with log exporting

This seems to be the case today in terms of being able to configure log format and log level. The reason there is such an extensive amount of configuration needed is we do not want to have default behavior override any of the user's configuration without their knowledge (or even worse, in the cases in which they cannot change the config).

This means the logging instrumentation is indeed behaving as it was intended to as you have outlined above. Everything else follows the standard Python logging library practices for handlers and loggers.

With that being said, maybe there is something that can be done on the AUTOINSTRUMENTATION side of things. We already allow configuration of other OpenTelemetry components (mostly with env vars). Perhaps the better change would be to allow more robust and flexible configuration of the automatically instantiated LoggingHandler that is initialized during auto-instrumentation. Another thing to note is that autoinstrumentation with the LoggingHandler does not need the logging instrumentation, but perhaps we can share the same env var configurations.

I also see that you have a pr open. What specifically does this pr solve? Does it address the original issue at hand?

[dhofstetter]

@lzchen
The pull request resolves one major issue with current logging instrumentation:
The fact that the logging auto instrumentation won't capture the logs as expected. The reason lies in the way auto instrumentation is initialized (whenever there is only one other piece of code that is configuring pyhtons logging stack, then the logging instrumentation won't capture logs with the LOG_LEVEL a user wanted to have).

The probably best description what is not working at the moment ist: open-telemetry/opentelemetry-python-contrib#2346

Feel free to get back to me with further questions

[lzchen]

@dhofstetter

If your pr is simply to enhance the logging instrumentation, I am fine with it. In the future we may want to enhance autoinstrumentation as well to allow for configuration of the root logger for users that are NOT using the logging instrumentation. Not sure if we want to use the same env vars but we may have to deal with potential conflicts in the future.

Created a tracking issue: #4034