BaseTools: Add LogAgent to support multiple process Autogen

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>
Acked-by: Laszlo Ersek <lersek@redhat.com>
Tested-by: Laszlo Ersek <lersek@redhat.com>
Acked-by: Liming Gao <liming.gao@intel.com>

BaseTools/Source/Python/AutoGen/AutoGenWorker.py

@@ -26,12 +26,76 @@ def clearQ(q):
             q.get_nowait()
     except Empty:
         pass
+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,error_event):
         super(AutoGenManager,self).__init__()
         self.autogen_workers = autogen_workers
         self.feedback_q = feedback_q
-        self.terminate = False
         self.Status = True
         self.error_event = error_event
     def run(self):
@@ -64,7 +128,7 @@ class AutoGenManager(threading.Thread):
     def kill(self):
         self.feedback_q.put(None)
 class AutoGenWorkerInProcess(mp.Process):
-    def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data,error_event):
+    def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data,log_q,error_event):
         mp.Process.__init__(self)
         self.module_queue = module_queue
         self.data_pipe_file_path =data_pipe_file_path
@@ -73,6 +137,7 @@ class AutoGenWorkerInProcess(mp.Process):
         self.PlatformMetaFileSet = {}
         self.file_lock = file_lock
         self.share_data = share_data
+        self.log_q = log_q
         self.error_event = error_event
     def GetPlatformMetaFile(self,filepath,root):
         try:
@@ -88,14 +153,11 @@ class AutoGenWorkerInProcess(mp.Process):
                     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")

BaseTools/Source/Python/AutoGen/DataPipe.py

@@ -154,7 +154,7 @@ class MemoryDataPipe(DataPipe):
         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 ""}

BaseTools/Source/Python/Common/EdkLogger.py

@@ -10,6 +10,7 @@ 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
@@ -199,6 +200,41 @@ 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 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.handlers.QueueHandler(log_q)
+    _DebugChannel.setFormatter(_DebugFormatter)
+    _DebugLogger.addHandler(_DebugChannel)
+
+    # For VERBOSE, INFO, WARN level
+    _InfoLogger.setLevel(INFO)
+    _InfoChannel = logging.handlers.QueueHandler(log_q)
+    _InfoChannel.setFormatter(_InfoFormatter)
+    _InfoLogger.addHandler(_InfoChannel)
+
+    # For ERROR level
+    _ErrorLogger.setLevel(INFO)
+    _ErrorCh = logging.handlers.QueueHandler(log_q)
+    _ErrorCh.setFormatter(_ErrorFormatter)
+    _ErrorLogger.addHandler(_ErrorCh)
+
+## Set log level
+#
+#   @param  Level   One of log level in _LogLevel
+def SetLevel(Level):
+    if Level not in _LogLevels:
+        info("Not supported log level (%d). Use default level instead." % Level)
+        Level = INFO
+    _DebugLogger.setLevel(Level)
+    _InfoLogger.setLevel(Level)
+    _ErrorLogger.setLevel(Level)
+
 ## Initialize log system
 def Initialize():
     #
@@ -223,17 +259,6 @@ def Initialize():
     _ErrorCh.setFormatter(_ErrorFormatter)
     _ErrorLogger.addHandler(_ErrorCh)
 
-## Set log level
-#
-#   @param  Level   One of log level in _LogLevel
-def SetLevel(Level):
-    if Level not in _LogLevels:
-        info("Not supported log level (%d). Use default level instead." % Level)
-        Level = INFO
-    _DebugLogger.setLevel(Level)
-    _InfoLogger.setLevel(Level)
-    _ErrorLogger.setLevel(Level)
-
 def InitializeForUnitTest():
     Initialize()
     SetLevel(SILENT)

BaseTools/Source/Python/build/build.py

@@ -30,7 +30,8 @@ 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
 
@@ -699,7 +700,7 @@ class Build():
     #   @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
@@ -830,6 +831,7 @@ class Build():
         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):
         try:
             if SkipAutoGen:
@@ -837,7 +839,7 @@ class Build():
             feedback_q = mp.Queue()
             file_lock = mp.Lock()
             error_event = mp.Event()
-            auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data,error_event) for _ in range(self.ThreadNumber)]
+            auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data,self.log_q,error_event) for _ in range(self.ThreadNumber)]
             self.AutoGenMgr = AutoGenManager(auto_workers,feedback_q,error_event)
             self.AutoGenMgr.start()
             for w in auto_workers:
@@ -2406,8 +2408,12 @@ def MyOptionParser():
 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
@@ -2417,20 +2423,23 @@ def Main():
     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
@@ -2504,7 +2513,7 @@ def Main():
         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()
@@ -2588,6 +2597,8 @@ def Main():
     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__':