[Patch 7/9 V2] BaseTools: Add LogAgent to support multiple process Autogen

["Bob Feng" <bob.c.feng@intel.com>]

BZ: https://bugzilla.tianocore.org/show_bug.cgi?id=1875

AutoGen processes race the logfile. To resolve this issue,
this patch create a LogAgent thread in main process to write
the log content to console or file, Other process will send
the log content to the LogAgent.

Cc: Liming Gao <liming.gao@intel.com>
Signed-off-by: Bob Feng <bob.c.feng@intel.com>
---
 .../Source/Python/AutoGen/AutoGenWorker.py    | 86 +++++++++++++++----
 BaseTools/Source/Python/AutoGen/DataPipe.py   |  2 +-
 BaseTools/Source/Python/AutoGen/GenMake.py    |  3 +-
 BaseTools/Source/Python/Common/EdkLogger.py   | 33 ++++++-
 BaseTools/Source/Python/build/build.py        | 27 ++++--
 5 files changed, 122 insertions(+), 29 deletions(-)

diff --git a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
index 824237d2ec49..03139ffcc19a 100644
--- a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
+++ b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
@@ -19,52 +19,111 @@ from Workspace.WorkspaceDatabase import BuildDB
 import time
 from queue import Empty
 import traceback
 import sys
 from AutoGen.DataPipe import MemoryDataPipe
+import logging
+
+class LogAgent(threading.Thread):
+    def __init__(self,log_q,log_level,log_file=None):
+        super(LogAgent,self).__init__()
+        self.log_q = log_q
+        self.log_level = log_level
+        self.log_file = log_file
+    def InitLogger(self):
+        # For DEBUG level (All DEBUG_0~9 are applicable)
+        self._DebugLogger_agent = logging.getLogger("tool_debug_agent")
+        _DebugFormatter = logging.Formatter("[%(asctime)s.%(msecs)d]: %(message)s", datefmt="%H:%M:%S")
+        self._DebugLogger_agent.setLevel(self.log_level)
+        _DebugChannel = logging.StreamHandler(sys.stdout)
+        _DebugChannel.setFormatter(_DebugFormatter)
+        self._DebugLogger_agent.addHandler(_DebugChannel)
+
+        # For VERBOSE, INFO, WARN level
+        self._InfoLogger_agent = logging.getLogger("tool_info_agent")
+        _InfoFormatter = logging.Formatter("%(message)s")
+        self._InfoLogger_agent.setLevel(self.log_level)
+        _InfoChannel = logging.StreamHandler(sys.stdout)
+        _InfoChannel.setFormatter(_InfoFormatter)
+        self._InfoLogger_agent.addHandler(_InfoChannel)
+
+        # For ERROR level
+        self._ErrorLogger_agent = logging.getLogger("tool_error_agent")
+        _ErrorFormatter = logging.Formatter("%(message)s")
+        self._ErrorLogger_agent.setLevel(self.log_level)
+        _ErrorCh = logging.StreamHandler(sys.stderr)
+        _ErrorCh.setFormatter(_ErrorFormatter)
+        self._ErrorLogger_agent.addHandler(_ErrorCh)
+
+        if self.log_file:
+            if os.path.exists(self.log_file):
+                os.remove(self.log_file)
+            _Ch = logging.FileHandler(self.log_file)
+            _Ch.setFormatter(_DebugFormatter)
+            self._DebugLogger_agent.addHandler(_Ch)
+
+            _Ch= logging.FileHandler(self.log_file)
+            _Ch.setFormatter(_InfoFormatter)
+            self._InfoLogger_agent.addHandler(_Ch)
+
+            _Ch = logging.FileHandler(self.log_file)
+            _Ch.setFormatter(_ErrorFormatter)
+            self._ErrorLogger_agent.addHandler(_Ch)
+
+    def run(self):
+        self.InitLogger()
+        while True:
+            log_message = self.log_q.get()
+            if log_message is None:
+                break
+            if log_message.name == "tool_error":
+                self._ErrorLogger_agent.log(log_message.levelno,log_message.getMessage())
+            elif log_message.name == "tool_info":
+                self._InfoLogger_agent.log(log_message.levelno,log_message.getMessage())
+            elif log_message.name == "tool_debug":
+                self._DebugLogger_agent.log(log_message.levelno,log_message.getMessage())
+            else:
+                self._InfoLogger_agent.log(log_message.levelno,log_message.getMessage())
+
+    def kill(self):
+        self.log_q.put(None)
 class AutoGenManager(threading.Thread):
     def __init__(self,autogen_workers, feedback_q):
         super(AutoGenManager,self).__init__()
         self.autogen_workers = autogen_workers
         self.feedback_q = feedback_q
-        self.terminate = False
         self.Status = True
     def run(self):
         try:
             while True:
-                if self.terminate:
-                    break
-                if self.feedback_q.empty():
-                    time.sleep(1)
-                    continue
-                badnews = self.feedback_q.get(False)
-                if badnews:
-                    print(badnews)
+                badnews = self.feedback_q.get()
+                if badnews is None:
                     self.Status = False
                     self.TerminateWorkers()
                     break
         except Exception:
             return
 
     def kill(self):
-        self.terminate = True
+        self.feedback_q.put(None)
 
     def TerminateWorkers(self):
         for w in self.autogen_workers:
             if w.is_alive():
                 w.terminate()
 
 class AutoGenWorkerInProcess(mp.Process):
-    def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data):
+    def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data,log_q):
         mp.Process.__init__(self)
         self.module_queue = module_queue
         self.data_pipe_file_path =data_pipe_file_path
         self.data_pipe = None
         self.feedback_q = feedback_q
         self.PlatformMetaFileSet = {}
         self.file_lock = file_lock
         self.share_data = share_data
+        self.log_q = log_q
     def GetPlatformMetaFile(self,filepath,root):
         try:
             return self.PlatformMetaFileSet[(filepath,root)]
         except:
             self.PlatformMetaFileSet[(filepath,root)]  = filepath
@@ -75,18 +134,15 @@ class AutoGenWorkerInProcess(mp.Process):
             with self.file_lock:
                 if not os.path.exists(self.data_pipe_file_path):
                     self.feedback_q.put(taskname + ":" + "load data pipe %s failed." % self.data_pipe_file_path)
                 self.data_pipe = MemoryDataPipe()
                 self.data_pipe.load(self.data_pipe_file_path)
-            EdkLogger.Initialize()
+            EdkLogger.LogClientInitialize(self.log_q)
             loglevel = self.data_pipe.Get("LogLevel")
             if not loglevel:
                 loglevel = EdkLogger.INFO
             EdkLogger.SetLevel(loglevel)
-            logfile = self.data_pipe.Get("LogFile")
-            if logfile:
-                EdkLogger.SetLogFile(logfile)
             target = self.data_pipe.Get("P_Info").get("Target")
             toolchain = self.data_pipe.Get("P_Info").get("ToolChain")
             archlist = self.data_pipe.Get("P_Info").get("ArchList")
 
             active_p = self.data_pipe.Get("P_Info").get("ActivePlatform")
diff --git a/BaseTools/Source/Python/AutoGen/DataPipe.py b/BaseTools/Source/Python/AutoGen/DataPipe.py
index 9478f41d481b..33d2b14c9add 100644
--- a/BaseTools/Source/Python/AutoGen/DataPipe.py
+++ b/BaseTools/Source/Python/AutoGen/DataPipe.py
@@ -145,9 +145,9 @@ class MemoryDataPipe(DataPipe):
         self.DataContainer = {"PackageList": [(dec.MetaFile,dec.Arch) for dec in PlatformInfo.PackageList]}
 
         self.DataContainer = {"GuidDict": PlatformInfo.Platform._GuidDict}
 
         self.DataContainer = {"DatabasePath":GlobalData.gDatabasePath}
+
         self.DataContainer = {"FdfParser": True if GlobalData.gFdfParser else False}
 
         self.DataContainer = {"LogLevel": EdkLogger.GetLevel()}
-        self.DataContainer = {"LogFile": GlobalData.gOptions.LogFile if GlobalData.gOptions.LogFile is not None else ""}
diff --git a/BaseTools/Source/Python/AutoGen/GenMake.py b/BaseTools/Source/Python/AutoGen/GenMake.py
index 10e67f7dbb16..5802ae5ae485 100644
--- a/BaseTools/Source/Python/AutoGen/GenMake.py
+++ b/BaseTools/Source/Python/AutoGen/GenMake.py
@@ -1024,11 +1024,12 @@ cleanlib:
                         self.FileListMacros[T.FileListMacro].append(NewFile)
                     elif T.GenFileListMacro:
                         self.FileListMacros[T.FileListMacro].append(NewFile)
                     else:
                         Deps.append(NewFile)
-
+                for key in self.FileListMacros:
+                    self.FileListMacros[key].sort()
                 # Use file list macro as dependency
                 if T.GenFileListMacro:
                     Deps.append("$(%s)" % T.FileListMacro)
                     if Type in [TAB_OBJECT_FILE, TAB_STATIC_LIBRARY]:
                         Deps.append("$(%s)" % T.ListFileMacro)
diff --git a/BaseTools/Source/Python/Common/EdkLogger.py b/BaseTools/Source/Python/Common/EdkLogger.py
index ae2070bebba3..f6a5e3b4daf9 100644
--- a/BaseTools/Source/Python/Common/EdkLogger.py
+++ b/BaseTools/Source/Python/Common/EdkLogger.py
@@ -8,10 +8,11 @@
 ## Import modules
 from __future__ import absolute_import
 import Common.LongFilePathOs as os, sys, logging
 import traceback
 from  .BuildToolError import *
+import logging.handlers
 
 ## Log level constants
 DEBUG_0 = 1
 DEBUG_1 = 2
 DEBUG_2 = 3
@@ -198,30 +199,30 @@ def error(ToolName, ErrorCode, Message=None, File=None, Line=None, ExtraData=Non
 
 # Log information which should be always put out
 quiet   = _ErrorLogger.error
 
 ## Initialize log system
-def Initialize():
+def LogClientInitialize(log_q):
     #
     # Since we use different format to log different levels of message into different
     # place (stdout or stderr), we have to use different "Logger" objects to do this.
     #
     # For DEBUG level (All DEBUG_0~9 are applicable)
     _DebugLogger.setLevel(INFO)
-    _DebugChannel = logging.StreamHandler(sys.stdout)
+    _DebugChannel = logging.handlers.QueueHandler(log_q)
     _DebugChannel.setFormatter(_DebugFormatter)
     _DebugLogger.addHandler(_DebugChannel)
 
     # For VERBOSE, INFO, WARN level
     _InfoLogger.setLevel(INFO)
-    _InfoChannel = logging.StreamHandler(sys.stdout)
+    _InfoChannel = logging.handlers.QueueHandler(log_q)
     _InfoChannel.setFormatter(_InfoFormatter)
     _InfoLogger.addHandler(_InfoChannel)
 
     # For ERROR level
     _ErrorLogger.setLevel(INFO)
-    _ErrorCh = logging.StreamHandler(sys.stderr)
+    _ErrorCh = logging.handlers.QueueHandler(log_q)
     _ErrorCh.setFormatter(_ErrorFormatter)
     _ErrorLogger.addHandler(_ErrorCh)
 
 ## Set log level
 #
@@ -232,10 +233,34 @@ def SetLevel(Level):
         Level = INFO
     _DebugLogger.setLevel(Level)
     _InfoLogger.setLevel(Level)
     _ErrorLogger.setLevel(Level)
 
+## Initialize log system
+def Initialize():
+    #
+    # Since we use different format to log different levels of message into different
+    # place (stdout or stderr), we have to use different "Logger" objects to do this.
+    #
+    # For DEBUG level (All DEBUG_0~9 are applicable)
+    _DebugLogger.setLevel(INFO)
+    _DebugChannel = logging.StreamHandler(sys.stdout)
+    _DebugChannel.setFormatter(_DebugFormatter)
+    _DebugLogger.addHandler(_DebugChannel)
+
+    # For VERBOSE, INFO, WARN level
+    _InfoLogger.setLevel(INFO)
+    _InfoChannel = logging.StreamHandler(sys.stdout)
+    _InfoChannel.setFormatter(_InfoFormatter)
+    _InfoLogger.addHandler(_InfoChannel)
+
+    # For ERROR level
+    _ErrorLogger.setLevel(INFO)
+    _ErrorCh = logging.StreamHandler(sys.stderr)
+    _ErrorCh.setFormatter(_ErrorFormatter)
+    _ErrorLogger.addHandler(_ErrorCh)
+
 def InitializeForUnitTest():
     Initialize()
     SetLevel(SILENT)
 
 ## Get current log level
diff --git a/BaseTools/Source/Python/build/build.py b/BaseTools/Source/Python/build/build.py
index 71040e748b39..094b1934fd53 100644
--- a/BaseTools/Source/Python/build/build.py
+++ b/BaseTools/Source/Python/build/build.py
@@ -28,11 +28,12 @@ from subprocess import Popen,PIPE
 from collections import OrderedDict, defaultdict
 from optparse import OptionParser
 from AutoGen.PlatformAutoGen import PlatformAutoGen
 from AutoGen.ModuleAutoGen import ModuleAutoGen
 from AutoGen.WorkspaceAutoGen import WorkspaceAutoGen
-from AutoGen.AutoGenWorker import AutoGenWorkerInProcess,AutoGenManager
+from AutoGen.AutoGenWorker import AutoGenWorkerInProcess,AutoGenManager,\
+    LogAgent
 from AutoGen import GenMake
 from Common import Misc as Utils
 
 from Common.TargetTxtClassObject import TargetTxt
 from Common.ToolDefClassObject import ToolDef
@@ -697,11 +698,11 @@ class Build():
     #
     #   @param  Target              The build command target, one of gSupportedTarget
     #   @param  WorkspaceDir        The directory of workspace
     #   @param  BuildOptions        Build options passed from command line
     #
-    def __init__(self, Target, WorkspaceDir, BuildOptions):
+    def __init__(self, Target, WorkspaceDir, BuildOptions,log_q):
         self.WorkspaceDir   = WorkspaceDir
         self.Target         = Target
         self.PlatformFile   = BuildOptions.PlatformFile
         self.ModuleFile     = BuildOptions.ModuleFile
         self.ArchList       = BuildOptions.TargetArch
@@ -828,16 +829,17 @@ class Build():
 
         self.AutoGenMgr = None
         EdkLogger.info("")
         os.chdir(self.WorkspaceDir)
         self.share_data = Manager().dict()
+        self.log_q = log_q
     def StartAutoGen(self,mqueue, DataPipe,SkipAutoGen,PcdMaList,share_data):
         if SkipAutoGen:
             return
         feedback_q = mp.Queue()
         file_lock = mp.Lock()
-        auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data) for _ in range(mp.cpu_count())]
+        auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data,self.log_q) for _ in range(mp.cpu_count())]
         self.AutoGenMgr = AutoGenManager(auto_workers,feedback_q)
         self.AutoGenMgr.start()
         for w in auto_workers:
             w.start()
         if PcdMaList is not None:
@@ -2391,35 +2393,42 @@ def MyOptionParser():
 #   @retval 1     Tool failed
 #
 def Main():
     StartTime = time.time()
 
+    #
+    # Create a log Queue
+    #
+    LogQ = mp.Queue()
     # Initialize log system
-    EdkLogger.Initialize()
+    EdkLogger.LogClientInitialize(LogQ)
     GlobalData.gCommand = sys.argv[1:]
     #
     # Parse the options and args
     #
     (Option, Target) = MyOptionParser()
     GlobalData.gOptions = Option
     GlobalData.gCaseInsensitive = Option.CaseInsensitive
 
     # Set log level
+    LogLevel = EdkLogger.INFO
     if Option.verbose is not None:
         EdkLogger.SetLevel(EdkLogger.VERBOSE)
+        LogLevel = EdkLogger.VERBOSE
     elif Option.quiet is not None:
         EdkLogger.SetLevel(EdkLogger.QUIET)
+        LogLevel = EdkLogger.QUIET
     elif Option.debug is not None:
         EdkLogger.SetLevel(Option.debug + 1)
+        LogLevel = Option.debug + 1
     else:
         EdkLogger.SetLevel(EdkLogger.INFO)
 
-    if Option.LogFile is not None:
-        EdkLogger.SetLogFile(Option.LogFile)
-
     if Option.WarningAsError == True:
         EdkLogger.SetWarningAsError()
+    Log_Agent = LogAgent(LogQ,LogLevel,Option.LogFile)
+    Log_Agent.start()
 
     if platform.platform().find("Windows") >= 0:
         GlobalData.gIsWindows = True
     else:
         GlobalData.gIsWindows = False
@@ -2489,11 +2498,11 @@ def Main():
                 EdkLogger.error("build", ErrorCode, ExtraData=ErrorInfo)
 
         if Option.Flag is not None and Option.Flag not in ['-c', '-s']:
             EdkLogger.error("build", OPTION_VALUE_INVALID, "UNI flag must be one of -c or -s")
 
-        MyBuild = Build(Target, Workspace, Option)
+        MyBuild = Build(Target, Workspace, Option,LogQ)
         GlobalData.gCommandLineDefines['ARCH'] = ' '.join(MyBuild.ArchList)
         if not (MyBuild.LaunchPrebuildFlag and os.path.exists(MyBuild.PlatformBuildPath)):
             MyBuild.Launch()
 
         #
@@ -2575,10 +2584,12 @@ def Main():
 
     EdkLogger.SetLevel(EdkLogger.QUIET)
     EdkLogger.quiet("\n- %s -" % Conclusion)
     EdkLogger.quiet(time.strftime("Build end time: %H:%M:%S, %b.%d %Y", time.localtime()))
     EdkLogger.quiet("Build total time: %s\n" % BuildDurationStr)
+    Log_Agent.kill()
+    Log_Agent.join()
     return ReturnCode
 
 if __name__ == '__main__':
     r = Main()
     ## 0-127 is a safe return range, and 1 is a standard default error
-- 
2.20.1.windows.1