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....@intel.com>
Signed-off-by: Bob Feng <bob.c.f...@intel.com>
---
.../Source/Python/AutoGen/AutoGenWorker.py | 74 +++++++++++++++++--
BaseTools/Source/Python/AutoGen/DataPipe.py | 2 +-
BaseTools/Source/Python/Common/EdkLogger.py | 33 ++++++++-
BaseTools/Source/Python/build/build.py | 27 +++++--
4 files changed, 117 insertions(+), 19 deletions(-)
diff --git a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
index 9d06b45ec03f..1296604f688d 100644
--- a/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
+++ b/BaseTools/Source/Python/AutoGen/AutoGenWorker.py
@@ -24,16 +24,80 @@ def clearQ(q):
try:
while True:
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):
try:
fin_num = 0
@@ -62,19 +126,20 @@ class AutoGenManager(threading.Thread):
def TerminateWorkers(self):
self.error_event.set()
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
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
self.error_event = error_event
def GetPlatformMetaFile(self,filepath,root):
try:
return self.PlatformMetaFileSet[(filepath,root)]
except:
@@ -86,18 +151,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 62992080567f..2052084bdb4b 100644
--- a/BaseTools/Source/Python/AutoGen/DataPipe.py
+++ b/BaseTools/Source/Python/AutoGen/DataPipe.py
@@ -152,9 +152,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/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 4bddd80ee112..60b22053cd9d 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,18 +829,19 @@ 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):
try:
if SkipAutoGen:
return True,0
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:
w.start()
if PcdMaList is not None:
@@ -2405,35 +2407,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
@@ -2503,11 +2512,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()
#
@@ -2587,10 +2596,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__':
try:
mp.set_start_method('spawn')
--
2.20.1.windows.1
-=-=-=-=-=-=-=-=-=-=-=-
Groups.io Links: You receive all messages sent to this group.
View/Reply Online (#44932): https://edk2.groups.io/g/devel/message/44932
Mute This Topic: https://groups.io/mt/32740904/21656
Group Owner: devel+ow...@edk2.groups.io
Unsubscribe: https://edk2.groups.io/g/devel/unsub [arch...@mail-archive.com]
-=-=-=-=-=-=-=-=-=-=-=-
