WIP: Reduce logspam #1772
Closed
WIP: Reduce logspam #1772
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This is a completely normal condition when running in the AppImage container, so it just amounts to unnecessary logspam.
Don't log attempt to set font, just failure Don't log when setting dark theme Convert "Processing command-line arguments:" into debug message
Don't log confusing "Skipping English..." message Don't log _attempts_ to load translators Log successful attempts as debug messages
Don't always log versions from project file in `upgrade_project_data_structures()`, only log when upgrade paths are taken. Don't spew generic message whenever files contain temp blender paths. Updated file-recovery output to be more informative Replaced some %-formatted strings in log messages with .format() strings
Don't log every time the preview is resized Promote "Error applying JSON to timeline..." messages from info to error
This will allow some log messages in Angular source to be reduced from `log.info()` to `log.debug()` priority
ui_util:INFO Initializing UI for Dialog
blender_model:INFO updating effects model.
blender_listview:INFO File Name
blender_listview:INFO Title
blender_listview:INFO Extrude
blender_listview:INFO Bevel Depth
blender_listview:INFO Font Name
blender_listview:INFO Bfont
blender_listview:INFO Text Alignment
blender_listview:INFO CENTER
blender_listview:INFO Text Size
blender_listview:INFO Text Width
blender_listview:INFO Diffuse Color
blender_listview:INFO Specular Color
blender_listview:INFO Specular Intensity
blender_listview:INFO Start Frame
blender_listview:INFO End Frame
blender_listview:INFO Animation Length
blender_listview:INFO 2
blender_listview:INFO 1
blender_listview:INFO init_slider_values
blender_listview:INFO sliderPreview_valueChanged: 1
blender_listview:INFO sliderPreview_valueChanged: 125
blender_listview:INFO btnRefresh_clicked
blender_listview:INFO QThread Render Method Invoked
blender_listview:INFO preview_timer_onTimeout
blender_listview:INFO Blender command: blender -b '/home/ferd/rpmbuild/REPOS/openshot-qt/src/blender/blend/wireframe_text.blend' -P '/home/ferd/.openshot_qt/blender/7323d7c0-86b5-11e8-a60c-2c27d72bd51f/wireframe_text.py'
X server found. dri2 connection failed!
DRM_IOCTL_I915_GEM_APERTURE failed: Invalid argument
Assuming 131072kB available aperture size.
May lead to reduced performance or incorrect rendering.
get chip id failed: -1 [22]
param: 4, val: 0
X server found. dri2 connection failed!
DRM_IOCTL_I915_GEM_APERTURE failed: Invalid argument
Assuming 131072kB available aperture size.
May lead to reduced performance or incorrect rendering.
get chip id failed: -1 [22]
param: 4, val: 0
CUDA cuInit: Unknown error
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
# XXX
# (I removed literally _THIRTY_ of these identical lines)
# XXX
blender_listview:INFO Image detected from blender regex: [('/home/ferd/.openshot_qt/blender/7323d7c0-86b5-11e8-a60c-2c27d72bd51f/TitleFileName0125.png', '')]
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Blender render thread finished
blender_listview:INFO onRenableInterface
blender_listview:INFO QThread Render Method Invoked
blender_listview:INFO Blender command: blender -b '/home/ferd/rpmbuild/REPOS/openshot-qt/src/blender/blend/wireframe_text.blend' -P '/home/ferd/.openshot_qt/blender/7323d7c0-86b5-11e8-a60c-2c27d72bd51f/wireframe_text.py'
X server found. dri2 connection failed!
DRM_IOCTL_I915_GEM_APERTURE failed: Invalid argument
Assuming 131072kB available aperture size.
May lead to reduced performance or incorrect rendering.
get chip id failed: -1 [22]
param: 4, val: 0
X server found. dri2 connection failed!
DRM_IOCTL_I915_GEM_APERTURE failed: Invalid argument
Assuming 131072kB available aperture size.
May lead to reduced performance or incorrect rendering.
get chip id failed: -1 [22]
param: 4, val: 0
CUDA cuInit: Unknown error
blender_listview:INFO Image detected from blender regex: []
# XXX
# And another 30 here!
# XXX
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: [('/home/ferd/.openshot_qt/blender/7323d7c0-86b5-11e8-a60c-2c27d72bd51f/TitleFileName0125.png', '')]
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Image detected from blender regex: []
blender_listview:INFO Blender render thread finished
blender_listview:INFO onRenableInterface...Anyway, point is that's completely insane. |
|
I think this is my favorite part: blender_listview:INFO Start Frame
blender_listview:INFO End Frame
blender_listview:INFO Animation Length
blender_listview:INFO 2
blender_listview:INFO 1The "logging" degrades into just spewing out random data-parameter markers — not their current value, mind you, just the name of the parameter that's being processed, in what are clearly a bunch of debug printfs left in the code. But then things get somehow even worse when it flips the script and starts outputting random numerical values, with absolutely nothing to indicate what those numbers even represent! Which I think might actually be even worse than the 30 identical messages logged every time "blender regex" comes up empty. (At least those messages show both what operation was being performed, and the result of that operation — even if it is only |
This reverts commit 3f453de.
|
Can't wait till this PR is no longer WIP. Should be really helpful in keeping the logs succinct :) |
Nearly every message is reduced from 'info' to 'debug', some redundant/low-information logs are eliminated, and a new, terse (but actually more informative) standard formatting for messages is introduced and applied to as many log messages as possible.
* Deleted "flow" checkpoints which logged no data (e.g.)
```python3
log.info('currentChanged')
log.info('updateSelection')
```
* Reduced most other messages to `log.debug()`
* Deleted _numerous_ blocks of program-flow debug printfs, like:
```python3
if result == QDialog.Accepted:
log.info('Import image sequence add confirmed')
else:
log.info('Import image sequence add cancelled')
# Or, every time a callback fires...
log.info('actionRedo_trigger')
```
* Many "checkpoint" messages removed or reduced to `log.debug`
* Where possible, checkpoint messages that logged every time
through a loop were replaced with more informative messages
that only log under interesting conditions, letting the
uninteresting loop iterations pass silently
* Remaining useful `log.info()` messages formatted to contain more
information, log more tersely (sometimes combining two or three
consecutive messages into a single, concise form
* Made `keyPressEvent` log messages debug-only
I got a little too ambitious beefing up one of the messages in `properties_model.py`
Every message is reduced to `log.debug()` _except_ the one about
changing the debug mode.
All debug messages are formatted with useful context, so...
```python3
log.info(value)
log.debug('{} set to {}'.format(param["setting"], value))
```
All `qt_log()` messages in the angular code are replaced with `qt_debug()` which only logs in debug mode.
This commit enables something I've been working towards for some time now: The ability to configure OpenShot's console output and logfile output to different logging levels, with potentially _more_ messages being logged to the logfile than are shown on the console. As a result, it brings all of the following: * Log messages of level INFO or higher are written to the console log * By default, initially the same messages are written to the logfile as well * The `debug-mode` preference now affects openshot-qt's own logging, as well as the libopenshot proxy logging. When `debug-mode` is switched on, the `openshot-qt.log` file will receive all messages of level DEBUG or higher. * Log messages proxied from libopenshot are now logged at level DEBUG, instead of INFO, so that they will be written to the log file (only if `debug-mode` is on), but will not be printed to the console output. This opens up the possibility of adding a second ZeroMQ logging channel for messages at a _higher_ severity than debug, which would always be active rather than being gated by the `debug-mode` switch. That priority logging channel could be used for messages which openshot should always log, such as error messages. This would be a possible means of addressing OpenShot#1450.
|
@ferdnyc - I think the line endings change has impacted this one (also). |
Closed
|
Replaced with #1905. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
OpenShot outputs a staggering number of unnecessary, redundant, or generic messages to its log while running, especially on startup.
(A log message every time a fallback icon is used; every time an interface binding is created; every time an effect is loaded — that one just says "effects_model:INFO category: Video" every time, so super useless; every time the preview is resized; etc...)
The user doesn't care about any of these, and honestly they're of no help to developers either. They're just the equivalent of debug
printf()s being left in the code. So, this PR aims to wipe them out.Along the way, I'm fixing the type of some other messages (lowering some from
log.info()tolog.debug(), promoting others fromlog.info()tolog.error(), etc.) and updating the formatting of any that use Python %-string formatting to instead usestr.format.WIP because I still have more files to go through.