Openshot-qt: When are logging warnings used?
I'm currently writing an article about logging in Python. I'm looking at several big projects to see what the best practices are. One part that I'm not certain about is when exactly which log levels are used and what is logged.
This is how I used it so far:
- log.debug: If there are bugs that happen often enough that one should deal with them, but all other tries so far to pin them down failed. Kind of "debugging in production". Often, I remove those once I've found the issue.
- log.info: This is what I use most of the time. Key parts of the application are logged here. If something is more time-consuming, I tend to log it more thoroughly.
- log.warning: Something that could become a problem or indicate a problem, e.g. free disk space or a timeout when trying to reach a website.
- log.error: Something failed which is user-facing, e.g. the user wanted to save a file and the location was not writable
- log.critical: I think I've never used it :thinking:
- warnings.warn: Deprecations or missing environment options that are non-critical (e.g. a BLAS is missing)
I've copied the lines where logging is used in OpenShot below. It would be awesome if you could tell me what the best practices are :pray:
log.warning
This is where openshot uses logging.warning:
freeze.py:268: log.warning("Skipping {}: {}".format(mod_name, ex))
src/classes/language.py:148: log.warning('Failed to parse language for %s' % locale_name)
src/classes/app.py:118: log.warning("Error displaying dependency/system details", exc_info=1)
src/classes/app.py:294: log.warning('Failed to write session ended log')
src/classes/project_data.py:71: log.warning("Cannot get empty key.")
src/classes/project_data.py:152: log.warning("_set() key must be a list. key: {}".format(key))
src/classes/project_data.py:155: log.warning("Cannot set empty key.")
src/classes/project_data.py:259: log.warning("Unable to load user project defaults from {}: {}".format(info.USER_DEFAULT_PROJECT, ex))
src/classes/importers/final_cut_pro.py:145: log.warning('Error building File object for %s' % clip_path, exc_info=1)
src/classes/importers/edl.py:99: log.warning('Error building File object for %s' % clip_path, exc_info=1)
src/classes/json_data.py:200: log.warning(msg)
src/classes/thumbnail.py:66: log.warning("Could not parse rotation value {}: {}".format(rotate_data, ex))
src/classes/thumbnail.py:68: log.warning("Error reading rotation metadata from {}".format(file_path), exc_info=1)
src/classes/updates.py:89: log.warning('Failed to clear history attribute from undo/redo data. {}'.format(ex))
src/classes/updates.py:122: log.warning('Failed to clear history attribute from undo/redo data. {}'.format(ex))
src/classes/updates.py:214: log.warning("Cannot add existing listener: {}".format(str(listener)))
src/classes/updates.py:223: log.warning("Cannot add existing watcher: {}".format(str(watcher)))
src/windows/views/effects_treeview.py:62: log.warning("No draggable items found in model!")
src/windows/views/timeline_mixins.py:106: log.warning("WebEngine backend still not ready after {} retries.".format(retries))
src/windows/views/timeline_mixins.py:149: log.warning('JS: %s line %d: %s' % (source, line, msg))
src/windows/views/timeline_mixins.py:184: log.warning("WebKit backend still not ready after {} retries.".format(retries))
src/windows/views/emojis_listview.py:111: log.warning("Failed to import file: {}".format(str(ex)))
src/windows/views/effects_listview.py:62: log.warning("No draggable items found in model!")
src/windows/views/transitions_listview.py:65: log.warning("No draggable items found in model!")
src/windows/views/timeline_webview.py:222: log.warning('Failed to parse clip JSON data', exc_info=1)
src/windows/views/changelog_treeview.py:87: log.warning('Failed to launch web browser to %s' % self.commit_url)
src/windows/views/files_treeview.py:107: log.warning("No draggable items found in model!")
src/windows/views/transitions_treeview.py:62: log.warning("No draggable items found in model!")
src/windows/views/files_listview.py:106: log.warning("No draggable items found in model!")
src/windows/animated_title.py:135: log.warning('Failed to remove child widget for effect controls')
src/windows/about.py:78: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name))
src/windows/about.py:272: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name))
src/windows/about.py:292: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name))
src/windows/about.py:314: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name))
src/windows/models/transition_model.py:183: log.warning('Invalid transition image file {}: {}'.format(filename, ex))
src/windows/models/files_model.py:147: log.warning("Couldn't remove {} from model!".format(delete_file_id))
src/windows/models/files_model.py:352: log.warning("Failed to import {}: {}".format(filepath, ex))
src/windows/main_window.py:1118: log.warning("######## RENUMBERING TRACKS ########")
src/windows/main_window.py:1220: log.warning("Could not find track {}: {}".format(selected_layer_num, ex))
src/windows/main_window.py:1267: log.warning("Could not find track {}: {}".format(selected_layer_num, ex))
src/windows/main_window.py:1943: log.warning("Couldn't find current file for properties window")
src/windows/main_window.py:2876: log.warning('Failed to connect to Unity launcher (Linux only) for updating export progress.')
src/windows/export.py:303: log.warning("Invalid framerate detected, not sending it to libopenshot: %s" % fps_double)
src/windows/export.py:695: log.warning('Failed to convert bitrate string to bytes: %s' % BitRateString)
log.error
src/classes/exporters/final_cut_pro.py:138: log.error('No track object found with number: %s' % track.get("number"))
src/classes/exporters/final_cut_pro.py:232: log.error("Error writing XML export: {}".format(str(inst)))
src/classes/exporters/edl.py:78: log.error('No track object found with number: %s' % track.get("number"))
src/classes/app.py:94: log.error('OpenShotApp::Import Error: %s' % str(ex))
src/classes/app.py:100: log.error('OpenShotApp::Init Error: %s' % str(ex))
src/classes/app.py:178: log.error('Failed to create PERMISSION/test.osp file (likely permissions error): %s' % TEST_PATH_FILE)
src/classes/app.py:203: log.error("Error setting Ubuntu-R.ttf QFont: %s" % str(ex))
src/classes/app.py:276: log.error("Couldn't save user settings on exit.\n{}".format(ex))
src/classes/project_data.py:85: log.error("Unexpected key part type: {}".format(type(key_part).__name__))
src/classes/project_data.py:167: log.error("Unexpected key part type: {}".format(type(key_part).__name__))
src/classes/project_data.py:302: log.error("Failed to parse file '%s' as a profile: %s" % (profile_path, e))
src/classes/project_data.py:539: log.error(msg)
src/classes/project_data.py:699: log.error(msg)
src/classes/project_data.py:895: log.error("Error while moving temp paths to project assets folder {}: {}".format(asset_path, ex))
src/classes/metrics.py:68: log.error("Error determining OS version in metrics.py")
src/classes/metrics.py:172: log.error("Failed to Track metric: %s" % (Ex))
src/classes/metrics.py:200: log.error("Failed to Track exception: %s" % (Ex))
src/classes/settings.py:98: log.error("Error loading settings file: %s" % ex)
src/classes/assets.py:75: log.error("Error while getting/creating asset folder {}: {}".format(asset_path, ex))
src/classes/json_data.py:193: log.error(str(ex))
src/classes/json_data.py:197: log.error(msg)
src/classes/json_data.py:214: log.error(msg)
src/classes/json_data.py:257: log.error("Error while converting relative paths to absolute paths: %s" % str(ex))
src/classes/json_data.py:332: log.error("Error while converting absolute paths to relative paths: %s" % str(ex))
src/classes/json_data.py:367: log.error("Couldn't write to backup file {}: {}".format(backup_file, ex))
src/classes/thumbnail.py:123: def log_error(self, msg_format, *args):
src/classes/thumbnail.py:125: log.error(msg_format % args)
src/classes/exceptions.py:35: log.error('Unhandled Exception', exc_info=(exeception_type, exeception_value, exeception_traceback))
src/classes/updates.py:303: log.error("Couldn't apply '{}' to update listener: {}\n{}".format(action.type, listener, ex))
src/classes/version.py:57: log.error("Failed to get version from: %s" % url)
src/windows/views/blender_listview.py:470: log.error("Blender error output:\n{}".format(command_output))
src/windows/views/blender_listview.py:526: log.error("Could not load GPU enable code! {}".format(e))
src/windows/views/blender_listview.py:782: log.error("Worker exception: {}".format(ex))
src/windows/cutting.py:137: log.error('Failed to load media file into preview player: %s' % self.file_path)
src/windows/ui/main-window.ui:1204: <iconset theme="dialog-error" resource="../../../images/openshot.qrc">
src/windows/ui/main-window.ui:1205: <normaloff>:/icons/Humanity/status/16/dialog-error.svg</normaloff>:/icons/Humanity/status/16/dialog-error.svg</iconset>
src/windows/profile.py:87: log.error("Failed to parse file '%s' as a profile: %s" % (profile_path, e))
src/windows/main_window.py:275: log.error("Unhandled crash detected... will attempt to recover backup project: %s" % info.BACKUP_FILE)
src/windows/main_window.py:484: log.error("Couldn't save project %s. %s" % (file_path, str(ex)))
src/windows/main_window.py:553: log.error("Couldn't open project {}".format(file_path))
src/windows/main_window.py:872: log.error("Unable to open the Help Contents: {}".format(str(ex)))
src/windows/main_window.py:886: log.error("Unable to open the Bug Report page: {}".format(str(ex)))
src/windows/main_window.py:893: log.error("Unable to open the subreddit page: {}".format(str(ex)))
src/windows/main_window.py:900: log.error("Unable to open the translation page: {}".format(str(ex)))
src/windows/main_window.py:907: log.error("Unable to open the donation page: {}".format(str(ex)))
src/windows/main_window.py:914: log.error("Unable to open the download page: {}".format(str(ex)))
src/windows/main_window.py:1145: log.error('Track number {} not found'.format(oldnum))
src/windows/main_window.py:1211: log.error('No track object found with id: %s' % selected_layer_id)
src/windows/main_window.py:1258: log.error('No track object found with id: %s' % selected_layer_id)
src/windows/title_editor.py:176: log.error("Couldn't load title preview from {}".format(tmp_filename))
src/windows/title_editor.py:360: log.error("Error writing SVG title: {}".format(inst))
src/windows/export.py:224: log.error("Failed to parse file '%s' as a profile: %s" % (profile_path, e))
src/windows/export.py:259: log.error("Failed to parse file '%s' as a preset: %s" % (preset_path, e))
src/windows/export.py:427: log.error("Failed to parse file '%s' as a preset: %s" % (preset_path, e))
src/windows/export.py:584: log.error("Failed to parse file '%s' as a preset: %s" % (preset_path, e))
src/windows/preview_thread.py:277: log.error('Failed to load media file into video player: %s' % path)
log.debug
src/classes/language.py:42: log.debug("Using compiled translation resources")
src/classes/language.py:45: log.debug("Loading translations from: {}".format(language_path))
src/classes/language.py:117: log.debug("Exiting translation system (since we successfully loaded: {})".format(locale_name))
src/classes/language.py:131: log.debug('Attempting to load {} in \'{}\''.format(filename,path))
src/classes/language.py:134: log.debug('Successfully loaded {} in \'{}\''.format(filename, path))
src/windows/views/timeline_mixins.py:104: log.debug("run_js() called before document ready event. Script queued: %s" % code)
src/windows/views/timeline_mixins.py:108: log.debug("Script queued, {} retries so far".format(retries))
src/windows/views/timeline_mixins.py:182: log.debug("run_js() called before document ready event. Script queued: %s" % code)
src/windows/views/timeline_mixins.py:186: log.debug("Script queued, {} retries so far".format(retries))
src/windows/views/tutorial.py:302: log.debug('Failed to properly disconnect from dock signals', exc_info=1)
src/windows/views/timeline_webview.py:353: log.debug('transition start: %s' % transition_data["start"])
src/windows/views/timeline_webview.py:354: log.debug('transition end: %s' % transition_data["end"])
src/windows/views/timeline_webview.py:376: log.debug('ShowPlayheadMenu: %s' % position)
src/windows/views/timeline_webview.py:410: log.debug('ShowEffectMenu: %s' % effect_id)
src/windows/views/timeline_webview.py:426: log.debug('ShowTimelineMenu: position: %s, layer: %s' % (position, layer_id))
src/windows/views/timeline_webview.py:450: log.debug('ShowClipMenu: %s' % clip_id)
src/windows/views/timeline_webview.py:920: log.debug("Transform_Triggered")
src/windows/views/timeline_webview.py:1001: log.debug("Split_Audio_Triggered")
src/windows/views/timeline_webview.py:1076: log.debug("Adding clip for channel %s" % channel)
src/windows/views/timeline_webview.py:1140: log.debug(action)
src/windows/views/timeline_webview.py:1215: log.debug(action)
src/windows/views/timeline_webview.py:1402: log.debug(action)
src/windows/views/timeline_webview.py:1474: log.debug(action)
src/windows/views/timeline_webview.py:1586: log.debug("Nudging clip(s) and/or transition(s)")
src/windows/views/timeline_webview.py:1597: log.debug("Nudging by %s sec" % nudgeDistance)
src/windows/views/timeline_webview.py:1673: log.debug(action)
src/windows/views/timeline_webview.py:1756: log.debug(action)
src/windows/views/timeline_webview.py:1985: log.debug(action)
src/windows/views/timeline_webview.py:2122: log.debug(action)
src/windows/views/timeline_webview.py:2162: log.debug(action)
src/windows/views/timeline_webview.py:2202: log.debug(clip.data)
src/windows/views/timeline_webview.py:2943: log.debug(clip)
src/windows/views/timeline_webview.py:3004: log.debug('Adding clip for {}'.format(os.path.basename(filepath)))
src/windows/views/timeline_webview.py:3020: log.debug('dragLeaveEvent - Undo drop')
src/windows/views/timeline_webview.py:3037: log.debug('redraw_audio_onTimeout')
src/windows/views/properties_tableview.py:185: log.debug('Failed to access data on selected label widget')
src/windows/views/blender_listview.py:213: log.debug('Failed to read plain text value from widget')
src/windows/main_window.py:291: log.debug("Wrote value {} to lock file {}".format(
src/windows/main_window.py:295: log.debug('Failed to write lock file (attempt: {})'.format(
src/windows/main_window.py:307: log.debug("Removed lock file {}".format(lock_path))
src/windows/main_window.py:312: log.debug('Failed to destroy lock file (attempt: %s)' % attempt, exc_info=1)
src/windows/main_window.py:2175: log.debug('addSelection: item_type: {}, clear_existing: {}'.format(
src/windows/main_window.py:2602: log.debug('Failed to notify unity launcher of export progress. Frame: %s' % current_frame)
src/windows/main_window.py:2611: log.debug('Failed to notify unity launcher of export progress. Completed.')
src/windows/title_editor.py:225: log.debug('Failed to delete child settings widget')
src/windows/title_editor.py:450: log.debug('Failed to parse {} as color value'.format(txt))
src/windows/title_editor.py:459: log.debug('Failed to parse {} as opacity value'.format(txt))
src/windows/preferences.py:300: log.debug("Preparing to test hardware decoding: %s" % (value_list))
src/windows/preferences.py:306: log.debug("Completed hardware decoding testing")
src/windows/preferences.py:503: log.debug('Failed to get plain text from widget')
src/windows/preferences.py:560: log.debug("Current hardware decoder: %s (%s-%s)" % (current_decoder_name, current_decoder, current_decoder_card))
src/windows/preferences.py:564: log.debug("Testing hardware decoder: %s (%s-%s)" % (decoder_name, decoder, decoder_card))
src/windows/preferences.py:579: log.debug("Successful hardware decoder! %s (%s-%s)" % (decoder_name, decoder, decoder_card))
src/windows/preferences.py:581: log.debug("CheckPixel failed testing hardware decoding (i.e. wrong color found): %s (%s-%s)" %
src/windows/preferences.py:588: log.debug("Exception trying to test hardware decoding (this is expected): %s (%s-%s)" %
log.info and log.critical
There are way to many usages of log.info and no usage of log.critical at all.
MartinThoma
All 7 comments
I'm currently writing an article about logging in Python. I'm looking at several big projects to see what the best practices are.
In all honesty, I _personally_ wouldn't draw on OpenShot as an example of "best practices" — even by our own estimation, OpenShot's logging is suboptimal. It serves our own needs for the most part, but it's nothing I'd hold up as an example of best practices or even good practices, nor would I encourage anyone else to emulate, study, or learn from our practices, (except perhaps as a cautionary tale).
It all really comes down to the fact that we don't _use_ the logs for all that much other than ad-hoc debugging, and that shows in both the substance and the quantity of what's logged. Most of the logs are effectively debug printf()s that have remained in the code. Many of them are effectively debugger watchpoints without either the debugger or the watchpoint — they serve only to announce entry into a particular function or arrival at a particular line of code, and nothing more.
We've only recently _started_ to transition those "waypoint" logs to err on the side of using log.debug() rather than log.info() (or higher!), so that at least they'll be hidden by default. But that work only started within the last month or two when a --debug command-line option was added to the application launcher, to make the messages visible when necessary. Until that point, there was no way to _view_ anything output with log.debug(), so that level was almost completely unused.
In addition, we:
- Don't use Python parent/child loggers, everything logs to a single
openshot-qtlogging instance. - Are spotty about including system error details when logging from exceptions. Many log calls inside
exceptblocks still log just an ad-hoc (and not even always accurate) message about the condition that's assumed to have raised the exception, but doesn't include theexc_info=1traceback or even the string representation of theExceptionitself. - Tend to ignore logging in favor of using Qt
QMessageBoxdialogs, for any messages the user _should_ actually see, because we have Windows users for whom logging is effectively useless. Too frequently, in those cases, we pop up the dialog instead of logging a message, which means that nothing appears in the logs.* - Have much of our core program logic implemented in a C++ library that's loaded as an extension via SWIG bindings. That extension does its own logging over a ZeroMQ link, and those messages are handled completely separate from the Python logging. In normal use the bus isn't being listened on, so all of the messages are ignored and there's no log output from the library _at all_. (Even on error conditions.) If "debugging mode" is enabled, then EVERYTHING from the library is output at
log.info()level, including error conditions. There are no log levels at all in OpenShot's current ZeroMQ logging implementation.
* – (This one is why you see so few log.warning() level messages — if something _is_ a warning for the user, it'll be expressed as a QMessageBox.warning() rather than a log.warning(). Logs are _only_ for the developers (or at least that's how the code is written), and it doesn't really make sense to _warn_ developers of some condition during a user session, because nobody will ever receive that warning until long after the fact.)
One part that I'm not certain about is when exactly which log levels are used and what is logged.
This is how I used it so far:
- log.debug: If there are bugs that happen often enough that one should deal with them, but all other tries so far to pin them down failed. Kind of "debugging in production". Often, I remove those once I've found the issue.
It would be lovely if everyone followed that same cleanup principle. It is not well-adhered-to in the OpenShot codebase, alas. Especially since most of our debug logs are in the form of log.info() messages which get output during normal sessions.
- log.info: This is what I use most of the time. Key parts of the application are logged here. If something is more time-consuming, I tend to log it more thoroughly.
The logging statements in OpenShot tend to be completely raw — typically their intended audience is the person who inserted the message, and nobody else. Logging _bare_ values with no identifying information is not unheard of, even. (I think I finally excised it a few months ago, but for the longest time there was a logging statement in the code that simply logged the keycode associated with a shortcut key, every time one was triggered. Just the keycode, nothing else. So you'd see log lines like this:
main_window: 1677624
...Invaluable. :unamused:
- log.warning: Something that could become a problem or indicate a problem, e.g. free disk space or a timeout when trying to reach a website.
See above.
In an _ideal_ world, personally how I'd try to use log.warning() would be as a signpost along code paths that I _expect_ shouldn't normally be reached. So when one of them is, that fact would presumably indicate a programming (not program) error — a function called with invalid arguments, or a typo in an identifier, something like that. Stuff that, even if it doesn't create an error condition (IOW, it's able to be _handled_), still shouldn't be ignored. log.info() messages are always able to be ignored.
- log.error: Something failed which is user-facing, e.g. the user wanted to save a file and the location was not writable
Indeed. And not only was the failure user-facing, but was _user-involved_. IOW (and I've been trying to evangelize this view recently), a missing application icon or an unreadable file from within the package are _not_ anything we should bother the user about, because (a) it doesn't affect them, it only affects the program, and more importantly, (b) there's nothing they can reasonably be expected to do, in response to that error. IMHO anytime an error condition is logged or displayed, the expectation is that it's a _problem_ the user should be seeking to correct. Even when it directly impacts their use of the application, if it's not also something they should know how to correct and be able to correct, then we shouldn't be making it their problem.
(As an example, a couple of those QMessageBox.warning() dialogs OpenShot pops up are there to notify the user that an icon file is missing. ...Why do they need to know that, and what on Earth are they supposed to do about it?)
- log.critical: I think I've never used it thinking
I don't think I have either, TBH. I'm not sure what would constitute a "critical" error in an enduser application. That's far more likely to have meaning in a system service or a network daemon, persistent, long-lived code where an error merely means _something_ went wrong, but a critical error means _everything_ went wrong. When that happens in a user application, it just exits (or crashes).
- warnings.warn: Deprecations or missing environment options that are non-critical (e.g. a BLAS is missing)
The warnings module is also entirely absent from the OpenShot codebase.
I've copied the lines where logging is used in OpenShot below. It would be awesome if you could tell me what the best practices are
I'll try to give some broad-strokes takes, but I fear this will only serve to irritate me reading through it all like this (I'm referring to my irritation with the current state of our logging, not in any way related to your questions or the details you've asked for. I'm happy to answer as best I can, my only worry is that I fear you may be seeking to find order or design in a process that's primarily relied on entirely different forces to drive it.)
log.warning
This is where openshot uses logging.warning:
freeze.py:268: log.warning("Skipping {}: {}".format(mod_name, ex))
That's a packaging script, so internal-use.
src/classes/language.py:148: log.warning('Failed to parse language for %s' % locale_name) src/classes/app.py:118: log.warning("Error displaying dependency/system details", exc_info=1) src/classes/app.py:294: log.warning('Failed to write session ended log') src/classes/project_data.py:71: log.warning("Cannot get empty key.") src/classes/project_data.py:152: log.warning("_set() key must be a list. key: {}".format(key)) src/classes/project_data.py:155: log.warning("Cannot set empty key.")
Most of these should be debug logs, TBH, especially if they can occur under normal conditions.
src/classes/project_data.py:259: log.warning("Unable to load user project defaults from {}: {}".format(info.USER_DEFAULT_PROJECT, ex)) src/classes/importers/final_cut_pro.py:145: log.warning('Error building File object for %s' % clip_path, exc_info=1) src/classes/importers/edl.py:99: log.warning('Error building File object for %s' % clip_path, exc_info=1) src/classes/json_data.py:200: log.warning(msg) src/classes/thumbnail.py:66: log.warning("Could not parse rotation value {}: {}".format(rotate_data, ex)) src/classes/thumbnail.py:68: log.warning("Error reading rotation metadata from {}".format(file_path), exc_info=1) src/classes/updates.py:89: log.warning('Failed to clear history attribute from undo/redo data. {}'.format(ex)) src/classes/updates.py:122: log.warning('Failed to clear history attribute from undo/redo data. {}'.format(ex))
Most of these are good, they signify issues processing the user's project file or settings data, which could indicate possible corruption or mistakes made hand-editing. Not necessarily errors, but if errors crop up later this may be the cause.
src/classes/updates.py:214: log.warning("Cannot add existing listener: {}".format(str(listener))) src/classes/updates.py:223: log.warning("Cannot add existing watcher: {}".format(str(watcher))) src/windows/views/effects_treeview.py:62: log.warning("No draggable items found in model!")
Back to stuff that isn't the user's problem.
src/windows/views/timeline_mixins.py:106: log.warning("WebEngine backend still not ready after {} retries.".format(retries)) src/windows/views/timeline_mixins.py:149: log.warning('JS: %s line %d: %s' % (source, line, msg)) src/windows/views/timeline_mixins.py:184: log.warning("WebKit backend still not ready after {} retries.".format(retries))
Issues with the web view backend that drives our HTML-based timeline UI. The "not ready" messages are only displayed after several retries, since the backend can be slow to initialize but is expected to _eventually_ signal readiness. If it doesn't, something's wrong. (The middle message relays console output from the web view's JS engine; the newer WebEngine backend supports multiple logging severities so when that PR is merged the Python log severity will be set accordingly.
src/windows/views/emojis_listview.py:111: log.warning("Failed to import file: {}".format(str(ex))) src/windows/views/timeline_webview.py:222: log.warning('Failed to parse clip JSON data', exc_info=1) src/windows/views/changelog_treeview.py:87: log.warning('Failed to launch web browser to %s' % self.commit_url)
src/windows/views/effects_listview.py:62: log.warning("No draggable items found in model!") src/windows/views/transitions_listview.py:65: log.warning("No draggable items found in model!") src/windows/views/files_treeview.py:107: log.warning("No draggable items found in model!") src/windows/views/transitions_treeview.py:62: log.warning("No draggable items found in model!") src/windows/views/files_listview.py:106: log.warning("No draggable items found in model!")
These are a result of cut-and-paste code, which I find personally irritating because it creates false equivalencies. In the _files_ views, this could indicate a problem accessing the user's imported media files which is definitely something they should be alerted to. In the OTHER cases, where that same code was copied, the source for that model data is instead our own internal files. There's no point in crying to the user if we're having issues _there_.
src/windows/animated_title.py:135: log.warning('Failed to remove child widget for effect controls') src/windows/about.py:78: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name)) src/windows/about.py:272: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name)) src/windows/about.py:292: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name)) src/windows/about.py:314: log.warning('Failed to parse log file %s with encoding %s' % (changelog_path, encoding_name)) src/windows/models/transition_model.py:183: log.warning('Invalid transition image file {}: {}'.format(filename, ex))
OMFG debug debug debug. How are these warnings!?
src/windows/models/files_model.py:147: log.warning("Couldn't remove {} from model!".format(delete_file_id)) src/windows/models/files_model.py:352: log.warning("Failed to import {}: {}".format(filepath, ex))
Again, these involve potential user data issues so that's somewhat reasonable.
src/windows/main_window.py:1118: log.warning("######## RENUMBERING TRACKS ########")
Heh. That's mine, and arguably it's evidence of my own hypocrisy. I'm breaking a lot of my own "rules" (which aren't really hard _rules_ rules) about what the user should be bothered with, here.
This code only runs when a very unusual condition is encountered, where it has to renumber all of the layers in the project data to make room between them, since our layer stacking operates solely based on numbering: A higher-numbered layer is on top of all lower-numbered layers. So, when inserting a new track between two others, if the numbering has gotten compressed so much that they're numerically adjacent, renumber_all_layers is called to... well, do exactly what it says on the tin. Which means updating the _entire_ project-data structure (since each item on the timeline has its layer number stored with it, so renumbering means updating _every_ child node as well.) Since that's a scary operation with potential to do massive damage if I screwed it up in any way, I first announce my intentions with this warning. That way, at least the user will know who to blame for their scrambled data.
src/windows/main_window.py:1220: log.warning("Could not find track {}: {}".format(selected_layer_num, ex)) src/windows/main_window.py:1267: log.warning("Could not find track {}: {}".format(selected_layer_num, ex)) src/windows/main_window.py:1943: log.warning("Couldn't find current file for properties window")
A request was made to add a new track above/below an existing one, or preview a media file... that no longer exists. Possible program logic error or invalid state that went undetected.
src/windows/main_window.py:2876: log.warning('Failed to connect to Unity launcher (Linux only) for updating export progress.')
OMFG debug.
src/windows/export.py:303: log.warning("Invalid framerate detected, not sending it to libopenshot: %s" % fps_double) src/windows/export.py:695: log.warning('Failed to convert bitrate string to bytes: %s' % BitRateString)
Issues parsing the export parameters, so yeah things the user should be aware of, and may even be responsible for (if they entered bad data).
log.error
src/classes/exporters/final_cut_pro.py:138: log.error('No track object found with number: %s' % track.get("number")) src/classes/exporters/final_cut_pro.py:232: log.error("Error writing XML export: {}".format(str(inst))) src/classes/exporters/edl.py:78: log.error('No track object found with number: %s' % track.get("number"))
Problems generating the output file requested by the user, so they deserve to know why.
src/classes/app.py:94: log.error('OpenShotApp::Import Error: %s' % str(ex)) src/classes/app.py:100: log.error('OpenShotApp::Init Error: %s' % str(ex))
Issues with access to internal application components. Will probably terminate the session, but not likely something the user can correct themselves. Still, heck maybe these should even be log.critical.
src/classes/app.py:178: log.error('Failed to create PERMISSION/test.osp file (likely permissions error): %s' % TEST_PATH_FILE)
Interference with our ability to write to the user's settings directory, which we also use as a session cache so that's going to become their problem very quickly.
src/classes/app.py:203: log.error("Error setting Ubuntu-R.ttf QFont: %s" % str(ex))
FFFFFFFFFFFFFFFFF—... ... ... debug, although arguably the log shouldn't exist because we shouldn't even be trying to do the thing that failed (overriding the system default UI font with our own, arbitrarily) in the first place.
src/classes/app.py:276: log.error("Couldn't save user settings on exit.\n{}".format(ex))
Again, definitely going to become the user's problem.
src/classes/project_data.py:85: log.error("Unexpected key part type: {}".format(type(key_part).__name__)) src/classes/project_data.py:167: log.error("Unexpected key part type: {}".format(type(key_part).__name__))
Possible corrupt user data.
src/classes/project_data.py:302: log.error("Failed to parse file '%s' as a profile: %s" % (profile_path, e)) src/classes/project_data.py:539: log.error(msg) src/classes/project_data.py:699: log.error(msg) src/classes/project_data.py:895: log.error("Error while moving temp paths to project assets folder {}: {}".format(asset_path, ex)) src/classes/settings.py:98: log.error("Error loading settings file: %s" % ex) src/classes/assets.py:75: log.error("Error while getting/creating asset folder {}: {}".format(asset_path, ex)) src/classes/json_data.py:193: log.error(str(ex)) src/classes/json_data.py:197: log.error(msg) src/classes/json_data.py:214: log.error(msg) src/classes/json_data.py:257: log.error("Error while converting relative paths to absolute paths: %s" % str(ex)) src/classes/json_data.py:332: log.error("Error while converting absolute paths to relative paths: %s" % str(ex)) src/classes/json_data.py:367: log.error("Couldn't write to backup file {}: {}".format(backup_file, ex))
More in that same vein.
```
src/classes/metrics.py:68: log.error("Error determining OS version in metrics.py")
src/classes/metrics.py:172: log.error("Failed to Track metric: %s" % (Ex))
src/classes/metrics.py:200: log.error("Failed to Track exception: %s" % (Ex))
Things that are in no way the user's concern. Debug, warning, warning, at most.
...I think I've hit my limit at this point, if you have specific questions about any of the rest feel free to point me at those particular parts.
I'm _certain_ this was way more than you needed or perhaps even wanted, hopefully it's somehow helpful though.
ferdnyc
on 9 Sep 2020
Wow, this is amazing! Thank you so much already! (I'm only 25% through so far; it's late here, but I am looking forward to read the rest tomorrow!
because we have Windows users for whom logging is effectively useless
Oh, that is interesting. Why that?
MartinThoma
on 9 Sep 2020
because we have Windows users for whom logging is effectively useless
Oh, that is interesting. Why that?
Well, for the longest time they had no way to run OpenShot the way Linux users could, launched from a terminal with the log output displayed "real-time" on stdout.
(They actually _do_ have a WAY to do that, now, because at some point I realized we could be building a console version of the application launcher alongside the GUI version, for the Windows packaging. So now we do, and that's included in the application folder as openshot-qt-cli.exe. But it's intentionally undocumented, so it's not really an avenue open to general users.)
Which means the logs' only visibility to Windows users is if they choose to look at the logfile in C:\Users\username\.openshot_qtopenshot-qt.log, and they generally just _don't_. They get the error messages we display to them via QMessageBox popups; in cases of fatal Python crashes, the cx_Freeze Windows wrapper binary will typically show a crash dialog displaying a traceback; and that's it. Anything else is invisible to them.
ferdnyc
on 10 Sep 2020
Thank you for helping me :hugs:
You pointed out that some log levels should be different. Should I make a PR and change them? Or should I close this issue directly?
MartinThoma
on 15 Sep 2020
@MartinThoma Happy to help!
If you're satisfied (you've gotten the answers you need), feel free to close the issue, absolutely.
If you're willing to take the time to put together a PR to fix those log levels, that'd be great. We definitely appreciate any help. Don't feel like you're at all obligated or expected to do that, though.
ferdnyc
on 16 Sep 2020
Thank you again for answering my questions - this one can be closed now :-)
MartinThoma
on 26 Sep 2020
Ah, I didn't realize the issue wasn't tagged in #3724; I assumed when I merged that PR, this had auto-closed. Actually _checking_ probably would've been the smarter approach... :roll_eyes:
ferdnyc
on 26 Sep 2020
Related issues
Geoff0627
·
3Comments
audioclown
·
3Comments
Obed9
·
3Comments
Sefran007
·
3Comments
LadyReader
·
3Comments