I’m currently investigating the cause of the ftrack api spamming me with debug logging, and it specifically appears whilst publishing. Its generating so many log outputs that I believe its slowing the process down quite a bit.
Now this might be completely unrelated to Pyblish, but so far I’m struggling to find what could be causing the logging for ftrack to be set to debug. As far as I can tell, the output only happens during Pyblish publishing. For example I’ve just taken a section of code from an integration plugin and run it from within nukes script editor, and no output was generated at all while creating entities through ftrack. Interestingly I’m not getting the same result in 3dsmax, running the same code. However I seem to recall the debug messages appearing about the time I started using Pyblish, however that could be completely coincidental.
So I guess my questions are:
- Is there any chance\seems reasonable that Pyblish could be related to my problem.
- Is there a way to turn Pyblish’s logging off, (purely for testing purposes.) I’ve tried
logging.getLogger("pyblish").setLevel(logging.WARNING) in order to reduce them, however it still seems to generate the pyblish Info logs as well as the pesky ftrack ones.
I appreciate this is a long shot, but thought it might be worth asking here. In truth I suspect the answer must be buired somewhere in our own internal code, but I’ve been performing text searches across the whole lot for likely suspects.
That’s a tricky one to test, as I don’t have access to ftrack. Would it be possible to find a way to replicate the problem in any way I can replicate on my end?
Other than that, I can’t think of anything that might cause this.
Yeah, it is a tricky one. I’ll have a think, and see if I can mock something up, in fact doing so might be a good way to test if is related.
Let me know how it goes, I’m happy to help in any way I can.
I haven’t managed to mock up a test yet that I can share with you, but I did do the following.
Using the code bellow I did the following in order.
- I launched a fresh copy of nuke.
- I then ran the code.
- Then I launched the publish app for the first time and ran a publish.
- I got a ton of ftrack debug.
- I then closed the app.
- Ran the code again.
- Relaunched the publish app and did a publish
- This time got no ftrack debug.
for name, logger in logging.Logger.manager.loggerDict.iteritems():
print "fail", name
So it would possibly seem that its getting initialised on the import of a module somewhere in the publish tool (but not necessarily Pyblish), as the second attempt didn’t restore the debug.
Which Pyblish app are you running? Perhaps it is something local to that app.
Have a look at running a plain
OK This produces the same result:
self.logger = logging.getLogger("TestLogging")
self.logger.debug("I'm a debug message")
def process(self, context):
tlc = TestLoggingClass()
result within nuke:
# Result: hello python
DEBUG 12:43:50.243:TestLogging(7868): Im a debug message
So it does produce the message, even though I haven’t set a logging level so it should be
WARNING by default.
you can lower the logging level of ftrack_api so it stops spamming pyblish
Running the same code in max 2017 or even in standalone python doesn’t produce this. So it seems to be related to pyblish and nuke combined.
Thank you, I tried this at the start of my Pyblish app, and that suppresses it.
I guess the question still stands as to why this is happening in the first place. The solution is acceptable if not a little ugly as it would seem you need to suppress anything that uses logging during the plugins processing.
Thank you for your input though, I wasn’t sure which of the many ftrack loggers I would needed to set, so that answers that.