logger.error() produces traces with severityLevel 1

[matthiasschuurmans]

Is your question related to a specific version? If so, please specify:

Python version 3.10 azure-functions 1.17.0 azure-functions-durable 1.2.8

What binding does your question apply to, if any? (e.g. Blob Trigger, Event Hub Binding, etc)

orchestrationTrigger and activityTrigger

Question

Hi, I have a Python (Durable) Function App, which produces logging that gets sent to Application Insights via providing APPINSIGHTS_INSTRUMENTATIONKEY. I can query the logs in the ADX traces table. Normally, logging produced via logger.error() ends up in that table with a severityLevel of 3, but sometimes, it also ends up with severityLevel 1. As a simple test, I just put logger.error('Test test 1 2 3') in my orchestrator and run it locally, and the logs end up like

I am having a hard time figuring out why. I tried a lot of googling, documentation reading and code searching, but cannot find out where exactly in the azure functions code the logs get sent to App Insights. Can anyone help me out? Apologies if this is not the right place to ask or I overlooked an answer somewhere. Thanks!

[bhagyshricompany]

Thanks for reporting .pls share the fun invocation id timestamp region.etc.Thanks

[matthiasschuurmans]

@bhagyshricompany As mentioned, this is just from a local run of the orchestrator via func host start with APPINSIGHTS_INSTRUMENTATIONKEY in my local.settings.json.

Region West Europe

Additional info: customDimensions {"LogLevel":"Information","Category":"Host.Function.Console","prop__{OriginalFormat}":"2023-11-21 10:06:00,293 - ERROR - Test test 1 2 3, invocation ID 91d104d7-5f55-4c27-97bf-f1d091d8d3d7","ProcessId":"19812","HostInstanceId":"4c934758-d748-49e6-93db-80eb76af0c8f"} sdkVersion azurefunctionscoretools: 4.0.5148

customDimensions {"Category":"Host.Function.Console","HostInstanceId":"4c934758-d748-49e6-93db-80eb76af0c8f","ProcessId":"19812","LogLevel":"Information","prop__{OriginalFormat}":"2023-11-21 10:05:00,464 - ERROR - Test test 1 2 3, invocation ID a3145a94-0921-461b-8da3-9aa232953dd1"} sdkVersion azurefunctionscoretools: 4.0.5148

[bhagyshricompany]

@gavin-aguiar pls comment and vaildate.Thanks

[hallvictoria]

Hi @matthiasschuurmans, thanks for your patience.

I tried to repro this, but I didn't run into this issue for both running locally or deployed. I used the logging module and called logging.error('Test test 1 2 3').

A couple follow-up questions:

• What programming model are you using?
• Are you creating a new logger or using the root logger?
• Could you provide your function app code?

[matthiasschuurmans]

Hi @hallvictoria , thanks for your reply. Your comment gave a hint about where the problem is: I make my own logger, with this function:

def get_logger(
    name: str,
    propagate: bool = False,
    add_stream_handler: bool = True,
    level: Union[str, int] = logging.INFO,
    format: str = '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
) -> logging.Logger:
    """
    Function to get a logger

    Parameters
    ----------
    name: str
        The name of the logger. In normal circumstances, this should be __name__ of the caller of the function
    propagate: bool
        Set propagate to this value
    add_stream_handler: bool
        Whether to add a stream handler to this logger
    level: int
        What level to make the logger (and handler(s) if applicable)
    format: str
        The format of the messages of this logger. Only used if any handlers are added

    Returns
    -------
    logging.Logger
        A logger with the appropriate handlers and formatting
    """
    if level not in [logging.NOTSET, logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL]:
        level = logging.INFO
        logger.warning(f'Log level {level} not supported, setting to logging.INFO')

    logger = logging.getLogger(name)
    logger.setLevel(level)
    logger.propagate = propagate
    formatter = logging.Formatter(format)
    # First clear handlers in case the user uses the same name but wants to have different handlers
    logger.handlers.clear()

    if add_stream_handler:
        ch = logging.StreamHandler(stream=sys.stdout)
        ch.setLevel(level)
        ch.setFormatter(formatter)
        logger.addHandler(ch)

    return logger

What I'm beginning to believe, is that Azure Python worker configure their own logger somehow. The simple case, not running in an Azure Function, is this:

if __name__ == '__main__':
    python_logger = logging.getLogger('python_logger')
    ds_logger = get_logger('ds_logger')
    python_logger.info('Info python logger')
    python_logger.error('Error python logger')
    ds_logger.info('Info DS logger')
    ds_logger.error('Error DS logger')

Output (in VS code) gives

This makes sense: python_logger is a simple logger that gets no handlers, no set level, and so defaults to logging.WARNING and sys.stderr from the root logger and just outputs Error python logger. My own function gets a handler, doesn't propagate, writes to sys.stdout and has a format, and thus shows both Info DS logger and Error DS logger.

But when I run the same in an Azure Function locally, I get this output:

Firstly, we see that, from my logger, both the Info... and Error... are blue (instead of white), which is already an indication that they're treated as the same.

But what's most interesting, is that I see both Info python logger in blue, and Error python logger in red! This is different from default python logger behavior as showcased above, because we see info() as well. This then also seems to be what determines the severityLevel in Application Insights table: blue logging gets severityLevel 1, and red logging gets severityLevel 3.

My guess is that the severityLevel might be related to the stream of the StreamHandler? Since I write to sys.stdout, everything becomes blue, and errors also get severityLevel 1?

[hallvictoria]

Ah, I see. The worker does configure its own logger using a GRPC handler. Creating a new logger means that the new logger won't have that handler and won't output to App Insights in the same manner. Those logs are treated essentially as console logs.

A workaround for your case would be to use stderr as your stream handler instead of stdout. (i.e. ch = logging.StreamHandler(stream=sys.stderr)).

In general though, we recommend using the logging module for logs sent to AI instead of creating a new logger. The root logger here is set up in the worker to have the correct handler.

Here's some additional documentation: https://learn.microsoft.com/en-us/azure/developer/python/sdk/azure-sdk-logging

[matthiasschuurmans]

@hallvictoria Ok, thanks for confirming. If I understand correctly, you rely on user's loggers to propagate? So that the messages end up (at least) being handled by the root logger, which has that handler you describe? I'll have to think about how to set it up, because I also want to see logging from my own underlying libraries, and I also have non Azure-Function stuff that relies on this logger.

If I change the stream to sys.stderr, I imagine normal info/warning logging will also have severityLevel 3? Does the handler you describe somehow decide the stream based on the function call? (info(), warning(), error() etc)

[hallvictoria]

Yes, that's true. One other workaround in this case would be to set propagate=True. Keeping the custom handler would create duplicate logs when running the function (like below), but it would enable the logs to pass through the worker and have their severity level be set accordingly.

When propagate=False, the logs aren't actually recognized and sent through our worker. They're treated as console logs by the host.

We currently only support logging through root logger, not with custom loggers. Adding a different handler is allowed but propagate must be set to True so that the logs can be received by the worker and displayed correctly in App Insights.

[matthiasschuurmans]

@hallvictoria I solved the problem by changing to sys.stderr as the stream. info(), warning() and error() all get the appropriate severityLevel now. Thank you for your help!

It surprised me though, I figured since all is written to sys.stderr now, all would be severityLevel 3. Can you explain how that now works from Azure workers perspective? The handler you add to the root logger is not used since propagate is still False. How exactly does the severityLevel gets set?

[hallvictoria]

The worker doesn't recognize logs that aren't sent through the root logger, which is why we recommend using the root or extending it. We don't take any control in setting the severity levels in those cases -- the stream is just captured by the host and returned. I'm not too familiar with how that situation works -- my best guess is that there's an underlying difference between the system stdout and stderr streams that allows for the severity level to be captured appropriately.

[matthiasschuurmans]

@hallvictoria Alright thanks again, closing this issue :)