[orca/gnome-3-34] Tweak debugging output

[Joanmarie Diggs <joanied src gnome org>]

commit 2b62c8f0c424aa038ea8a102d2f69384b7770e5c
Author: Joanmarie Diggs <jdiggs igalia com>
Date:   Mon Feb 3 14:53:38 2020 -0500

    Tweak debugging output

 src/orca/braille.py                      | 4 ++--
 src/orca/debug.py                        | 8 +++++---
 src/orca/event_manager.py                | 2 +-
 src/orca/generator.py                    | 8 ++++----
 src/orca/script.py                       | 2 +-
 src/orca/scripts/web/speech_generator.py | 4 ++--
 6 files changed, 15 insertions(+), 13 deletions(-)
---
diff --git a/src/orca/braille.py b/src/orca/braille.py
index 966ca77aa..331e97180 100644
--- a/src/orca/braille.py
+++ b/src/orca/braille.py
@@ -1208,12 +1208,12 @@ def refresh(panToCursor=True,
         cursorCell += 1 # Normalize to 1-based offset
 
     logLine = "BRAILLE LINE:  '%s'" % string
-    debug.println(debug.LEVEL_INFO, logLine)
+    debug.println(debug.LEVEL_INFO, logLine, True)
     log.info(logLine)
 
     logLine = "     VISIBLE:  '%s', cursor=%d" % \
                     (string[startPos:endPos], cursorCell)
-    debug.println(debug.LEVEL_INFO, logLine)
+    debug.println(debug.LEVEL_INFO, logLine, True)
     log.info(logLine)
 
     substring = string[startPos:endPos]
diff --git a/src/orca/debug.py b/src/orca/debug.py
index 2feb32275..3d6d08016 100644
--- a/src/orca/debug.py
+++ b/src/orca/debug.py
@@ -29,13 +29,14 @@ __copyright__ = "Copyright (c) 2005-2008 Sun Microsystems Inc."
 __license__   = "LGPL"
 
 import inspect
-import time
 import traceback
 import os
 import pyatspi
 import subprocess
 import sys
 
+from datetime import datetime
+
 # Used to turn off all debugging.
 #
 LEVEL_OFF = 10000
@@ -208,7 +209,8 @@ def println(level, text="", timestamp=False):
     if level >= debugLevel:
         text = text.replace("\ufffc", "[OBJ]")
         if timestamp:
-            text = "%s - %s" % (time.strftime("%H:%M:%S"), text)
+            text = text.replace("\n", "\n%s" % (" " * 18))
+            text = "%s - %s" % (datetime.now().strftime("%H:%M:%S.%f"), text)
         if debugFile:
             try:
                 debugFile.writelines([text, "\n"])
@@ -273,7 +275,7 @@ def printObjectEvent(level, event, sourceInfo=None, timestamp=False):
     println(level, text, timestamp)
 
     if sourceInfo:
-        println(level, "             %s" % sourceInfo, timestamp)
+        println(level, "%s%s" % (' ' * 18, sourceInfo), timestamp)
 
 def printInputEvent(level, string, timestamp=False):
     """Prints out an input event.  The given level may be overridden
diff --git a/src/orca/event_manager.py b/src/orca/event_manager.py
index cbc513611..05a76b063 100644
--- a/src/orca/event_manager.py
+++ b/src/orca/event_manager.py
@@ -734,7 +734,7 @@ class EventManager:
 
         if not debug.eventDebugFilter or debug.eventDebugFilter.match(eType) \
            and not eType.startswith("mouse:"):
-            debug.printDetails(debug.LEVEL_INFO, ' ' * 11, event.source)
+            debug.printDetails(debug.LEVEL_INFO, ' ' * 18, event.source)
 
         script = self._getScriptForEvent(event)
         if not script:
diff --git a/src/orca/generator.py b/src/orca/generator.py
index 46e2b140e..06c1837bf 100644
--- a/src/orca/generator.py
+++ b/src/orca/generator.py
@@ -254,18 +254,18 @@ class Generator:
                     globalsDict[arg] = self._methodsDict[arg](obj, **args)
                     duration = "%.4f" % (time.time() - currentTime)
                     debug.println(debug.LEVEL_ALL,
-                                  "           GENERATION TIME: %s  ---->  %s=%s" \
-                                  % (duration, arg, repr(globalsDict[arg])))
+                                  "%sGENERATION TIME: %s  ---->  %s=%s" \
+                                  % (' ' * 18, duration, arg, repr(globalsDict[arg])))
 
         except:
             debug.printException(debug.LEVEL_SEVERE)
             result = []
 
         duration = "%.4f" % (time.time() - startTime)
-        debug.println(debug.LEVEL_ALL, "           COMPLETION TIME: %s" % duration)
+        debug.println(debug.LEVEL_ALL, "%sCOMPLETION TIME: %s" % (' ' * 18, duration))
         debug.println(debug.LEVEL_ALL, "%s GENERATOR: Results:" % self._mode.upper(), True)
         for element in result:
-            debug.println(debug.LEVEL_ALL, "           %s" % element)
+            debug.println(debug.LEVEL_ALL, "%s%s" % (' ' * 18, element))
 
         if args.get('isProgressBarUpdate') and result:
             self.setProgressBarUpdateTimeAndValue(obj)
diff --git a/src/orca/script.py b/src/orca/script.py
index 2ebb6da3c..a86757544 100644
--- a/src/orca/script.py
+++ b/src/orca/script.py
@@ -373,7 +373,7 @@ class Script:
             reason = "appears to be duplicate state-changed event"
 
         if skip:
-            eventDetails = '           %s' % str(cachedEvent).replace('\t', ' ' * 11)
+            eventDetails = '        %s' % str(cachedEvent).replace('\t', ' ' * 8)
             msg = 'SCRIPT: Skipping object event due to %s\n%s' % (reason, eventDetails)
             debug.println(debug.LEVEL_INFO, msg, True)
 
diff --git a/src/orca/scripts/web/speech_generator.py b/src/orca/scripts/web/speech_generator.py
index ce3fa2173..51e6e31b8 100644
--- a/src/orca/scripts/web/speech_generator.py
+++ b/src/orca/scripts/web/speech_generator.py
@@ -593,9 +593,9 @@ class SpeechGenerator(speech_generator.SpeechGenerator):
 
         self._restoreRole(oldRole, args)
         msg = "WEB: Speech generation for document object %s complete:" % obj
-        debug.println(debug.LEVEL_INFO, msg)
+        debug.println(debug.LEVEL_INFO, msg, True)
         for element in result:
-            debug.println(debug.LEVEL_ALL, "           %s" % element)
+            debug.println(debug.LEVEL_ALL, "%s%s" % (' ' * 18, element))
 
         return result