Migrate Taskmaster tracing to use python logging

4 files changed, 128 insertions, 64 deletions

diff --git a/SCons/Script/Main.py b/SCons/Script/Main.py
index 22042f5..b902842 100644
--- a/SCons/Script/Main.py
+++ b/SCons/Script/Main.py
@@ -1291,23 +1291,12 @@ def _build_targets(fs, options, targets, target_top):
             """Leave the order of dependencies alone."""
             return dependencies
 
-    def tmtrace_cleanup(tfile):
-        tfile.close()
-
-    if options.taskmastertrace_file == '-':
-        tmtrace = sys.stdout
-    elif options.taskmastertrace_file:
-        tmtrace = open(options.taskmastertrace_file, 'w')
-        atexit.register(tmtrace_cleanup, tmtrace)
-    else:
-        tmtrace = None
-    taskmaster = SCons.Taskmaster.Taskmaster(nodes, task_class, order, tmtrace)
+    taskmaster = SCons.Taskmaster.Taskmaster(nodes, task_class, order, options.taskmastertrace_file)
 
     # Let the BuildTask objects get at the options to respond to the
     # various print_* settings, tree_printer list, etc.
     BuildTask.options = options
 
-
     is_pypy = platform.python_implementation() == 'PyPy'
     # As of 3.7, python removed support for threadless platforms.
     # See https://www.python.org/dev/peps/pep-0011/
diff --git a/SCons/Taskmaster/TaskmasterTests.py b/SCons/Taskmaster/TaskmasterTests.py
index f20fd71..2ff15f0 100644
--- a/SCons/Taskmaster/TaskmasterTests.py
+++ b/SCons/Taskmaster/TaskmasterTests.py
@@ -1241,10 +1241,19 @@ Task.postprocess():  node <executing  0   'n3'>
 
 Taskmaster: Looking for a node to evaluate
 Taskmaster: No candidate anymore.
-
 """
-        assert value == expect, value
-
+        v_split=value.split('\n')
+        e_split=expect.split('\n')
+        if len(v_split) != len(e_split):
+            print("different number of lines:%d %d"%(len(v_split), len(e_split)))
+
+        # breakpoint()
+        for v, e in zip(v_split, e_split):
+            # print("%s:%s"%(v,e))
+            if v != e:
+                print("\n[%s]\n[%s]" % (v, e))
+
+        assert value == expect, "Expected:\n%s\nGot:\n%s"%(expect, value)
 
 
 if __name__ == "__main__":
diff --git a/SCons/Taskmaster/__init__.py b/SCons/Taskmaster/__init__.py
index d571795..59b5886 100644
--- a/SCons/Taskmaster/__init__.py
+++ b/SCons/Taskmaster/__init__.py
@@ -46,14 +46,16 @@ Task
     The Taskmaster instantiates a Task object for each (set of)
     target(s) that it decides need to be evaluated and/or built.
 """
-
+import io
 import sys
 from abc import ABC, abstractmethod
 from itertools import chain
+import logging
 
 import SCons.Errors
 import SCons.Node
 import SCons.Warnings
+from SCons.Util import DispatchingFormatter
 
 StateString = SCons.Node.StateString
 NODE_NO_STATE = SCons.Node.no_state
@@ -71,6 +73,7 @@ print_prepare = False               # set by option --debug=prepare
 
 CollectStats = None
 
+
 class Stats:
     """
     A simple class for holding statistics about the disposition of a
@@ -92,6 +95,7 @@ class Stats:
         self.side_effects  = 0
         self.build  = 0
 
+
 StatsNodes = []
 
 fmt = "%(considered)3d "\
@@ -102,6 +106,7 @@ fmt = "%(considered)3d "\
       "%(side_effects)3d " \
       "%(build)3d "
 
+
 def dump_stats():
     for n in sorted(StatsNodes, key=lambda a: str(a)):
         print((fmt % n.attributes.stats.__dict__) + str(n))
@@ -125,6 +130,9 @@ class Task(ABC):
     these methods explicitly to update state, etc., rather than
     roll their own interaction with Taskmaster from scratch.
     """
+
+    LOGGER = None
+
     def __init__(self, tm, targets, top, node):
         self.tm = tm
         self.targets = targets
@@ -132,9 +140,10 @@ class Task(ABC):
         self.node = node
         self.exc_clear()
 
-    def trace_message(self, method, node, description='node'):
-        fmt = '%-20s %s %s\n'
-        return fmt % (method + ':', description, self.tm.trace_node(node))
+    def trace_message(self, node, description='node'):
+        # This grabs the name of the function which calls trace_message()
+        method_name=sys._getframe(1).f_code.co_name+"():"
+        Task.LOGGER.debug('%-15s %s %s' % (method_name, description, self.tm.tm_trace_node(node)))
 
     def display(self, message):
         """
@@ -159,7 +168,7 @@ class Task(ABC):
         """
         global print_prepare
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.prepare()', self.node))
+        if T: self.trace_message(self.node)
 
         # Now that it's the appropriate time, give the TaskMaster a
         # chance to raise any exceptions it encountered while preparing
@@ -213,7 +222,7 @@ class Task(ABC):
         prepare(), executed() or failed().
         """
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.execute()', self.node))
+        if T: self.trace_message(self.node)
 
         try:
             cached_targets = []
@@ -256,8 +265,7 @@ class Task(ABC):
         the Node's callback methods.
         """
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.executed_without_callbacks()',
-                                         self.node))
+        if T: self.trace_message(self.node)
 
         for t in self.targets:
             if t.get_state() == NODE_EXECUTING:
@@ -280,8 +288,7 @@ class Task(ABC):
         """
         global print_prepare
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.executed_with_callbacks()',
-                                         self.node))
+        if T: self.trace_message(self.node)
 
         for t in self.targets:
             if t.get_state() == NODE_EXECUTING:
@@ -322,7 +329,7 @@ class Task(ABC):
         nodes when using Configure().
         """
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.failed_stop()', self.node))
+        if T: self.trace_message(self.node)
 
         # Invoke will_not_build() to clean-up the pending children
         # list.
@@ -349,7 +356,7 @@ class Task(ABC):
         nodes when using Configure().
         """
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.failed_continue()', self.node))
+        if T: self.trace_message(self.node)
 
         self.tm.will_not_build(self.targets, lambda n: n.set_state(NODE_FAILED))
 
@@ -361,7 +368,7 @@ class Task(ABC):
         visited--the canonical example being the "scons -c" option.
         """
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.make_ready_all()', self.node))
+        if T: self.trace_message(self.node)
 
         self.out_of_date = self.targets[:]
         for t in self.targets:
@@ -379,8 +386,9 @@ class Task(ABC):
         """
         global print_prepare
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.make_ready_current()',
-                                         self.node))
+        if T:
+            T.log_handler.stream.write('\n') # Prefix message with new line. This is a hack
+            self.trace_message(self.node)
 
         self.out_of_date = []
         needs_executing = False
@@ -427,7 +435,7 @@ class Task(ABC):
         that can be put back on the candidates list.
         """
         T = self.tm.trace
-        if T: T.write(self.trace_message('Task.postprocess()', self.node))
+        if T: self.trace_message(self.node)
 
         # We may have built multiple targets, some of which may have
         # common parents waiting for this build.  Count up how many
@@ -444,9 +452,7 @@ class Task(ABC):
             # A node can only be in the pending_children set if it has
             # some waiting_parents.
             if t.waiting_parents:
-                if T: T.write(self.trace_message('Task.postprocess()',
-                                                 t,
-                                                 'removing'))
+                if T: self.trace_message(t, 'removing')
                 pending_children.discard(t)
             for p in t.waiting_parents:
                 parents[p] = parents.get(p, 0) + 1
@@ -473,9 +479,7 @@ class Task(ABC):
 
         for p, subtract in parents.items():
             p.ref_count = p.ref_count - subtract
-            if T: T.write(self.trace_message('Task.postprocess()',
-                                             p,
-                                             'adjusted parent ref count'))
+            if T: self.trace_message(p, 'adjusted parent ref count')
             if p.ref_count == 0:
                 self.tm.candidates.append(p)
 
@@ -604,9 +608,59 @@ class Taskmaster:
             order = lambda l: l
         self.order = order
         self.message = None
-        self.trace = trace
         self.next_candidate = self.find_next_candidate
         self.pending_children = set()
+        self.trace = False
+        self.configure_trace(trace)
+
+    def configure_trace(self, trace=None):
+        """
+        This handles the command line option --taskmastertrace=
+        It can be:
+        -           : output to stdout
+        <filename>  : output to a file
+        False/None  : Do not trace
+        """
+        if not trace:
+            self.trace = False
+            return
+
+        # TODO: May want to switch format to something like this.
+        # log_format = (
+        #     '%(relativeCreated)05dms'
+        #     ':%(relfilename)s'
+        #     ':%(funcName)s'
+        #     '#%(lineno)s'
+        #     ': %(message)s'
+        # )
+        tm_formatter = logging.Formatter('Taskmaster: %(message)s')
+        if isinstance(trace, io.StringIO):
+            log_handler = logging.StreamHandler(trace)
+        elif trace == '-':
+            log_handler = logging.StreamHandler(sys.stdout)
+        elif trace:
+            log_handler = logging.FileHandler(filename=trace)
+
+        logger = logging.getLogger('Taskmaster')
+        logger.setLevel(level=logging.DEBUG)
+        logger.addHandler(log_handler)
+        self.trace = logger
+
+        logger.log_handler = log_handler
+
+        # Now setup Task's logger.
+        tl = logging.getLogger("Task")
+        tl.setLevel(level=logging.DEBUG)
+        tl.addHandler(log_handler)
+        task_formatter = logging.Formatter('%(name)s.%(message)s')
+        Task.LOGGER = tl
+
+        log_handler.setFormatter(DispatchingFormatter({
+            'Taskmaster': tm_formatter,
+            'Task': task_formatter,
+        },
+            logging.Formatter('%(message)s')
+        ))
 
     def find_next_candidate(self):
         """
@@ -735,14 +789,13 @@ class Taskmaster:
             for p in n.waiting_parents:
                 assert p.ref_count > 0, (str(n), str(p), p.ref_count)
 
+    def tm_trace_message(self, message):
+        return 'Taskmaster: %s' % message
 
-    def trace_message(self, message):
-        return 'Taskmaster: %s\n' % message
-
-    def trace_node(self, node):
-        return '<%-10s %-3s %s>' % (StateString[node.get_state()],
+    def tm_trace_node(self, node):
+        return('<%-10s %-3s %s>' % (StateString[node.get_state()],
                                     node.ref_count,
-                                    repr(str(node)))
+                                    repr(str(node))))
 
     def _find_next_ready_node(self):
         """
@@ -769,12 +822,14 @@ class Taskmaster:
         self.ready_exc = None
 
         T = self.trace
-        if T: T.write('\n' + self.trace_message('Looking for a node to evaluate'))
+        if T:
+            T.log_handler.stream.write('\n')  # Prefix message with new line. This is a hack
+            self.trace.debug('Looking for a node to evaluate')
 
         while True:
             node = self.next_candidate()
             if node is None:
-                if T: T.write(self.trace_message('No candidate anymore.') + '\n')
+                if T: self.trace.debug('No candidate anymore.')
                 return None
 
             node = node.disambiguate()
@@ -797,7 +852,7 @@ class Taskmaster:
             else:
                 S = None
 
-            if T: T.write(self.trace_message('    Considering node %s and its children:' % self.trace_node(node)))
+            if T: self.trace.debug('    Considering node %s and its children:' % self.tm_trace_node(node))
 
             if state == NODE_NO_STATE:
                 # Mark this node as being on the execution stack:
@@ -805,7 +860,7 @@ class Taskmaster:
             elif state > NODE_PENDING:
                 # Skip this node if it has already been evaluated:
                 if S: S.already_handled = S.already_handled + 1
-                if T: T.write(self.trace_message('       already handled (executed)'))
+                if T: self.trace.debug('       already handled (executed)')
                 continue
 
             executor = node.get_executor()
@@ -816,7 +871,7 @@ class Taskmaster:
                 exc_value = sys.exc_info()[1]
                 e = SCons.Errors.ExplicitExit(node, exc_value.code)
                 self.ready_exc = (SCons.Errors.ExplicitExit, e)
-                if T: T.write(self.trace_message('       SystemExit'))
+                if T: self.trace.debug('       SystemExit')
                 return node
             except Exception as e:
                 # We had a problem just trying to figure out the
@@ -825,7 +880,7 @@ class Taskmaster:
                 # raise the exception when the Task is "executed."
                 self.ready_exc = sys.exc_info()
                 if S: S.problem = S.problem + 1
-                if T: T.write(self.trace_message('       exception %s while scanning children.\n' % e))
+                if T: self.trace.debug('       exception %s while scanning children.' % e)
                 return node
 
             children_not_visited = []
@@ -836,7 +891,7 @@ class Taskmaster:
             for child in chain(executor.get_all_prerequisites(), children):
                 childstate = child.get_state()
 
-                if T: T.write(self.trace_message('       ' + self.trace_node(child)))
+                if T: self.trace.debug('       ' + self.tm_trace_node(child))
 
                 if childstate == NODE_NO_STATE:
                     children_not_visited.append(child)
@@ -857,8 +912,8 @@ class Taskmaster:
                 self.candidates.extend(self.order(children_not_visited))
 
             # if T and children_not_visited:
-            #    T.write(self.trace_message('     adding to candidates: %s' % map(str, children_not_visited)))
-            #    T.write(self.trace_message('     candidates now: %s\n' % map(str, self.candidates)))
+            #    self.trace.debug('     adding to candidates: %s' % map(str, children_not_visited))
+            #    self.trace.debug('     candidates now: %s\n' % map(str, self.candidates))
 
             # Skip this node if any of its children have failed.
             #
@@ -883,7 +938,7 @@ class Taskmaster:
                     n.set_state(NODE_FAILED)
 
                 if S: S.child_failed = S.child_failed + 1
-                if T: T.write(self.trace_message('****** %s\n' % self.trace_node(node)))
+                if T: self.trace.debug('****** %s' % self.tm_trace_node(node))
                 continue
 
             if children_not_ready:
@@ -897,13 +952,13 @@ class Taskmaster:
                     # count so we can be put back on the list for
                     # re-evaluation when they've all finished.
                     node.ref_count =  node.ref_count + child.add_to_waiting_parents(node)
-                    if T: T.write(self.trace_message('     adjusted ref count: %s, child %s' %
-                                  (self.trace_node(node), repr(str(child)))))
+                    if T: self.trace.debug('     adjusted ref count: %s, child %s' %
+                                                (self.tm_trace_node(node), repr(str(child))))
 
                 if T:
                     for pc in children_pending:
-                        T.write(self.trace_message('       adding %s to the pending children set\n' %
-                                self.trace_node(pc)))
+                        self.trace.debug('       adding %s to the pending children set' %
+                                              self.tm_trace_node(pc))
                 self.pending_children = self.pending_children | children_pending
 
                 continue
@@ -923,8 +978,7 @@ class Taskmaster:
             # The default when we've gotten through all of the checks above:
             # this node is ready to be built.
             if S: S.build = S.build + 1
-            if T: T.write(self.trace_message('Evaluating %s\n' %
-                                             self.trace_node(node)))
+            if T: self.trace.debug('Evaluating %s' % self.tm_trace_node(node))
 
             # For debugging only:
             #
@@ -989,8 +1043,8 @@ class Taskmaster:
 
         if T:
             for n in nodes:
-                T.write(self.trace_message('       removing node %s from the pending children set\n' %
-                        self.trace_node(n)))
+                self.trace.debug('       removing node %s from the pending children set\n' %
+                                      self.tm_trace_node(n))
         try:
             while len(to_visit):
                 node = to_visit.pop()
@@ -1006,8 +1060,8 @@ class Taskmaster:
 
                 for p in parents:
                     p.ref_count = p.ref_count - 1
-                    if T: T.write(self.trace_message('       removing parent %s from the pending children set\n' %
-                                  self.trace_node(p)))
+                    if T: self.trace.debug('       removing parent %s from the pending children set\n' %
+                                                self.tm_trace_node(p))
         except KeyError:
             # The container to_visit has been emptied.
             pass
diff --git a/SCons/Util.py b/SCons/Util.py
index 49a3a0f..476d4d6 100644
--- a/SCons/Util.py
+++ b/SCons/Util.py
@@ -35,6 +35,7 @@ from collections.abc import MappingView
 from contextlib import suppress
 from types import MethodType, FunctionType
 from typing import Optional, Union
+from logging import Formatter
 
 # Note: Util module cannot import other bits of SCons globally without getting
 # into import loops. Both the below modules import SCons.Util early on.
@@ -2159,6 +2160,17 @@ def wait_for_process_to_die(pid):
                 else:
                     time.sleep(0.1)
 
+# From: https://stackoverflow.com/questions/1741972/how-to-use-different-formatters-with-the-same-logging-handler-in-python
+class DispatchingFormatter(Formatter):
+
+    def __init__(self, formatters, default_formatter):
+        self._formatters = formatters
+        self._default_formatter = default_formatter
+
+    def format(self, record):
+        formatter = self._formatters.get(record.name, self._default_formatter)
+        return formatter.format(record)
+
 # Local Variables:
 # tab-width:4
 # indent-tabs-mode:nil