Maya and logging hierarchy

[vince touache]

hi all, 

I'm finally trying to work clean with the logging lib, but there are still a few things I can't figure out, even after reading previous topics here and elsewhere.

Everything about Handlers and Formatters kinda make sense, I'm not too concerned about it. Instead, what bugs me is more the parent/child relationship with the root.

(for all my experiments, I'm using pymel's tool to vizualise my logging hierarchy)

What do I want to achieve:

I' like to create one main logger, under the root, when initializing my program, and then mimic my project hierarchy in the logger, so that I have full control on the entire verbosity.

So if my program looks like this:

my_app

|__ child01.py

|__ child02.py

I'd like to have something like this in my loggers:

root (created by Maya)

|__ my_app

    |__ my_app.child01

    |__ my_app.child02

However, when trying to do this, there are many things that don't make sense to me:

1. If I look at PyMel, they are using the "children" property, and when I use it in maya, it sometimes works, sometimes not. I can't understand the logic. Looks like the children attribute is created only when there are children, which sounds like a weird design to me. Am I missing something? Furthermore, even though I can use logging.root.children in maya, this simply does not seem to exist outside of maya (python2 or python3), even though the logging.__version__ is the same

ex:

mainLog = logging.getLogger("my_tool")  # meant to be the parent for my entire app

child1 = logging.getLogger("my_tool.child1")  # similar to mainLog.getChild("child1"), correct?

child1.parent.name

>>> my_tool

hasattr(mainLog, "children")

>>> False

wtf???? child1's parent is mainLog, but mainLog doesn't have a child?

2. How is it possible that I have twice the same logger, at the same level? If I run several time my tool, I end up with root.my_logger being here twice or more. I thought the whole point of the logging was to behave like a singleton, and logging.getLogger("my_app") would return me the existing logger instance for my_app, if exists, create it otherwise. Instead, I end up with 2 loggers named the same, and apparently at the same level of hierarchy:

for x in logging.root.children:

    print x.name

    >>> will return me several time the same name. If I want to do it on purpose, I can't

3. Is there, somewhere, I page I can look at, with a clean logging system?

I didn't detail too much all the examples or put screenshots because this email is long enough already, but I can provide totally more info if needed ofc =]

If anyone has an explanation for me, that' would be reeeeally appreciated!

Thank you so much !

[Justin Israel]

I'm not fully clear on why this has gotten so complex in your application, but usually I would expect for the main to establish the highest level logger and all the library modules to create their own logger and use just their own  logger instance. Then the top level logger can set up the handlers and formatters, while the child loggers don't have to be aware of that concept and their log messages just bubble up to handlers. 

When naming the loggers it would also be common to use __name__ to automatically establish the child relationship from their import paths. But I am not sure how you are intending to use getChild in your logic? Does your main need to be able to directly access these child loggers for some reason? 

As for why you are seeing multiple copies of loggers, that is not supposed to happen. Are you using the reload() function somewhere which can lead to duplicate execution of code in a shared Maya Python interpreter? Is it a problem thag you are appending handlers more than once to the same loggers? 

--
You received this message because you are subscribed to the Google Groups "Python Programming for Autodesk Maya" group.
To unsubscribe from this group and stop receiving emails from it, send an email to python_inside_m...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/python_inside_maya/79b453f8-f9a8-4066-b0d7-a03cfcb0ffe8n%40googlegroups.com.

[vince touache]

Thanks for your answer

- using __name__ is the basic workflow I was using before. But I want to handle it differently now, with potentially a specific handler per logger. Also, __name__ will return something like gui.mainWindow, which will be parented directly to the root. Instead, I'd like to have a logger named {my_app}, parented to the root. and all the loggers of my app parented to this main. Like if I was doing logging.getLogger("my_app" + __name__)

- As far as I can tell, log.getLogger("myapp").getChild("child01)" is exactly the same than logging.getLogger("myapp.child01"). And yes, the need is to be able to access these child loggers, for 2 reasons: the first one is simply printing stuff with this logger, and the second one is simply attach different handlers, with potentially different formatters.

- I definitely see multiple copies of loggers. And I do not use any reload in my entire program. I first thought the pymel logging menu was a bit buggy and was returning me wrong info, but when I check the hierarchy myself, I can see 2 different loggers, with the same name, at the same level. Any idea, other than the reload, of why it happens?

Would it help if I post some screenshots?

thanks

[Justin Israel]

On Mon, Sep 7, 2020 at 8:28 AM vince touache <fruit...@gmail.com> wrote:

Thanks for your answer

- using __name__ is the basic workflow I was using before. But I want to handle it differently now, with potentially a specific handler per logger. Also, __name__ will return something like gui.mainWindow, which will be parented directly to the root. Instead, I'd like to have a logger named {my_app}, parented to the root. and all the loggers of my app parented to this main. Like if I was doing logging.getLogger("my_app" + __name__)

- As far as I can tell, log.getLogger("myapp").getChild("child01)" is exactly the same than logging.getLogger("myapp.child01"). And yes, the need is to be able to access these child loggers, for 2 reasons: the first one is simply printing stuff with this logger, and the second one is simply attach different handlers, with potentially different formatters.

So then maybe you just need a log.py module, or in your __init__.py, to establish your application logger, and then the rest of the modules can access the global LOGGER to create a child or call something like myApp.getLogger()

 

- I definitely see multiple copies of loggers. And I do not use any reload in my entire program. I first thought the pymel logging menu was a bit buggy and was returning me wrong info, but when I check the hierarchy myself, I can see 2 different loggers, with the same name, at the same level. Any idea, other than the reload, of why it happens?

Yea I have no idea what is happening in terms of PyMel. The python documentation states that getLogger() always retrieves the same logger and doesn't create duplicates.

 

To view this discussion on the web visit https://groups.google.com/d/msgid/python_inside_maya/0bc40be4-8eec-44b2-85aa-c2f6e04a8e13n%40googlegroups.com.

[vince touache]

"So then maybe you just need a log.py module, or in your __init__.py ...."

Yes, this is exactly what I'm trying to do! I do all my logging shit under utils.logger, and in my files, I use utils.logger.getLogging(__name__). That way, I handle all my logging crap inside the same file, set all the levels in one place, etc...

"The python documentation states that getLogger() ....."

That's also what I've seen in the documentation, and that's why I can't understand... It's definitely not a pymel issue, as I have the exact same result with the "children" property. See screenshot: same name, different object, but they are all direct children of the root logger. As I said, I wouldn't be able to do it if I wanted to...

It looks like there are many different behaviors implemented by maya itself, on top of the logging lib itself.

Do you have some projects in mind I could look at, to see how they handle this?

[vince touache]

I may have figured it out! Needs more testing, but basically, I had a "refresh" arg to my fonction, which was doing roughly this:

if refresh:

    del logging.root.manager.loggerDict["my_app_logger"]

Terrible idea. I thought this dict was holding a flat hierarchy of all the loggers, but it seems that it's not the only place where the existing loggers are found. Therefore, messing with this dict seems to result in some inconsistancy (e.g. 2 loggers with similar name). I guess the singleton behavior is done (by the logging module) by checking a given name (typically __name__) against this dict. If the key exists, logging returns the value (= the existing instance). If not, creates a new one. Even if existed already somewhere else in memory.