[orca] Still more debugging output to track down an issue launching Orca

[Joanmarie Diggs <joanied src gnome org>]

commit fb70ed94c72226d6ba462aa2ec2d30789b486577
Author: Joanmarie Diggs <jdiggs igalia com>
Date:   Fri Jan 29 15:07:00 2021 +0100

    Still more debugging output to track down an issue launching Orca

 src/orca/orca.py             | 10 ++++++--
 src/orca/orca_bin.py.in      |  4 ++++
 src/orca/settings_manager.py | 54 ++++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 66 insertions(+), 2 deletions(-)
---
diff --git a/src/orca/orca.py b/src/orca/orca.py
index 41781c6da..2da51c385 100644
--- a/src/orca/orca.py
+++ b/src/orca/orca.py
@@ -600,8 +600,7 @@ def init(registry):
     return True
 
 def start(registry, cacheValues):
-    """Starts Orca.
-    """
+    """Starts Orca."""
 
     debug.println(debug.LEVEL_INFO, 'ORCA: Starting', True)
 
@@ -755,6 +754,8 @@ def main(cacheValues=True):
     an exit code of 0 means normal completion and an exit code of 50
     means Orca exited because of a hang."""
 
+    debug.println(debug.LEVEL_INFO, "ORCA: Launching (main).", True)
+
     if debug.debugFile and os.path.exists(debug.debugFile.name):
         faulthandler.enable(file=debug.debugFile, all_threads=False)
     else:
@@ -772,10 +773,13 @@ def main(cacheValues=True):
     signal.signal(signal.SIGQUIT, shutdownOnSignal)
     signal.signal(signal.SIGSEGV, crashOnSignal)
 
+    debug.println(debug.LEVEL_INFO, "ORCA: Enabling accessibility (if needed).", True)
     if not _settingsManager.isAccessibilityEnabled():
         _settingsManager.setAccessibility(True)
 
+    debug.println(debug.LEVEL_INFO, "ORCA: Initializing ATSPI registry.", True)
     init(pyatspi.Registry)
+    debug.println(debug.LEVEL_INFO, "ORCA: ATSPI registry initialized.", True)
 
     try:
         message = messages.START_ORCA
@@ -805,8 +809,10 @@ def main(cacheValues=True):
                 _scriptManager.setActiveScript(script, "Found focused object.")
 
     try:
+        debug.println(debug.LEVEL_INFO, "ORCA: Starting ATSPI registry.", True)
         start(pyatspi.Registry, cacheValues) # waits until we stop the registry
     except:
+        debug.println(debug.LEVEL_SEVERE, "ORCA: Exception starting ATSPI registry.", True)
         die(EXIT_CODE_HANG)
     return 0
 
diff --git a/src/orca/orca_bin.py.in b/src/orca/orca_bin.py.in
index aa9fb82ef..6cf8523ca 100644
--- a/src/orca/orca_bin.py.in
+++ b/src/orca/orca_bin.py.in
@@ -243,11 +243,14 @@ def main():
         print(messages.CLI_NO_DESKTOP_ERROR)
         return 1
 
+    debug.println(debug.LEVEL_INFO, "INFO: Preparing to launch.", True)
     manager = orca.getSettingsManager()
+
     if not manager:
         print(messages.CLI_SETTINGS_MANAGER_ERROR)
         return 1
 
+    debug.println(debug.LEVEL_INFO, "INFO: About to activate settings manager.", True)
     manager.activate(args.user_prefs, settingsDict)
     sys.path.insert(0, manager.getPrefsDir())
 
@@ -266,6 +269,7 @@ def main():
         print(messages.CLI_OTHER_ORCAS_ERROR)
         return 1
 
+    debug.println(debug.LEVEL_INFO, "INFO: About to launch Orca,", True)
     return orca.main()
 
 if __name__ == "__main__":
diff --git a/src/orca/settings_manager.py b/src/orca/settings_manager.py
index 74ace605f..f5a6763c1 100644
--- a/src/orca/settings_manager.py
+++ b/src/orca/settings_manager.py
@@ -292,15 +292,26 @@ class SettingsManager(object):
         profile and store them in the object's attributes.
         A profile can be passed as a parameter. This could be useful for
         change from one profile to another."""
+
+        msg = 'SETTINGS MANAGER: Loading settings for %s profile' % profile
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         if profile is None:
             profile = self.profile
         self.profileGeneral = self.getGeneralSettings(profile) or {}
         self.profilePronunciations = self.getPronunciations(profile) or {}
         self.profileKeybindings = self.getKeybindings(profile) or {}
 
+        msg = 'SETTINGS MANAGER: Settings for %s profile loaded' % profile
+        debug.println(debug.LEVEL_INFO, msg, True)
+
     def _mergeSettings(self):
         """Update the changed values on the profile settings
         over the current and active settings"""
+
+        msg = 'SETTINGS MANAGER: Merging settings.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         self.profileGeneral.update(self._appGeneral)
         self.profilePronunciations.update(self._appPronunciations)
         self.profileKeybindings.update(self._appKeybindings)
@@ -309,6 +320,9 @@ class SettingsManager(object):
         self.pronunciations.update(self.profilePronunciations)
         self.keybindings.update(self.profileKeybindings)
 
+        msg = 'SETTINGS MANAGER: Settings merged.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
     def _enableAccessibility(self):
         """Enables the GNOME accessibility flag.  Users need to log out and
         then back in for this to take effect.
@@ -402,16 +416,25 @@ class SettingsManager(object):
             orca_i18n.setLocaleForMessages(newVoiceLocale)
             orca_i18n.setLocaleForGUI(newVoiceLocale)
 
+        msg = 'SETTINGS MANAGER: Profile set to: %s' % profile
+        debug.println(debug.LEVEL_INFO, msg, True)
+
     def removeProfile(self, profile):
         self._backend.removeProfile(profile)
 
     def _setSettingsRuntime(self, settingsDict):
+        msg = 'SETTINGS MANAGER: Setting runtime settings.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         for key, value in settingsDict.items():
             setattr(settings, str(key), value)
         self._getCustomizedSettings()
         for key, value in self.customizedSettings.items():
             setattr(settings, str(key), value)
 
+        msg = 'SETTINGS MANAGER: Runtime settings set.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
     def _setPronunciationsRuntime(self, pronunciationsDict):
         pronunciation_dict.pronunciation_dict = {}
         for key, value in pronunciationsDict.values():
@@ -439,6 +462,10 @@ class SettingsManager(object):
     def _setProfileGeneral(self, general):
         """Set the changed general settings from the defaults' ones
         as the profile's."""
+
+        msg = 'SETTINGS MANAGER: Setting general settings for profile'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         self.profileGeneral = {}
 
         for key, value in general.items():
@@ -451,18 +478,35 @@ class SettingsManager(object):
             elif self.general.get(key) != value:
                 self.profileGeneral[key] = value
 
+        msg = 'SETTINGS MANAGER: General settings for profile set'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
     def _setProfilePronunciations(self, pronunciations):
         """Set the changed pronunciations settings from the defaults' ones
         as the profile's."""
+
+        msg = 'SETTINGS MANAGER: Setting pronunciation settings for profile.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         self.profilePronunciations = self.defaultPronunciations.copy()
         self.profilePronunciations.update(pronunciations)
 
+        msg = 'SETTINGS MANAGER: Pronunciation settings for profile set.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
     def _setProfileKeybindings(self, keybindings):
         """Set the changed keybindings settings from the defaults' ones
         as the profile's."""
+
+        msg = 'SETTINGS MANAGER: Setting keybindings settings for profile.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         self.profileKeybindings = self.defaultKeybindings.copy()
         self.profileKeybindings.update(keybindings)
 
+        msg = 'SETTINGS MANAGER: Keybindings settings for profile set.'
+        debug.println(debug.LEVEL_INFO, msg, True)
+
     def _saveAppSettings(self, appName, general, pronunciations, keybindings):
         appGeneral = {}
         profileGeneral = self.getGeneralSettings(self.profile)
@@ -491,6 +535,9 @@ class SettingsManager(object):
     def saveSettings(self, script, general, pronunciations, keybindings):
         """Save the settings provided for the script provided."""
 
+        msg = 'SETTINGS MANAGER: Saving settings for %s (app: %s)' % (script, script.app)
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         app = script.app
         if app:
             self._saveAppSettings(app.name, general, pronunciations, keybindings)
@@ -510,10 +557,17 @@ class SettingsManager(object):
         self._setProfilePronunciations(pronunciations)
         self._setProfileKeybindings(keybindings)
 
+        msg = 'SETTINGS MANAGER: Saving for backend %s' % self._backend
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         self._backend.saveProfileSettings(self.profile,
                                           self.profileGeneral,
                                           self.profilePronunciations,
                                           self.profileKeybindings)
+
+        msg = 'SETTINGS MANAGER: Settings for %s (app: %s) saved' % (script, script.app)
+        debug.println(debug.LEVEL_INFO, msg, True)
+
         return self._enableAccessibility()
 
     def _adjustBindingTupleValues(self, bindingTuple):