WIP: Reduce logspam

src/classes/app.py

@@ -123,7 +123,6 @@ def __init__(self, *args, mode=None):
         if self.settings.get("theme") != "No Theme":
             # Load embedded font
             try:
-                log.info("Setting font to %s" % os.path.join(info.IMAGES_PATH, "fonts", "Ubuntu-R.ttf"))
                 font_id = QFontDatabase.addApplicationFont(os.path.join(info.IMAGES_PATH, "fonts", "Ubuntu-R.ttf"))
                 font_family = QFontDatabase.applicationFontFamilies(font_id)[0]
                 font = QFont(font_family)
@@ -135,7 +134,6 @@ def __init__(self, *args, mode=None):
         # Set Experimental Dark Theme
         if self.settings.get("theme") == "Humanity: Dark":
             # Only set if dark theme selected
-            log.info("Setting custom dark theme")
             self.setStyle(QStyleFactory.create("Fusion"))
 
             darkPalette = self.palette()
@@ -163,7 +161,7 @@ def __init__(self, *args, mode=None):
         self.updates.reset()
         self.window.updateStatusChanged(False, False)
 
-        log.info('Process command-line arguments: %s' % args)
+        log.debug('Process command-line arguments: %s' % args)
         if len(args[0]) == 2:
             path = args[0][1]
             if ".osp" in path:

src/classes/logger.py

@@ -50,29 +50,47 @@ def errors(self):
         pass
 
 # Initialize logging module, give basic formats and level we want to report
-logging.basicConfig(format="%(module)12s:%(levelname)s %(message)s",
-                    datefmt='%H:%M:%S',
-                    level=logging.INFO)
+#logging.basicConfig(format="%(module)12s:%(levelname)s %(message)s",
+#                    datefmt='%H:%M:%S',
+#                    level=logging.NOTSET)
 
 # Create a formatter
 formatter = logging.Formatter('%(module)12s:%(levelname)s %(message)s')
 
 # Get logger instance & set level
 log = logging.getLogger('OpenShot')
-log.setLevel(logging.INFO)
+log.setLevel(logging.DEBUG)
+
+# create console handler, set level to INFO, add formatter
+ch = logging.StreamHandler()
+ch.setLevel(logging.INFO)
+ch.setFormatter(formatter)
+log.addHandler(ch)
 
 # Add rotation file handler
 fh = RotatingFileHandler(
     os.path.join(info.USER_PATH, 'openshot-qt.log'), encoding="utf-8", maxBytes=25*1024*1024, backupCount=3)
+fh.setLevel(logging.INFO)
 fh.setFormatter(formatter)
 log.addHandler(fh)
 
 def reroute_output():
     """Route stdout and stderr to logger (custom handler)"""
-    if not getattr(sys, 'frozen', False):
-        so = StreamToLogger(log, logging.INFO)
+    if True or not getattr(sys, 'frozen', False):
+        so = StreamToLogger(log, logging.DEBUG)
         sys.stdout = so
 
         se = StreamToLogger(log, logging.ERROR)
         sys.stderr = se
 
+        print("Redirected console output to logger")
+
+def debug_logging(enable=True):
+    """Enable/disable debug logging to the logfile"""
+    if enable:
+        fh.setLevel(logging.DEBUG)
+        #log.info("Enabled DEBUG message logging")
+    else:
+        fh.setLevel(logging.INFO)
+        #log.info("Disabled DEBUG message logging")
+

src/classes/logger_libopenshot.py

@@ -27,7 +27,7 @@
 
 from threading import Thread
 from classes import settings, info
-from classes.logger import log
+from classes.logger import log, debug_logging
 import openshot
 import os
 import zmq
@@ -55,8 +55,9 @@ def run(self):
         # Set filepath for ZmqLogger also
         openshot.ZmqLogger.Instance().Path(os.path.join(info.USER_PATH, 'libopenshot.log'))
 
-        # Enable / Disable logger
+        # Enable / Disable debug loggers
         openshot.ZmqLogger.Instance().Enable(debug_enabled)
+        debug_logging(debug_enabled)
 
         # Socket to talk to server
         context = zmq.Context()
@@ -80,4 +81,4 @@ def run(self):
 
             # Log the message (if any)
             if msg:
-                log.info(msg.strip().decode('UTF-8'))
+                log.debug(msg.strip().decode('UTF-8'))

src/classes/project_data.py

@@ -141,7 +141,7 @@ def set(self, key, value):
     def _set(self, key, values=None, add=False, partial_update=False, remove=False):
         """ Store setting, but adding isn't allowed. All possible settings must be in default settings file. """
 
-        log.info(
+        log.debug(
             "_set key: {} values: {} add: {} partial: {} remove: {}".format(key, values, add, partial_update, remove))
         parent, my_key = None, ""
 
@@ -473,7 +473,7 @@ def read_legacy_project_file(self, file_path):
                                 file = file_lookup[clip.file_object.unique_id]
                             else:
                                 # Skip missing file
-                                log.info("Skipping importing missing file: %s" % clip.file_object.unique_id)
+                                log.info("Clip contains missing file, skipped: {}".format(clip.file_object.unique_id))
                                 continue
 
                             # Create clip
@@ -633,11 +633,9 @@ def upgrade_project_data_structures(self):
         openshot_version = self._data["version"]["openshot-qt"]
         libopenshot_version = self._data["version"]["libopenshot"]
 
-        log.info(openshot_version)
-        log.info(libopenshot_version)
-
         if openshot_version == "0.0.0":
             # If version = 0.0.0, this is the beta of OpenShot
+            log.info('Upgrading OpenShot 0.0.0 project data')
             # Fix alpha values (they are now flipped)
             for clip in self._data["clips"]:
                 # Loop through keyframes for alpha
@@ -651,6 +649,7 @@ def upgrade_project_data_structures(self):
                         point["handle_right"]["Y"] = 1.0 - point["handle_right"]["Y"]
 
         elif openshot_version <= "2.1.0-dev":
+            log.info('Upgrading OpenShot 2.1.0-dev project data')
             # Fix handle_left and handle_right coordinates and default to ease in/out bezier curve
             # using the new percent based keyframes
             for clip_type in ["clips", "effects"]:
@@ -737,8 +736,6 @@ def move_temp_paths_to_project_folder(self, file_path):
 
                 # Find any temp BLENDER file paths
                 if info.BLENDER_PATH in path or info.ASSETS_PATH in path:
-                    log.info("Temp blender file path detected in file")
-
                     # Get folder of file
                     folder_path, file_name = os.path.split(path)
                     parent_path, folder_name = os.path.split(folder_path)
@@ -770,8 +767,6 @@ def move_temp_paths_to_project_folder(self, file_path):
 
                 # Find any temp BLENDER file paths
                 if info.BLENDER_PATH in path or info.ASSETS_PATH in path:
-                    log.info("Temp blender file path detected in clip")
-
                     # Get folder of file
                     folder_path, file_name = os.path.split(path)
                     parent_path, folder_name = os.path.split(folder_path)
@@ -787,8 +782,6 @@ def move_temp_paths_to_project_folder(self, file_path):
 
                 # Find any temp BLENDER file paths
                 if info.BLENDER_PATH in path or info.ASSETS_PATH in path:
-                    log.info("Temp blender file path detected in clip thumbnail")
-
                     # Get folder of file
                     folder_path, file_name = os.path.split(path)
                     parent_path, folder_name = os.path.split(folder_path)
@@ -911,35 +904,35 @@ def check_if_paths_are_valid(self):
             path = file["path"]
             parent_path, file_name_with_ext = os.path.split(path)
             while not os.path.exists(path) and "%" not in path:
-                # File already exists! Prompt user to find missing file
+                # Prompt user to find missing media file
                 QMessageBox.warning(None, _("Missing File (%s)") % file["id"], _("%s cannot be found.") % file_name_with_ext)
                 starting_folder = QFileDialog.getExistingDirectory(None, _("Find directory that contains: %s" % file_name_with_ext), starting_folder)
-                log.info("Missing folder chosen by user: %s" % starting_folder)
                 if starting_folder:
                     # Update file path and import_path
                     path = os.path.join(starting_folder, file_name_with_ext)
                     file["path"] = path
                     get_app().updates.update(["import_path"], os.path.dirname(path))
+                    log.debug('Updated File path: {}'.format(path))
                 else:
-                    log.info('Removed missing file: %s' % file_name_with_ext)
                     self._data["files"].remove(file)
+                    log.info('Removed missing file: {}'.format(file_name_with_ext))
                     break
 
         # Loop through each clip (in reverse order)
         for clip in reversed(self._data["clips"]):
             path = clip["reader"]["path"]
             parent_path, file_name_with_ext = os.path.split(path)
             while not os.path.exists(path) and "%" not in path:
-                # Clip already exists! Prompt user to find missing file
-                QMessageBox.warning(None, _("Missing File in Clip (%s)") % clip["id"], _("%s cannot be found.") % file_name_with_ext)
+                # Prompt user to find missing file for Clip
+                QMessageBox.warning(None, _("Missing file in Clip (%s)") % clip["id"], _("%s cannot be found.") % file_name_with_ext)
                 starting_folder = QFileDialog.getExistingDirectory(None, _("Find directory that contains: %s" % file_name_with_ext), starting_folder)
-                log.info("Missing folder chosen by user: %s" % starting_folder)
                 if starting_folder:
                     # Update clip path
                     path = os.path.join(starting_folder, file_name_with_ext)
                     clip["reader"]["path"] = path
+                    log.debug('Updated file path for Clip: {}'.format(path))
                 else:
-                    log.info('Removed missing clip: %s' % file_name_with_ext)
+                    log.info('Removed missing Clip: {}'.format(file_name_with_ext))
                     self._data["clips"].remove(clip)
                     break
 

src/classes/timeline.py

@@ -103,16 +103,13 @@ def changed(self, action):
                 self.timeline.ApplyJsonDiff(action.json(is_array=True))
 
         except Exception as e:
-            log.info("Error applying JSON to timeline object in libopenshot: %s. %s" % (e, action.json(is_array=True)))
+            log.error("Error applying JSON to timeline object in libopenshot: %s. %s" % (e, action.json(is_array=True)))
 
     def MaxSizeChangedCB(self, new_size):
         """Callback for max sized change (i.e. max size of video widget)"""
         while not self.window.initialized:
-            log.info('Waiting for main window to initialize before calling SetMaxSize')
             time.sleep(0.5)
 
-        log.info("Adjusting max size of preview image: %s" % new_size)
-
         # Clear timeline preview cache (since our video size has changed)
         self.timeline.ClearAllCache()
 

src/classes/ui_util.py

@@ -129,8 +129,6 @@ def get_icon(theme_name):
 
     if theme_name:
         has_icon = QIcon.hasThemeIcon(theme_name)
-        if not has_icon:
-            log.warn('Icon theme {} not found. Will use backup icon.'.format(theme_name))
         fallback_icon, fallback_path = get_default_icon(theme_name)
         # log.info('Fallback icon path for {} is {}'.format(theme_name, fallback_path))
         if has_icon or fallback_icon:
@@ -196,13 +194,11 @@ def connect_auto_events(window, elem, name):
         func_name = name + "_trigger"
         if hasattr(window, func_name) and callable(getattr(window, func_name)):
             func = getattr(window, func_name)
-            log.info("Binding event {}:{}".format(window.objectName(), func_name))
             elem.triggered.connect(getattr(window, func_name))
     if hasattr(elem, 'click'):
         func_name = name + "_click"
         if hasattr(window, func_name) and callable(getattr(window, func_name)):
             func = getattr(window, func_name)
-            log.info("Binding event {}:{}".format(window.objectName(), func_name))
             elem.clicked.connect(getattr(window, func_name))
 
 

src/timeline/app.js

@@ -53,7 +53,7 @@ var App = angular.module('openshot-timeline', ['ui.bootstrap','ngAnimate']);
 
 	// Check for Qt Integration
 	if(typeof timeline != 'undefined') {
-		timeline.qt_log("Qt Found!");
+		timeline.qt_debug("Qt Found!");
 		$('body').scope().EnableQt();
 		timeline.page_ready();
 	} else {

src/timeline/js/controllers.js

@@ -252,7 +252,7 @@ App.controller('TimelineCtrl',function($scope) {
   $scope.Qt = false;
   $scope.EnableQt = function() { 
 	  	$scope.Qt = true;
-	  	timeline.qt_log("$scope.Qt = true;"); 
+	  	timeline.qt_debug("$scope.Qt = true;");
   };
 
   // Move the playhead to a specific time
@@ -431,7 +431,7 @@ App.controller('TimelineCtrl',function($scope) {
 				$scope.project.clips[clip_index].audio_data = audio_data;
 				$scope.project.clips[clip_index].show_audio = true;
 			});
-			timeline.qt_log("Audio data successful set on clip JSON");
+			timeline.qt_debug("Audio data successful set on clip JSON");
 			break;
 		}
 
@@ -724,7 +724,7 @@ App.controller('TimelineCtrl',function($scope) {
  // Show clip context menu
  $scope.ShowClipMenu = function(clip_id, event) {
  	if ($scope.Qt) {
-	 	timeline.qt_log("$scope.ShowClipMenu");
+	 	timeline.qt_debug("$scope.ShowClipMenu");
 	 	$scope.SelectClip(clip_id, false, event);
 	 	timeline.ShowClipMenu(clip_id);
  	}
@@ -733,15 +733,15 @@ App.controller('TimelineCtrl',function($scope) {
  // Show clip context menu
  $scope.ShowEffectMenu = function(effect_id) {
  	if ($scope.Qt) {
-	 	timeline.qt_log("$scope.ShowEffectMenu");
+	 	timeline.qt_debug("$scope.ShowEffectMenu");
 	 	timeline.ShowEffectMenu(effect_id);
  	}
  };
 
  // Show transition context menu
  $scope.ShowTransitionMenu = function(tran_id, event) {
  	if ($scope.Qt) {
-	 	timeline.qt_log("$scope.ShowTransitionMenu");
+	 	timeline.qt_debug("$scope.ShowTransitionMenu");
 	 	$scope.SelectTransition(tran_id, false, event);
 	 	timeline.ShowTransitionMenu(tran_id);
  	}
@@ -750,23 +750,23 @@ App.controller('TimelineCtrl',function($scope) {
  // Show track context menu
  $scope.ShowTrackMenu = function(layer_id) {
  	if ($scope.Qt) {
-	 	timeline.qt_log("$scope.ShowTrackMenu");
+	 	timeline.qt_debug("$scope.ShowTrackMenu");
 	 	timeline.ShowTrackMenu(layer_id);
  	}
  };
 
  // Show marker context menu
  $scope.ShowMarkerMenu = function(marker_id) {
  	if ($scope.Qt) {
-	 	timeline.qt_log("$scope.ShowMarkerMenu");
+	 	timeline.qt_debug("$scope.ShowMarkerMenu");
 	 	timeline.ShowMarkerMenu(marker_id);
  	}
  };
 
   // Show playhead context menu
  $scope.ShowPlayheadMenu = function(position) {
  	if ($scope.Qt) {
-	 	timeline.qt_log("$scope.ShowPlayheadMenu");
+	 	timeline.qt_debug("$scope.ShowPlayheadMenu");
 	 	timeline.ShowPlayheadMenu(position);
 	 }
  };
@@ -958,7 +958,7 @@ $scope.SetTrackLabel = function (label){
  $scope.UpdateLayerIndex = function(){
 
 	 if ($scope.Qt)
-		 timeline.qt_log('UpdateLayerIndex');
+		 timeline.qt_debug('UpdateLayerIndex');
 
 	var vert_scroll_offset = $("#scrolling_tracks").scrollTop();
 	var horz_scroll_offset = $("#scrolling_tracks").scrollLeft();
@@ -994,7 +994,7 @@ $scope.SetTrackLabel = function (label){
 		 return;
 
 	 if ($scope.Qt)
-		 timeline.qt_log('SortItems');
+		 timeline.qt_debug('SortItems');
 
 	 $scope.$apply(function(){
 		 // Sort by position second