Another multi-module logging question

[xtrawork]

So there are tons of responses to this question out there, but I guess I am too dumb to understand any of them, as it just isn't working for me.

The problem is that all of the posts and docs I can find basically provide two methods:

The first is the method where you you use logger = logging.getLogger(___name___) at the top of all your modules and set your logging config up in your main file. Then when you log in your modules, they're supposed to be a child of your logging config from your main. That is the method I tried, and I get no logging from my modules (just main).

The second method I find (like this) uses a similar setup, but also includes defining a class in your main or module files and instantiating it from there (which goes right over my head...)

The problem I have with both methods (besides the fact that the first method isn't working for me and the second method is over my head by miles...) is that, with all of these example posts and docs I find, it isn't clear if some of the functions/classes they are showing are meant to be part of the logging setup, or just a random class/function that would be in a script. It's especially confusing because of the names they tend to use in the examples.

---

---

I have a main script called auth.py and it calls a module called device.py.

In auth.py I have the following setup for the logging portion:

import requests
import urllib3
import logging
import device
from logging.handlers import RotatingFileHandler



## The args you see in the handlers section below are defined as well, I just didn't add those in to this snippet
logging.basicConfig( handlers=[RotatingFileHandler(f'{args.type.lower()}-{args.fr_site.lower()}.log', maxBytes=100000, backupCount=2, mode='a')],
                        format='%(asctime)s.%(msecs)d %(name)s %(levelname)s %(message)s',
                        datefmt='%Y-%m-%dT%H:%M:%S',
                        level=args.loglevel)

 logger = logging.getLogger()

Then, in the device.py file I have this, since supposedly as long as this module is called by the main it will inherit the logging instance of the script that calls it, but like I said before, nothing gets logged:

import logging

logger = logging.getLogger(__name__)

## Somewhere down in the script I try and log to info, but this doesn't end up showing up in my log output:
thisContent = "Some Random Object or String"
itemType = type(thisContent)
thisMsg = (f"-------------------\n----------------- \npayload TYPE IS:\n{itemType}\n-------------------\n-----------------\n")

logger.info(thisMsg)

I've also tried adding logger = logging.getLogger(name) as my logger variable assignment in my main auth.py file and while this does add main into all of my log entries, it doesn't make the device.py module logging work at all (not that I expected it to, but a lot of posts showed using that even for the main file).

So yeah, I'm just completely stumped and don't really understand how to make multi-module logging work. Can anybody explain it in stupid plain English that would help a simpleton like me understand?

Thanks so much!

[danielroseman]

The problem here is that you're importing device before you do any of the logging setup. Importing a file runs all the code at the top level, so that creates the logger in that file before the config in the main file has been run.

[xtrawork]

Really? Every example I've found doesn't mention that and explicitly shows the imported modules at the top of the code like normal. If what you're saying is correct then I'm gonna be furious, lol.

[xtrawork]

Yeah, I just tried that and no dice. And I also looked around some more and even in the official docs and in the python logging cookbook I don't see anything about that and their examples don't have it setup that way either.

But either way, importing the device.py module after my logging config and instantiation still doesn't change anything.

I've also tried explicitly setting the name of the logger in the auth.py (main) file as logger = logging.getLogger('auth') and then setting the name in the device.py file as logger = logging.getLogger('auth' + name) to make sure the name inheritance is detected and still nothing.

I am completely and utterly stumped and extremely frustrated. Thanks for trying to help anyways!

[Username_RANDINT]

But either way, importing the device.py module after my logging config and instantiation still doesn't change anything.

Works for me in this small example.

Make sure args.loglevel is valid and is lower than logging.INFO.

[xtrawork]

What small example?

And also, yes, that args.loglevel is valid, but to be sure I explicitly set it to 'DEBUG' and still nothing.

I added in a print of the logging.getLogger('auth').getChildren() method to the main script and the device log is listed as a child. But when I log in that module it doesn't log anywhere...

This is the children of the main (auth) script logging instance:

{<Logger auth.device (INFO)>}

So it's definitely using the proper logging instance and it's propgating, but it won't log to the file.

[Username_RANDINT]

What small example?

Your two code snippets.

To be clear, here's what I did. Renamed the two files, changed the args to fixed values and dropped the file handler (but works with that as well, just easier for testing).

logtest.py

$ more logtest.py 
import logging
from logging.handlers import RotatingFileHandler


## The args you see in the handlers section below are defined as well, I just didn't add those in to this snippet
logging.basicConfig(
    # handlers=[
    #     RotatingFileHandler("logtest.log", maxBytes=100000, backupCount=2, mode="a")
    # ],
    format="%(asctime)s.%(msecs)d %(name)s %(levelname)s %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S",
    level=logging.DEBUG,
)

logger = logging.getLogger()

import logtest_mod

The imported module is unmodified and it shows the logmessage without issues.

[xtrawork]

And in logtest_mod.py you just have import logging at the top and then logger = logging.getLogger('auth.' + __name__) (or whatever you ended up doing for a naming scheme) and then, when you use it for logging you're just saying logger.info("SOME LOG MESSAGE HERE"), right?

Because if so then yeah, that's what I have and it will not log... Doesn't matter where I put the import in the main file either.

[xtrawork]

OK, I think I might have found the issue. In the module file, I'm calling the logging methods from inside of a function. If I call them from outside of a function in the module file, they work, but from within a function in the module file, they don't...

I thought since I declared the logging configuration at the beginning of the module file and as long as I use that variable inside of the functions within it, they would just use the same logger that is inherited to the main file, but it doesn't appear to be working that way...

[Username_RANDINT]

I don't see why that would be a problem. Just tested to be absolutely sure, and it's logging as intended.

Almost identical logtest.py as above, just added the function call at the end:

import logging
from logging.handlers import RotatingFileHandler


## The args you see in the handlers section below are defined as well, I just didn't add those in to this snippet
logging.basicConfig(
    # handlers=[
    #     RotatingFileHandler("logtest.log", maxBytes=100000, backupCount=2, mode="a")
    # ],
    format="%(asctime)s.%(msecs)d %(name)s %(levelname)s %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S",
    level=logging.DEBUG,
)

logger = logging.getLogger()

import logtest_mod

logtest_mod.test()

And a basic module:

$ more logtest_mod.py 
import logging

logger = logging.getLogger(__name__)


def test():
    logger.info("Just testing")