Python logging issue: some logs are missing from the output

Question

I am trying to understand python logging. I created a project with the following structure.

    .
    ├── config
    │   └── configfile.conf
    ├── mytest
    │   ├── pyvmomi.py
    │   └── s_lib.py
    ├── VM_dep.py
    └── vm_setup.py

VM_dep.py is the the main file:

#! /usr/bin/env python3

import logging
from mytest import pyvmomi
from vm_setup import SetupVM


LOGGER = logging.getLogger(__name__)

TEMP_FOLDER = "."

def main():
    LOGGER.info("Running as user: %s", "John Doe")

    
    pyvmomi.create_vm()
    LOGGER.info("VM deployed successfully, IP address: %s", "10.234.103.222")

    vm_to_setup = SetupVM()
    vm_to_setup.configure_vm()


if __name__ == "__main__":
        main()

Pyvmomi.py file:

from pathlib import Path
import logging
import logging.config

basefolder = Path(__file__).parents[1]
configfile = (basefolder / "config/configfile.conf").resolve()
logging.config.fileConfig(configfile)

# create logger
logger = logging.getLogger('pyvmomi_lib')


def create_vm():
        logger.info("Pyvmomi")
    

vm_setup.py file

#! /usr/bin/env python3

import logging
# from mytest import s_lib  <-- this line is intentionally commented


LOGGER = logging.getLogger(__name__)


class VMSetupException(Exception):
    """Create custom exception type."""


class SetupVM:
    def configure_vm(self):
        LOGGER.info(
                "===================== Setup VM =================================="
            )

s_lib.py

from pathlib import Path
import logging.config


basefolder = Path(__file__).parents[1]
configfile = (basefolder / "config/configfile.conf").resolve()
# print(configfile)
logging.config.fileConfig(configfile)

# create logger
logger = logging.getLogger("opcc_k8s_lib")

logger.info("Hiya LOG LIBRARY")

I noticed a behavior which I am unable to understand. In the vm_setup.py file i have one line commented:

# from mytest import s_lib

As long as this line is commented, the output is as follows:

❯ python3 VM_dep.py
12-26-2021 05:29:31 PM __main__ VM_dep INFO Running as user: John Doe 
12-26-2021 05:29:31 PM pyvmomi_lib pyvmomi INFO Pyvmomi
12-26-2021 05:29:31 PM __main__ VM_dep INFO VM deployed successfully, IP address: 10.234.103.222 
12-26-2021 05:29:31 PM vm_setup vm_setup INFO ===================== Setup VM
    ==================================

But when I uncomment the above line, the output changes to:

❯ python3 VM_dep.py
12-26-2021 05:33:08 PM opcc_k8s_lib s_lib INFO Hiya LOG LIBRARY
12-26-2021 05:33:08 PM __main__ VM_dep INFO Running as user: John Doe
12-26-2021 05:33:08 PM __main__ VM_dep INFO VM deployed successfully, IP address: 10.234.103.222
12-26-2021 05:33:08 PM vm_setup vm_setup INFO ===================== Setup VM ==================================

I am not getting 12-26-2021 05:29:31 PM pyvmomi_lib pyvmomi INFO Pyvmomi this in the output

When we import s_lib in the vm_setup.py file, it runs this logging.config.fileConfig(configfile) again(fist time this is called while importing pyvmomi lib. I believe loading the fileConfig again is causing this issue but I cant understand why. Any help would be appreciated.

Here is the config file:

[loggers]
keys=root,simpleConsoleExample

[handlers]
keys=consoleHandler

[formatters]
keys=simpleConsoleFormatter

[logger_root]
level=INFO
handlers=consoleHandler

[logger_simpleConsoleExample]
level=INFO
handlers=consoleHandler
qualname=simpleConsoleExample
propagate=0

[handler_consoleHandler]
class=StreamHandler
level=INFO
formatter=simpleConsoleFormatter
args=(sys.stdout,)

[formatter_simpleConsoleFormatter]
format=%(asctime)s %(name)s %(module)s %(levelname)s %(message)s
datefmt=%m-%d-%Y %I:%M:%S %p

Answer 1

I fix your issue by adding ,disable_existing_loggers=False) in s_lib.py. The default value is True. Here's a link to Python Doc

from pathlib import Path
import logging.config


basefolder = Path(__file__).parents[1]
configfile = (basefolder / "config/configfile.conf").resolve()
# print(configfile)
logging.config.fileConfig(configfile,disable_existing_loggers=False)

# create logger
logger = logging.getLogger("opcc_k8s_lib")

logger.info("Hiya LOG LIBRARY")

The output that i got on my laptop

nabs@LAPTOP:~/stackoverflow$ python3 VM_dep.py
12-26-2021 02:28:59 PM opcc_k8s_lib s_lib INFO Hiya LOG LIBRARY
12-26-2021 02:28:59 PM __main__ VM_dep INFO Running as user: John Doe
12-26-2021 02:28:59 PM pyvmomi_lib Pyvmomi INFO Pyvmomi
12-26-2021 02:28:59 PM __main__ VM_dep INFO VM deployed successfully, IP address: 10.234.103.222
12-26-2021 02:28:59 PM vm_setup vm_setup INFO ===================== Setup VM ==================================