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>

diff --git a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
index 9d06b45ec03f4cb24a5d07bf42292b09ab4583a6..1296604f688d3844ff3bdb443e01dab7491727fa 100644 (file)
--- a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
+++ b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
@@ -26,12 +26,76 @@ def clearQ(q):
             q.get_nowait()\r
     except Empty:\r
         pass\r
+import logging\r
+\r
+class LogAgent(threading.Thread):\r
+    def __init__(self,log_q,log_level,log_file=None):\r
+        super(LogAgent,self).__init__()\r
+        self.log_q = log_q\r
+        self.log_level = log_level\r
+        self.log_file = log_file\r
+    def InitLogger(self):\r
+        # For DEBUG level (All DEBUG_0~9 are applicable)\r
+        self._DebugLogger_agent = logging.getLogger("tool_debug_agent")\r
+        _DebugFormatter = logging.Formatter("[%(asctime)s.%(msecs)d]: %(message)s", datefmt="%H:%M:%S")\r
+        self._DebugLogger_agent.setLevel(self.log_level)\r
+        _DebugChannel = logging.StreamHandler(sys.stdout)\r
+        _DebugChannel.setFormatter(_DebugFormatter)\r
+        self._DebugLogger_agent.addHandler(_DebugChannel)\r
+\r
+        # For VERBOSE, INFO, WARN level\r
+        self._InfoLogger_agent = logging.getLogger("tool_info_agent")\r
+        _InfoFormatter = logging.Formatter("%(message)s")\r
+        self._InfoLogger_agent.setLevel(self.log_level)\r
+        _InfoChannel = logging.StreamHandler(sys.stdout)\r
+        _InfoChannel.setFormatter(_InfoFormatter)\r
+        self._InfoLogger_agent.addHandler(_InfoChannel)\r
+\r
+        # For ERROR level\r
+        self._ErrorLogger_agent = logging.getLogger("tool_error_agent")\r
+        _ErrorFormatter = logging.Formatter("%(message)s")\r
+        self._ErrorLogger_agent.setLevel(self.log_level)\r
+        _ErrorCh = logging.StreamHandler(sys.stderr)\r
+        _ErrorCh.setFormatter(_ErrorFormatter)\r
+        self._ErrorLogger_agent.addHandler(_ErrorCh)\r
+\r
+        if self.log_file:\r
+            if os.path.exists(self.log_file):\r
+                os.remove(self.log_file)\r
+            _Ch = logging.FileHandler(self.log_file)\r
+            _Ch.setFormatter(_DebugFormatter)\r
+            self._DebugLogger_agent.addHandler(_Ch)\r
+\r
+            _Ch= logging.FileHandler(self.log_file)\r
+            _Ch.setFormatter(_InfoFormatter)\r
+            self._InfoLogger_agent.addHandler(_Ch)\r
+\r
+            _Ch = logging.FileHandler(self.log_file)\r
+            _Ch.setFormatter(_ErrorFormatter)\r
+            self._ErrorLogger_agent.addHandler(_Ch)\r
+\r
+    def run(self):\r
+        self.InitLogger()\r
+        while True:\r
+            log_message = self.log_q.get()\r
+            if log_message is None:\r
+                break\r
+            if log_message.name == "tool_error":\r
+                self._ErrorLogger_agent.log(log_message.levelno,log_message.getMessage())\r
+            elif log_message.name == "tool_info":\r
+                self._InfoLogger_agent.log(log_message.levelno,log_message.getMessage())\r
+            elif log_message.name == "tool_debug":\r
+                self._DebugLogger_agent.log(log_message.levelno,log_message.getMessage())\r
+            else:\r
+                self._InfoLogger_agent.log(log_message.levelno,log_message.getMessage())\r
+\r
+    def kill(self):\r
+        self.log_q.put(None)\r
 class AutoGenManager(threading.Thread):\r
     def __init__(self,autogen_workers, feedback_q,error_event):\r
         super(AutoGenManager,self).__init__()\r
         self.autogen_workers = autogen_workers\r
         self.feedback_q = feedback_q\r
-        self.terminate = False\r
         self.Status = True\r
         self.error_event = error_event\r
     def run(self):\r
@@ -64,7 +128,7 @@ class AutoGenManager(threading.Thread):
     def kill(self):\r
         self.feedback_q.put(None)\r
 class AutoGenWorkerInProcess(mp.Process):\r
-    def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data,error_event):\r
+    def __init__(self,module_queue,data_pipe_file_path,feedback_q,file_lock, share_data,log_q,error_event):\r
         mp.Process.__init__(self)\r
         self.module_queue = module_queue\r
         self.data_pipe_file_path =data_pipe_file_path\r
@@ -73,6 +137,7 @@ class AutoGenWorkerInProcess(mp.Process):
         self.PlatformMetaFileSet = {}\r
         self.file_lock = file_lock\r
         self.share_data = share_data\r
+        self.log_q = log_q\r
         self.error_event = error_event\r
     def GetPlatformMetaFile(self,filepath,root):\r
         try:\r
@@ -88,14 +153,11 @@ class AutoGenWorkerInProcess(mp.Process):
                     self.feedback_q.put(taskname + ":" + "load data pipe %s failed." % self.data_pipe_file_path)\r
                 self.data_pipe = MemoryDataPipe()\r
                 self.data_pipe.load(self.data_pipe_file_path)\r
-            EdkLogger.Initialize()\r
+            EdkLogger.LogClientInitialize(self.log_q)\r
             loglevel = self.data_pipe.Get("LogLevel")\r
             if not loglevel:\r
                 loglevel = EdkLogger.INFO\r
             EdkLogger.SetLevel(loglevel)\r
-            logfile = self.data_pipe.Get("LogFile")\r
-            if logfile:\r
-                EdkLogger.SetLogFile(logfile)\r
             target = self.data_pipe.Get("P_Info").get("Target")\r
             toolchain = self.data_pipe.Get("P_Info").get("ToolChain")\r
             archlist = self.data_pipe.Get("P_Info").get("ArchList")\r

diff --git a/BaseTools/Source/Python/AutoGen/DataPipe.py b/BaseTools/Source/Python/AutoGen/DataPipe.py
index 62992080567f1bbafc0947e6555d7cb1a4511225..2052084bdb4bc897ddee33b145ca5c083326728a 100644 (file)
--- 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}\r
 \r
         self.DataContainer = {"DatabasePath":GlobalData.gDatabasePath}\r
+\r
         self.DataContainer = {"FdfParser": True if GlobalData.gFdfParser else False}\r
 \r
         self.DataContainer = {"LogLevel": EdkLogger.GetLevel()}\r
-        self.DataContainer = {"LogFile": GlobalData.gOptions.LogFile if GlobalData.gOptions.LogFile is not None else ""}\r

diff --git a/BaseTools/Source/Python/Common/EdkLogger.py b/BaseTools/Source/Python/Common/EdkLogger.py
index ae2070bebba3a7466df281dff0f3dbb7f5e28d70..f6a5e3b4daf9e544ed06082048c6a62f056d8b94 100644 (file)
--- 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\r
 import traceback\r
 from  .BuildToolError import *\r
+import logging.handlers\r
 \r
 ## Log level constants\r
 DEBUG_0 = 1\r
@@ -200,26 +201,26 @@ def error(ToolName, ErrorCode, Message=None, File=None, Line=None, ExtraData=Non
 quiet   = _ErrorLogger.error\r
 \r
 ## Initialize log system\r
-def Initialize():\r
+def LogClientInitialize(log_q):\r
     #\r
     # Since we use different format to log different levels of message into different\r
     # place (stdout or stderr), we have to use different "Logger" objects to do this.\r
     #\r
     # For DEBUG level (All DEBUG_0~9 are applicable)\r
     _DebugLogger.setLevel(INFO)\r
-    _DebugChannel = logging.StreamHandler(sys.stdout)\r
+    _DebugChannel = logging.handlers.QueueHandler(log_q)\r
     _DebugChannel.setFormatter(_DebugFormatter)\r
     _DebugLogger.addHandler(_DebugChannel)\r
 \r
     # For VERBOSE, INFO, WARN level\r
     _InfoLogger.setLevel(INFO)\r
-    _InfoChannel = logging.StreamHandler(sys.stdout)\r
+    _InfoChannel = logging.handlers.QueueHandler(log_q)\r
     _InfoChannel.setFormatter(_InfoFormatter)\r
     _InfoLogger.addHandler(_InfoChannel)\r
 \r
     # For ERROR level\r
     _ErrorLogger.setLevel(INFO)\r
-    _ErrorCh = logging.StreamHandler(sys.stderr)\r
+    _ErrorCh = logging.handlers.QueueHandler(log_q)\r
     _ErrorCh.setFormatter(_ErrorFormatter)\r
     _ErrorLogger.addHandler(_ErrorCh)\r
 \r
@@ -234,6 +235,30 @@ def SetLevel(Level):
     _InfoLogger.setLevel(Level)\r
     _ErrorLogger.setLevel(Level)\r
 \r
+## Initialize log system\r
+def Initialize():\r
+    #\r
+    # Since we use different format to log different levels of message into different\r
+    # place (stdout or stderr), we have to use different "Logger" objects to do this.\r
+    #\r
+    # For DEBUG level (All DEBUG_0~9 are applicable)\r
+    _DebugLogger.setLevel(INFO)\r
+    _DebugChannel = logging.StreamHandler(sys.stdout)\r
+    _DebugChannel.setFormatter(_DebugFormatter)\r
+    _DebugLogger.addHandler(_DebugChannel)\r
+\r
+    # For VERBOSE, INFO, WARN level\r
+    _InfoLogger.setLevel(INFO)\r
+    _InfoChannel = logging.StreamHandler(sys.stdout)\r
+    _InfoChannel.setFormatter(_InfoFormatter)\r
+    _InfoLogger.addHandler(_InfoChannel)\r
+\r
+    # For ERROR level\r
+    _ErrorLogger.setLevel(INFO)\r
+    _ErrorCh = logging.StreamHandler(sys.stderr)\r
+    _ErrorCh.setFormatter(_ErrorFormatter)\r
+    _ErrorLogger.addHandler(_ErrorCh)\r
+\r
 def InitializeForUnitTest():\r
     Initialize()\r
     SetLevel(SILENT)\r

diff --git a/BaseTools/Source/Python/build/build.py b/BaseTools/Source/Python/build/build.py
index b9305bf7b25a635d04d6b21cc0161d4f7bad2028..4daef5652f8d6b6a41a91874ec85161dbdaf1dc7 100644 (file)
--- 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\r
 from AutoGen.ModuleAutoGen import ModuleAutoGen\r
 from AutoGen.WorkspaceAutoGen import WorkspaceAutoGen\r
-from AutoGen.AutoGenWorker import AutoGenWorkerInProcess,AutoGenManager\r
+from AutoGen.AutoGenWorker import AutoGenWorkerInProcess,AutoGenManager,\\r
+    LogAgent\r
 from AutoGen import GenMake\r
 from Common import Misc as Utils\r
 \r
@@ -699,7 +700,7 @@ class Build():
     #   @param  WorkspaceDir        The directory of workspace\r
     #   @param  BuildOptions        Build options passed from command line\r
     #\r
-    def __init__(self, Target, WorkspaceDir, BuildOptions):\r
+    def __init__(self, Target, WorkspaceDir, BuildOptions,log_q):\r
         self.WorkspaceDir   = WorkspaceDir\r
         self.Target         = Target\r
         self.PlatformFile   = BuildOptions.PlatformFile\r
@@ -830,6 +831,7 @@ class Build():
         EdkLogger.info("")\r
         os.chdir(self.WorkspaceDir)\r
         self.share_data = Manager().dict()\r
+        self.log_q = log_q\r
     def StartAutoGen(self,mqueue, DataPipe,SkipAutoGen,PcdMaList,share_data):\r
         try:\r
             if SkipAutoGen:\r
@@ -837,7 +839,7 @@ class Build():
             feedback_q = mp.Queue()\r
             file_lock = mp.Lock()\r
             error_event = mp.Event()\r
-            auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data,error_event) for _ in range(self.ThreadNumber)]\r
+            auto_workers = [AutoGenWorkerInProcess(mqueue,DataPipe.dump_file,feedback_q,file_lock,share_data,self.log_q,error_event) for _ in range(self.ThreadNumber)]\r
             self.AutoGenMgr = AutoGenManager(auto_workers,feedback_q,error_event)\r
             self.AutoGenMgr.start()\r
             for w in auto_workers:\r
@@ -2406,8 +2408,12 @@ def MyOptionParser():
 def Main():\r
     StartTime = time.time()\r
 \r
+    #\r
+    # Create a log Queue\r
+    #\r
+    LogQ = mp.Queue()\r
     # Initialize log system\r
-    EdkLogger.Initialize()\r
+    EdkLogger.LogClientInitialize(LogQ)\r
     GlobalData.gCommand = sys.argv[1:]\r
     #\r
     # Parse the options and args\r
@@ -2417,20 +2423,23 @@ def Main():
     GlobalData.gCaseInsensitive = Option.CaseInsensitive\r
 \r
     # Set log level\r
+    LogLevel = EdkLogger.INFO\r
     if Option.verbose is not None:\r
         EdkLogger.SetLevel(EdkLogger.VERBOSE)\r
+        LogLevel = EdkLogger.VERBOSE\r
     elif Option.quiet is not None:\r
         EdkLogger.SetLevel(EdkLogger.QUIET)\r
+        LogLevel = EdkLogger.QUIET\r
     elif Option.debug is not None:\r
         EdkLogger.SetLevel(Option.debug + 1)\r
+        LogLevel = Option.debug + 1\r
     else:\r
         EdkLogger.SetLevel(EdkLogger.INFO)\r
 \r
-    if Option.LogFile is not None:\r
-        EdkLogger.SetLogFile(Option.LogFile)\r
-\r
     if Option.WarningAsError == True:\r
         EdkLogger.SetWarningAsError()\r
+    Log_Agent = LogAgent(LogQ,LogLevel,Option.LogFile)\r
+    Log_Agent.start()\r
 \r
     if platform.platform().find("Windows") >= 0:\r
         GlobalData.gIsWindows = True\r
@@ -2504,7 +2513,7 @@ def Main():
         if Option.Flag is not None and Option.Flag not in ['-c', '-s']:\r
             EdkLogger.error("build", OPTION_VALUE_INVALID, "UNI flag must be one of -c or -s")\r
 \r
-        MyBuild = Build(Target, Workspace, Option)\r
+        MyBuild = Build(Target, Workspace, Option,LogQ)\r
         GlobalData.gCommandLineDefines['ARCH'] = ' '.join(MyBuild.ArchList)\r
         if not (MyBuild.LaunchPrebuildFlag and os.path.exists(MyBuild.PlatformBuildPath)):\r
             MyBuild.Launch()\r
@@ -2588,6 +2597,8 @@ def Main():
     EdkLogger.quiet("\n- %s -" % Conclusion)\r
     EdkLogger.quiet(time.strftime("Build end time: %H:%M:%S, %b.%d %Y", time.localtime()))\r
     EdkLogger.quiet("Build total time: %s\n" % BuildDurationStr)\r
+    Log_Agent.kill()\r
+    Log_Agent.join()\r
     return ReturnCode\r
 \r
 if __name__ == '__main__':\r