Python logger.info() not showing inside applyInPandas (but print() works) — why?

Kirankumarbs
Valued Contributor III

Problem: In Databricks, logs from an external binary (via os.system) show up, but Python logger.info() inside groupBy(...).applyInPandas(...) does not. print(..., flush=True) does show up.

Why: applyInPandas runs your function as a pandas UDF.  That code executes in a Python worker process, which has its own logging configuration or is missing one? For example, I do have root-level configuration like this when the Databricks Workflow/job starts

    log_level = os.getenv("LOG_LEVEL", default="INFO")
    logging.basicConfig(
        level=log_level,
        format="[%(levelname)s] [%(asctime)s] %(message)s",
    )
    logging.getLogger("py4j").setLevel("ERROR")
    logger.info(f"set root log level to {log_level}")

This captures the logs in Spark and workflow level but not in UDFs that are sent to applyInPandas

Well, I have three choices to try out:

  • I don't like(Tried and worked): Use print inside UDFs
  • Somewhat okay(Have to Try): Use an additional handler for the UDF function, like
import logging, sys

def setup_worker_logging(level=logging.INFO):
    logging.basicConfig(
        level=level,
        format='[%(levelname)s] [%(asctime)s] %(message)s',
        handlers=[logging.StreamHandler(sys.stdout)],
        force=True,
    )

# inside applyInPandas function
setup_worker_logging()
logger = logging.getLogger(__name__)
logger.info("visible now")
  • Proper Solution(Have to try): Add logs stream handler directly to the root logging setup that I have, for example, like
    formatting = "[%(levelname)s] [%(asctime)s] %(message)s"

    log_level = os.getenv("LOG_LEVEL", default="INFO")
    logging.basicConfig(level=log_level, format=formatting)

    # Add StreamHandler for stdout output
    stream_handler = logging.StreamHandler(sys.stdout)
    stream_handler.setLevel(logging.INFO)
    formatter = logging.Formatter(formatting)
    stream_handler.setFormatter(formatter)

    # Add handler to root logger
    root_logger = logging.getLogger()
    root_logger.addHandler(stream_handler)

    logging.getLogger("py4j").setLevel("ERROR")
    logger.info(f"set root log level to {log_level}")

Did any of you face such issues? If yes, how did you solve it in your production code?