Verbose logs are emitted at INFO level when telemetry is sent to Application Insights

[shingotoda]

• Package Name: azure-monitor-opentelemetry
• Package Version: 1.1.1
• Operating System: MacOS, Debian (bullseye)
• Python Version: 3.11

Describe the bug
I am writing Django app and implementing instrumentation with azure-monitor-opentelemetry. I set it up to have a named logger and set log level to WARNING. The following is the code to do this.

    from azure.monitor.opentelemetry import configure_azure_monitor
    configure_azure_monitor(logger_name='myapp')
    logger = logging.getLogger('myapp')
    logger.setLevel(logging.WARNING)

But I see the following message is emitted to stdout then results in being ingested to Log Analytics workspace, looks like this is a HTTP request log to send telemetry to application insights.

INFO Request URL: 'https://japaneast-1.in.applicationinsights.azure.com//v2.1/track'
Request method: 'POST'
Request headers:
    'Content-Type': 'application/json'
    'Content-Length': '893'
    'Accept': 'application/json'
    'x-ms-client-request-id': 'e164e506-9b7e-11ee-94dd-92dfbd47e697'
    'User-Agent': 'azsdk-python-azuremonitorclient/unknown Python/3.11.7 (Linux-5.15.0-1052-azure-x86_64-with-glibc2.31)'
A body is sent with the request
INFO Response status: 200
Response headers:
    'Content-Type': 'application/json; charset=utf-8'
    'Server': 'Microsoft-HTTPAPI/2.0'
    'Strict-Transport-Security': 'REDACTED'
    'X-Content-Type-Options': 'REDACTED'
    'Date': 'Fri, 15 Dec 2023 19:19:33 GMT'
    'Content-Length': '49'
INFO Transmission succeeded: Item received: 1. Items accepted: 1

After I debugged with pdb, it looks that this line is processed when telemetry is sent to Application Insights.

https://github.com/Azure/azure-sdk-for-python/blob/d8bcdc57c0287dca6b6bdc192c9255616c4f36d3/sdk/core/azure-core/azure/core/pipeline/policies/_universal.py#L509C1-L512C23

            if http_request.body:
                log_string += "\nA body is sent with the request"
                logger.info(log_string)
                return

This logger has root as parent.

(Pdb) logger.name
'azure.core.pipeline.policies.http_logging_policy'
(Pdb) logger.parent
<RootLogger root (INFO)>

I would personally think that since this message is too verbose from application perspective and it takes root logger, this should call logger.debug() instead of info() like other lines of this code like this.

azure-sdk-for-python/sdk/core/azure-core/azure/core/pipeline/policies/_universal.py

Line 324 in d8bcdc5

_LOGGER.debug(log_string)

Though it, I'm new to this codebase so my assumption might be wrong. Please let me know if there is a workaround to suppress this message.

Expected behavior
HTTP log is too verbose as it emits logs every time telemetry is sent to application insights. This should be debug log.

[github-actions]

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @azmonapplicationinsights @jeremydvoss @lzchen.

[lzchen]

Could you paste/give a link to your django app? I am running your instrumented code as a standalone Python app and cannot replicate the behavior you are experiencing above:

configure_azure_monitor(
    logger_name="myapp",
)

logger = logging.getLogger('myapp')
logger.setLevel(logging.WARNING)

logger.warning("test log")

I only see test log appear in AppInsights and nothing printed to the console.

[shingotoda]

@lzchen Could you set root logger's log level to INFO? Here is my snippet of logging configuration.

# Logger
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "simple": {
            "format": "{levelname} {message}",
            "style": "{",
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "simple",
            "stream": sys.stdout
        }
    },
    "root": {
        "handlers": ["console"],
        "level": 'INFO'
    }
}

Our app uses root logger for most of logging so INFO level is enabled.

[lzchen]

@shingotoda

I am able to replicate the logs showing up printed to stdout but these logs are not captured and sent to App Insights. Please confirm whether these logs are simply showing up in console (which is expected behavior) or is it doing that AND being collected as telemetry and sent to your AppInsights instance?

[github-actions]

Hi @shingotoda. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

[shingotoda]

@lzchen Great to hear that you replicated the log and it is correct that the log message isn't sent to Application Insights. But the issue is that our application is running on AKS and Container Insights will capture stdout and stderr stream to send messages to Log Analytics. If we use root logger that enables INFO level logs then all these verbose logs will be sent to Log Analytics which will result in incurring log ingestion cost.

I want to have this logs emitted from this library at Debug level.

Does that make sense?

[lzchen]

@shingotoda

This is a separate issue and unrelated to Application Insights then. If you set the root logger level to INFO, this will capture all the logs sent from your python application, including those sent by the telemetry SDK itself (those are all prefixed with the namespace azure.. It is advised to use named loggers in your application instead of setting logging settings directly on the root logger. For the issue of your stdout and stderr streams being send to Log Analytics, this does not seem to be an AppInsights SDK issue, I suggest changing how you are setting up your Python loggers (have dedicated, namespaced loggers for ones that you want to capture telemetry for, any ones you want to capture stdout messages for), and then approach someone from AKS/container insights to see if you can turn off automatic capture of stdout/stderr.

[shingotoda]

@lzchen Thank you for the reply. I have already used a named logger for Application Insights telemetry as you suggested in #33456. Its logger name is myapp as described in the Describe the bug section at the top of this thread.

But also, root logger is used for application log. My intent is to have separate loggers for Application Insights telemetry and application log so that telemetry will be sent to Application Insights and application log is sent to container log table in Log Analytics.

Since pieces of the SDK code use root logger to emit the message in (at least my) issue at INFO level, it's displayed in stdout then sent to Log Analytics. Capturing all stdout/stderr message worked OK in our app. If the SDK is installed, the message is shown every time our app receives a HTTP request so it produces a lot of noise in application log.

My question is if we could justify the INFO level log in HttpLoggingPolicy class like this to be set to DEBUG. My goal is to suppress this message.

[lzchen]

My question is if we could justify the INFO level log in HttpLoggingPolicy class like this to be set to DEBUG. My goal is to suppress this message.

This is most likely by design since you are configuring the root logger and that will affect all python logging. The log messages you see are mostly related to HttpLoggingPolicy which is part of azure core, not the monitoring sdk. However if you really need to use the root logger, there might be a way to already configure the loggers sent with azure core. @pvaneck is there a way to configure the verbose logging messages sent from azure.core today?

Secondly, even if the above were to be implemented, you will still see the

INFO Transmission succeeded: Item received: 1. Items accepted: 1, which IS sent by the monitoring SDK. Is this amount of logs an okay amount for you? It appears for the same reasoning as above, you are configuring the root logger to send info logs and the monitoring SDK sends INFO level logs when an item is successfully sent.

[shingotoda]

@lzchen

This is most likely by design since you are configuring the root logger and that will affect all python logging. The log messages you see are mostly related to HttpLoggingPolicy which is part of azure core, not the monitoring sdk. However if you really need to use the root logger, there might be a way to already configure the loggers sent with azure core. @pvaneck is there a way to configure the verbose logging messages sent from azure.core today?

I want to use the root logger and stop the message.

INFO Transmission succeeded: Item received: 1. Items accepted: 1, which IS sent by the monitoring SDK. Is this amount of logs an okay amount for you? It appears for the same reasoning as above, you are configuring the root logger to send info logs and the monitoring SDK sends INFO level logs when an item is successfully sent.

I want to also suppress this message as well. I revised it to use debug in my local environment. This worked as I expected,.

[MahrRah]

Is there any update on this?
We are seeing similar issues. When setting the log level to INFO we get the Transmission succeeded: Item received: logs send to AppInsights and have currently no way to supress them, which causes a for us unnecessary high load of trace data in our tables.

[lzchen]

@MahrRah

See this comment

[trumhemcut]

Is there any update on this? We are seeing similar issues. When setting the log level to INFO we get the Transmission succeeded: Item received: logs send to AppInsights and have currently no way to supress them, which causes a for us unnecessary high load of trace data in our tables.

I face the same issue, when will it be fixed pls?

[trumhemcut]

@shingotoda

This is a separate issue and unrelated to Application Insights then. If you set the root logger level to INFO, this will capture all the logs sent from your python application, including those sent by the telemetry SDK itself (those are all prefixed with the namespace azure.. It is advised to use named loggers in your application instead of setting logging settings directly on the root logger. For the issue of your stdout and stderr streams being send to Log Analytics, this does not seem to be an AppInsights SDK issue, I suggest changing how you are setting up your Python loggers (have dedicated, namespaced loggers for ones that you want to capture telemetry for, any ones you want to capture stdout messages for), and then approach someone from AKS/container insights to see if you can turn off automatic capture of stdout/stderr.

I've set namespace is azure, but I would like to log my INFO to AppInsights, how to do it without pushing unnecessary INFO Transmission succeeded: Item received to AppInsights?

[trumhemcut]

I have to fix temporarily by this config:

        configure_azure_monitor(connection_string=settings.APPLICATIONINSIGHTS_CONNECTION_STRING)
        
        # This is just to fix the issue https://github.com/Azure/azure-sdk-for-python/issues/33623
        logging.getLogger('azure.monitor.opentelemetry.exporter.export._base').setLevel(logging.WARNING)
        logging.getLogger('azure.core.pipeline.policies.http_logging_policy').setLevel(logging.WARNING)