I’d like to request some changes be made to the Slave logging behavior.
First off, it would be great if there were an option added to disable the line prefixes Deadline adds to every line of its log, from both the slave and the plugin process. It creates a lot of unnnecessary visual clutter in the log, and makes it that much more difficult to extract an actual error message. We use our own Python logger with its own formatting, and our code logs information as concisely as possible while still being informative, but the lines end up being far less readable coming out of the Slave:
0: PYTHON: luma.render : INFO : Loading job from log directory /Volumes/newhome/ruschn/Thinkbox/Deadline6/slave/ws-082/jobsData
vs:
luma.render : INFO : Loading job from log directory /Volumes/newhome/ruschn/Thinkbox/Deadline6/slave/ws-082/jobsData
Secondly, the Slave logging doesn’t currently deal with multi-line output very well. It seems like it takes any output, splits it on sequences of newlines (throwing consecutive newlines away in the process), and then logs each part of the resulting list as a line if (and only if) the resulting string is not empty. As a result, there is no way to format spacing into log lines.
Calling “print ‘\n’” results in no output.
Calling ‘print “foo\n\nbar”’ results in:
0: PYTHON: foo
0: PYTHON: bar
What I would prefer to see in this case (besides the removal of the line prefixes) is:
[code]0: PYTHON: foo
bar[/code]
Finally, it would be great if the logging font could be selected (and default to something monospaced).
When you have multiple slaves running on 1 machine or multiple threads running on 1 machine, its really useful to have the thread count “0:” displayed in the log.
For some time, I have suggested the use of colour to identify different STDOUT/STDERR/Application log messages on a per line-by-line basis.
I would have thought having the configuration ability to RegEx out the initial "[ThreadNumber]: [python]: " should be possible as a global repository setting?
Well, if you have multiple slaves running on a single machine, each one should generate its own log, no? As I mentioned, I’m not pushing to have the default behavior changed or anything, but I would really like to be able to disable all of the line prefixes. I really just want a monospaced, plaintext log output that I can format predictably from within my script or application…
We prefix the output for a few reasons. As Mike mentioned, we prefix the lines with the thread number to deal with concurrent tasks running on a slave. This is what allows the drop down in the slave UI (and the remote log viewer) to filter on a specific rendering thread. Without those prefixes, this wouldn’t work.
We also use the STDOUT, INFO, WARNING, and PYTHON prefixes so that it’s clear where the lines are coming from:
STDOUT is for lines from the rendering application
INFO is for LogInfo lines in the DeadlinePlugin
WARNING is for LogWarning lines in the DeadlinePlugin
PYTHON is for python ‘print’ statements that would normally go to the console
We find these prefixes to be extremely helpful when looking through log and error reports for jobs. Our clients send our support team error reports all the time, and if we didn’t have this information, it would be much more difficult to figure out where the error is originating (especially in our more advanced plugins). We still want to look at the possibility of color-coding the log and error reports in the Monitor, and the prefixes would be necessary for this.
We also throw away blank lines and split up new lines by design. We’ve seen some rendering applications print out tons of empty whitespace which makes the logs hard to parse through. We also feel that splitting up the new lines makes for a more readable log because all the lines are lined up by the prefix.
Finally, for the slave font, we just use the default font, so we’ll see if we can change this (or at least make it optional).
Ok, so it sounds like the line leaders are somewhat critical to the operation of the slave (I had hoped it was more or less a case where a simple flag could be added to suppress them).
So with that in mind, here are a couple other proposals:
Justify all line leaders to a common width. Coupled with a monospaced font, this would go even further toward readability, while still keeping all of the current info there.
0: INFO: This is an info message
0: PYTHON: This is a Python message
0: STDOUT: This is a subprocess message
0: WARNING: This is a warning message
Add an option to toggle the leaders on or off while viewing the logs in the Monitor.
Also, where do the messages that don’t have leaders come from?
0: Task timeout is disabled.
0: Loaded job: Test Job Name (5109e13e962ccc7dcbb5766e)
0: Plugin rendering frame(s): 1079-1081
While it is more readable, sadly it makes troubleshooting harder.
For example, when we print out a string that includes a full traceback (which will include new-lines), the error handler function operates (and potentially terminates) the run on each of those lines separately. Meaning, that if for example i want to make the “traceback” string an error string, deadline terminates the slave on the first line of the traceback, clamping out all the useful debug information.
This isn’t related actually. The slave handles each line of input one at a time, so if you do a multiline print statement in python, the stdout handlers are still handling those lines one at a time. So when you call self.FailRender( self.GetRegexMatch(0) ) from the stdout handler, only the line that it’s working on is in the message.
I did some testing though, and the full error message always made it into the error report’s log. This is because we wait 100ms before terminating the process. I agree that it’s not as convenient to scroll down the log message, but the full traceback output should be there.
Sorry about that. I meant to comment on those but lost track of the.
I think a monospaced font would go a long way to help here, and if we can get that in there, justifying the lines of output should be a simple addition. I’ve updated the monospace feature request we logged previously with this additional info.
I think I like the first idea better. This would require us to walk through every line of text from the log before displaying it and throw away stuff at the beginning. Not sure I like the thought of doing this.
These come from the slave render thread that’s handling the current task. Not sure if they need an additional prefix or not…
Yeah, that’s a good point; not an ideal step just for log display. The justified spacing and monospaced font are definitely more widely beneficial I would say, so not a huge deal.
