Version 3.8.0 breaks logging

[alta-atc]

When using version 3.8.0 none of my logging statements make it into the cloud logs.
Reverting to version 3.7.0 fixed this issue.

Example of implementation:

(imports:)

import logging
logging.basicConfig(level=logging.INFO)

(Within function:)
logging.info(f"Deletion Execution completed.")

Please feel free to suggest improved logging implementation if mine is incorrect.

[alta-atc]

Oh,

I should also add that the issue was not confined to logging, my entire function was non-functional. It was as if the cloud event could not be interpreted and converted to a dict. Here is an example of my code. None of the called functions were executed, and the lack of logging made diagnosing the issue very difficult.

I eventually converted my logging state

import logging
logging.basicConfig(level=logging.INFO)

from cloudevents.http import CloudEvent
import functions_framework
from google.events.cloud import firestore
from google.protobuf.json_format import MessageToDict

from library.execution import id
from library.conditions import deleted, created, updated
from library.salesforce import process_salesforce, salesforce_delete

@functions_framework.cloud_event
def fs_users(cloud_event: CloudEvent) -> None:

    try:
        
        data_pb = firestore.DocumentEventData()
        data_pb._pb.ParseFromString(cloud_event.data)
        data = MessageToDict(data_pb._pb)
        logging.info(f"{id()} Data: {data}")

        if deleted(data):
            salesforce_delete(data)
            logging.info(f"{id()} Deletion Execution completed.")
            return

    except Exception as e:
        logging.error(f"{id()} An error has occured in fs_users: {e}", exc_info=True)
        raise e
    
        

[jrmfg]

Sorry for the delay - thanks for raising this issue. This is caused by the LOG_EXECUTION_ID (opt-in) feature - we should fix it, but in the meantime, you can continue to use 3.8.0 without setting that option/environment variable.

I did a simple test to confirm this. If you're using the firebase sdk, this might be set by default for you. We'll look into a fix in ff-python (probably in 3.8.2).

[alta-atc]

Thanks. I'm using v3.7 for the moment while waiting for this fix.

[jrmfg]

I figured out what's going on:

From 3.8.0, if you opt into execution ID logging, a special root logging handler is configured for you, with the default logging level of WARN (30).

logging.basicConfig "does nothing if the root logger already has handlers configured, unless the keyword argument force is set to True." With 3.8.0, there's a handler there now.

I can't figure out an easy way to preserve the old basicConfig functionality with a patch, but there's an easy fix: change:

logging.basicConfig(level=logging.INFO)

to

logging.getLogger().setLevel(logging.INFO)

You'll get the log levels you want, with execution IDs included.

[alta-atc]

Great, thank you @jrmfg Jeremy! I have tested on my end and it works as intended. I will implement this change in my codebase.

Thank you