I’m adding several log handlers to a plugin class, grouped into “fatal” errors (which call self.AbortRender(msg, self.AbortLevel.Fatal)), and “failure” errors (which call the same, except with self.AbortLevel.Major).
One of those patterns is a pretty straightforward Python exception handler:
Traceback (most recent call last):
Deadline is finding the pattern properly and aborting, but the output the plugin generates in the log is at once unintelligible and overly verbose:
0: WARNING: Found failure message:
0: WARNING: r
0: STDOUT: Traceback (most recent call last):
0: WARNING: Found failure message:
0: WARNING:
0: WARNING: Another error occurred in stdout callback function:
0: STDOUT: File "/usr/local/setpkg/bin/setpkgcli", line 10, in <module>
0: WARNING: Found failure message:
0: WARNING:
0: WARNING: Another error occurred in stdout callback function:
0: STDOUT: from setpkg import *
0: WARNING: Found failure message:
0: WARNING:
0: WARNING: Another error occurred in stdout callback function:
0: STDOUT: File "/usr/local/setpkg/python/setpkg.py", line 380, in <module>
0: WARNING: Found failure message:
0: WARNING:
0: WARNING: Another error occurred in stdout callback function:
0: STDOUT: import cPickle as pickle
0: WARNING: Found failure message:
0: WARNING: m
0: WARNING: Another error occurred in stdout callback function: m
0: STDOUT: ImportError: /lumalocal/Deadline6/client/bin/python/lib/python2.6/lib-dynload/cPickle.so: undefined symbol: PyUnicodeUCS2_DecodeUTF8
If I don’t add the Traceback handler, the Traceback is echoed as it should be:
0: STDOUT: Traceback (most recent call last):
0: STDOUT: File "/usr/local/setpkg/bin/setpkgcli", line 10, in <module>
0: STDOUT: from setpkg import *
0: STDOUT: File "/usr/local/setpkg/python/setpkg.py", line 380, in <module>
0: STDOUT: import cPickle as pickle
0: STDOUT: ImportError: /lumalocal/Deadline6/client/bin/python/lib/python2.6/lib-dynload/cPickle.so: undefined symbol: PyUnicodeUCS2_DecodeUTF8
…but this obviously doesn’t fail the job right away, since the script is running inside a subshell, and as far as Deadline is concerned, the task process is still running.
Is there a reason the logging is getting so screwed up when I try to install log handlers?
I also just got this after changing one of the flags to the subshell, which tells me absolutely nothing about whats going on:
0: WARNING: Found failure message:
0: WARNING:
0: STDOUT: [16:19:13] starting renderCommand...
0: WARNING: Found failure message:
0: WARNING: e
0: WARNING: Another error occurred in stdout callback function: e
0: STDOUT: User: ruschn
0: WARNING: Found failure message:
0: WARNING:
0: WARNING: Another error occurred in stdout callback function:
0: STDOUT: [16:19:13] setting environ...
Scheduler Thread - Render Thread 0 threw a major error:
I should mention that those lines that are basically empty (or ‘e’) are me calling self.LogWarning(str(self.GetRegexMatch(0))) in my log handlers… so whatever Deadline has as the error pattern seems to be bogus.
OK, I came back to this one fresh this morning, and figured it out almost immediately. I’ve been looping through attributes on an internal object and adding fatal and failure patterns from it programmatically. Our current log parsing code allows log patterns to either be compiled regex objects or strings, and one of the string patterns I was adding was “[Farm Failure],” which obviously isn’t properly escaped out of the box. Changing my code to run raw string patterns through re.escape before passing them to AddStdoutHandlerCallback fixed things right up.
I would still like to know why the callback handlers are firing multiple times… maybe Deadline is aggregating search results for each line, and then firing N callbacks for that line?
I checked the the code, and we’re logging a warning when a stdout callback triggers an error while we’re already handling an error from another callback. This warning isn’t really necessary, and just clutters up the log, so we’ve changed it to be a debug message. Note that debug messages are only shown in the log when “DebugLogging=true” is defined in the dlinit file.
Yup, just use self.GetRegexMatch(0) from the callback function. Index 0 gives the whole line, while 1 and up will give you specific matches within that line that you defined with parenthesis in the regex.
Thanks. I’m not at my desk yet, but does this mean there is a self.LogDebug method on the plugin class? If not, would it be possible to add it (and maybe LogError as well)?
Hmm, I was under the impression that self.GetRegexMatch(0) returned the text matched by the regex, not the whole log line. I’ll try this again and confirm…
Well, I’m mainly thinking of cases where non-critical functions or processes fail or want to alert the user, without taking down the task. If Warning is the only non-info level available, those types of messages lose some of their significance. Spoiled by Python’s logging framework I guess…