It is more opinionated and has fewer log levels than the existing systems. But whenever I use the logging now, I always just log everything at max verbosity because figuring out the right filter or level is not worth it.
It would be interesting to understand if other developers are really relying on the extra granularity in the current systems.
If render-farms are a legit use-case, i feel a machine readable format (xml/json/yaml/i’m unsure what passes for a standard in this space honestly) should be designed for right from the start, there should be no arbitrary data to parse for 3rd parties, if a log event emits data about memory allocations/usage these should be in clearly labelled fields, and not contain any human readable data (ie it be logging 1237921 bytes, rather than 1.18MiB) trying to worm that in later is likely gonna be unsatisfactory for all parties involved.
The current logging systems i’ll be honest, i rarely use any of them, there’s (as you rightfully so noted) just too many of them, and since there is no clear way of logging, i chose not to learn any of them, so i don’t know how to use them and just sprinkle printf’s all over the place when i need them (and then carefully try to remove them so they don’t end up in any PR’s)
Render farms are already parsing the output, so something more structured would certainly help. Once the logging system is unified structured output seems like a logical next step, and pretty straightforward. It might have to go to a separate file to avoid mixing with random prints we can’t control.
Also some of the log data may be better suited for some kind of tracing framework than it is for logging, ie the ghost event data is likely better off with something like this:
There is indeed overlap with tracing. I would still want to be able to have ghost events in the logs. You could have e.g. --trace cycles and get all the same logs as using --log cycles sent to the tracing system, but not sure how well that would work.
The other thing we might add is a Python application handler that receives all log messages. This way render farms can make their own decisions about when to exit or how to format and write the logs. They might prefer that over whatever structured output we come up with.
The other thing we might add is a Python application handler that receives all log messages. This way render farms can make their own decisions about when to exit or how to format and write the logs. They might prefer that over whatever structured output we come up with.
I rarely to never use the currently logging system either for the same reasons that were already mentioned. If I need logging, I usually end up just printing the data I need myself which is faster then trying to figure out if there is some logging for it already and how to enable it (without getting spammed with tons of unrelated logging information).
More structured logging could help with that so that I could filter the logs more easily.
I have used the INFO levels it in the past in some rare occasions, mainly related to blendfile reading or liboverrides handling, when investigating complex massive studio production files.
These CLOG calls can produce a massive amount of prints at high verbosity level, so would start with lower verbosity and increase until I got what I needed.
But in general I agree with the proposal, quite often I end up adding dedicated custom prints (checking on some ID name e.g.). Or dumping everything in a big text file and searching from there.
And the current handling of defining which verbosity level to use for which INFO log is completely random anyway in our code.
There is a bit of chicken-and-egg problem with the verbosity levels. With the size of Blender it is hard to keep levels consistent. Having semantic names for levels is something that should make it much easier.
And I do use different levels – when doing some basic profiling I do use --debug-cycles, so that I have access to basic statistics etc. When I really debugging something I just end up --verbose 10 and grep. Same when I was doing Libmv work – it uses single verbosity level, as it is hard to differentiate what is more or less important.
There are a couple of notes when it comes to replacing glog with something else:
AFAIR, Cycles utilizes the gmock’s sink for glog to check constant folding. Would be good to make the result check more explicit somehow, as relying on logging is kind of weak.
Ceres version we’re shipping using glog, and its extern, and I would want to be able to see logging from it. Maybe we can switch Libmv and Ceres to he miniglog which is shipped with Ceres 2.2.0
I am not sure what we’ll do in the future with Ceres. It switched to absl logging. The absl dependency imposes some other complications when it’ll come to updates. Maybe we’d move Ceres to make deps, but would need to check what type of logging control Ceres API has.
I wouldn’t want Libmv to be too coupled to Blender’s logging, and wouldn’t want it to loose logging functionality when its build outside of Blender. Similar feeling goes towards Cycles. Not sure what would be the easiest solution. In a way, the correct way for such cases seems that there would need to be a way for Libmv to register logging sink.
I agree that logging need more attention and making it more user oriented would increase self-solving by the user. It could lower user reports especially when messages contains potential solution areas or links to pages with info. My suggestions are more oriented to also take some rules into account for system/developer based logging using the same mechanism.
Recently I have been adding some vulkan loggings using CLOG to connect the gpu and ghost module better and to get some feedback from users on specific systems. A trace level in that case which would be more developer oriented could also be considered.
In the markup of the loglines we could also consider timestamps as a part of the logging system, that could be turned on/off when using a human readable log output. I would assume that the json output would always contain an event time field.
I implemented a basic replacement for the scoped mock log now, still using the logging system. Could be replaced with something else but also no immediate need I think.
Yes, that’s what the proposed --log-level debug is meant for.
Timestamps are always enabled in my implementation. Previously there was a CLOG option for this but off by default.
A structured log file indeed should contain all possible information.
