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>

4 files changed, 117 insertions, 19 deletions

diff --git a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
index 9d06b45ec0..1296604f68 100644
--- a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
+++ b/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")

diff --git a/BaseTools/Source/Python/AutoGen/DataPipe.py b/BaseTools/Source/Python/AutoGen/DataPipe.py
index 6299208056..2052084bdb 100644
--- a/BaseTools/Source/Python/AutoGen/DataPipe.py
+++ b/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 ""}

diff --git a/BaseTools/Source/Python/Common/EdkLogger.py b/BaseTools/Source/Python/Common/EdkLogger.py
index ae2070bebb..f6a5e3b4da 100644
--- a/BaseTools/Source/Python/Common/EdkLogger.py
+++ b/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

@@ -200,26 +201,26 @@ def error(ToolName, ErrorCode, Message=None, File=None, Line=None, ExtraData=Non
 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)

 

@@ -234,6 +235,30 @@ def 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)

diff --git a/BaseTools/Source/Python/build/build.py b/BaseTools/Source/Python/build/build.py
index b9305bf7b2..4daef5652f 100644
--- a/BaseTools/Source/Python/build/build.py
+++ b/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__':