Switch bitbake internals to use logging directly rather than bb.msg

We use a custom Logger subclass for our loggers

This logger provides:
- 'debug' method which accepts a debug level
- 'plain' method which bypasses log formatting
- 'verbose' method which is more detail than info, but less than debug

(Bitbake rev: 3b2c1fe5ca56daebb24073a9dd45723d3efd2a8d)

Signed-off-by: Chris Larson <chris_larson@mentor.com>
Signed-off-by: Richard Purdie <rpurdie@linux.intel.com>

1 files changed, 44 insertions, 46 deletions

diff --git a/bitbake/lib/bb/runqueue.py b/bitbake/lib/bb/runqueue.py
index 94b456a98..94b9cab5e 100644
--- a/bitbake/lib/bb/runqueue.py
+++ b/bitbake/lib/bb/runqueue.py
@@ -22,22 +22,25 @@ Handles preparation and execution of a queue of tasks
 # with this program; if not, write to the Free Software Foundation, Inc.,
 # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
 
-import bb, os, sys
+import os
+import sys
 import subprocess
 import signal
 import stat
 import fcntl
 import copy
 import logging
+import bb
 from bb import msg, data, event
 
 bblogger = logging.getLogger("BitBake")
+logger = logging.getLogger("BitBake.RunQueue")
 
 try:
     import cPickle as pickle
 except ImportError:
     import pickle
-    bb.msg.note(1, bb.msg.domain.Cache, "Importing cPickle failed. Falling back to a very slow implementation.")
+    logger.info("Importing cPickle failed. Falling back to a very slow implementation.")
 
 class RunQueueStats:
     """
@@ -363,14 +366,14 @@ class RunQueueData:
         for task in range(numTasks):
             if task_done[task] is False or deps_left[task] != 0:
                 problem_tasks.append(task)
-                bb.msg.debug(2, bb.msg.domain.RunQueue, "Task %s (%s) is not buildable\n" % (task, self.get_user_idstring(task)))
-                bb.msg.debug(2, bb.msg.domain.RunQueue, "(Complete marker was %s and the remaining dependency count was %s)\n\n" % (task_done[task], deps_left[task]))
+                logger.debug(2, "Task %s (%s) is not buildable\n", task, self.get_user_idstring(task))
+                logger.debug(2, "(Complete marker was %s and the remaining dependency count was %s)\n\n", task_done[task], deps_left[task])
 
         if problem_tasks:
             message = "Unbuildable tasks were found.\n"
             message = message + "These are usually caused by circular dependencies and any circular dependency chains found will be printed below. Increase the debug level to see a list of unbuildable tasks.\n\n"
             message = message + "Identifying dependency loops (this may take a short while)...\n"
-            bb.msg.error(bb.msg.domain.RunQueue, message)
+            logger.error(message)
 
             msgs = self.circular_depchains_handler(problem_tasks)
 
@@ -398,7 +401,7 @@ class RunQueueData:
             # Nothing to do
             return 0
 
-        bb.msg.note(1, bb.msg.domain.RunQueue, "Preparing runqueue")
+        logger.info("Preparing runqueue")
 
         # Step A - Work out a list of tasks to run
         #
@@ -445,7 +448,7 @@ class RunQueueData:
             fn = taskData.fn_index[fnid]
             task_deps = self.dataCache.task_deps[fn]
 
-            bb.msg.debug(2, bb.msg.domain.RunQueue, "Processing %s:%s" %(fn, taskData.tasks_name[task]))
+            logger.debug(2, "Processing %s:%s", fn, taskData.tasks_name[task])
 
             if fnid not in taskData.failed_fnids:
 
@@ -505,7 +508,7 @@ class RunQueueData:
                 # Rmove all self references
                 if task in depends:
                     newdep = []
-                    bb.msg.debug(2, bb.msg.domain.RunQueue, "Task %s (%s %s) contains self reference! %s" % (task, taskData.fn_index[taskData.tasks_fnid[task]], taskData.tasks_name[task], depends))
+                    logger.debug(2, "Task %s (%s %s) contains self reference! %s", task, taskData.fn_index[taskData.tasks_fnid[task]], taskData.tasks_name[task], depends)
                     for dep in depends:
                         if task != dep:
                             newdep.append(dep)
@@ -567,7 +570,7 @@ class RunQueueData:
         # as active too. If the task is to be 'forced', clear its stamp. Once
         # all active tasks are marked, prune the ones we don't need.
 
-        bb.msg.note(2, bb.msg.domain.RunQueue, "Marking Active Tasks")
+        logger.verbose("Marking Active Tasks")
 
         def mark_active(listid, depth):
             """
@@ -600,7 +603,7 @@ class RunQueueData:
 
             # Remove stamps for targets if force mode active
             if self.cooker.configuration.force:
-                bb.msg.note(2, bb.msg.domain.RunQueue, "Remove stamp %s, %s" % (target[1], fn))
+                logger.verbose("Remove stamp %s, %s", target[1], fn)
                 bb.build.del_stamp(target[1], self.dataCache, fn)
 
             if fnid in taskData.failed_fnids:
@@ -643,7 +646,7 @@ class RunQueueData:
             else:
                 bb.msg.fatal(bb.msg.domain.RunQueue, "No active tasks and not in --continue mode?! Please report this bug.")
 
-        bb.msg.note(2, bb.msg.domain.RunQueue, "Pruned %s inactive tasks, %s left" % (delcount, len(self.runq_fnid)))
+        logger.verbose("Pruned %s inactive tasks, %s left", delcount, len(self.runq_fnid))
 
         # Remap the dependencies to account for the deleted tasks
         # Check we didn't delete a task we depend on
@@ -656,7 +659,7 @@ class RunQueueData:
                 newdeps.append(maps[origdep])
             self.runq_depends[listid] = set(newdeps)
 
-        bb.msg.note(2, bb.msg.domain.RunQueue, "Assign Weightings")
+        logger.verbose("Assign Weightings")
 
         # Generate a list of reverse dependencies to ease future calculations
         for listid in range(len(self.runq_fnid)):
@@ -675,7 +678,7 @@ class RunQueueData:
                     #self.dump_data(taskData)
                     bb.msg.fatal(bb.msg.domain.RunQueue, "Task %s (%s) has circular dependency on %s (%s)" % (taskData.fn_index[self.runq_fnid[dep]], self.runq_task[dep], taskData.fn_index[self.runq_fnid[listid]], self.runq_task[listid]))
 
-        bb.msg.note(2, bb.msg.domain.RunQueue, "Compute totals (have %s endpoint(s))" % len(endpoints))
+        logger.verbose("Compute totals (have %s endpoint(s))", len(endpoints))
 
         # Calculate task weights
         # Check of higher length circular dependencies
@@ -698,9 +701,7 @@ class RunQueueData:
         for prov in prov_list:
             if len(prov_list[prov]) > 1 and prov not in self.multi_provider_whitelist:
                 error = True
-                bb.msg.error(bb.msg.domain.RunQueue, "Multiple .bb files are due to be built which each provide %s (%s).\n This usually means one provides something the other doesn't and should." % (prov, " ".join(prov_list[prov])))
-        #if error:
-        #    bb.msg.fatal(bb.msg.domain.RunQueue, "Corrupted metadata configuration detected, aborting...")
+                logger.error("Multiple .bb files are due to be built which each provide %s (%s).\n This usually means one provides something the other doesn't and should.", prov, " ".join(prov_list[prov]))
 
 
         # Create a whitelist usable by the stamp checks
@@ -762,20 +763,20 @@ class RunQueueData:
         """
         Dump some debug information on the internal data structures
         """
-        bb.msg.debug(3, bb.msg.domain.RunQueue, "run_tasks:")
+        logger.debug(3, "run_tasks:")
         for task in range(len(self.rqdata.runq_task)):
-            bb.msg.debug(3, bb.msg.domain.RunQueue, " (%s)%s - %s: %s   Deps %s RevDeps %s" % (task,
+            logger.debug(3, " (%s)%s - %s: %s   Deps %s RevDeps %s" % (task,
                 taskQueue.fn_index[self.rqdata.runq_fnid[task]],
                 self.rqdata.runq_task[task],
                 self.rqdata.runq_weight[task],
                 self.rqdata.runq_depends[task],
                 self.rqdata.runq_revdeps[task]))
 
-        bb.msg.debug(3, bb.msg.domain.RunQueue, "sorted_tasks:")
+        logger.debug(3, "sorted_tasks:")
         for task1 in range(len(self.rqdata.runq_task)):
             if task1 in self.prio_map:
                 task = self.prio_map[task1]
-                bb.msg.debug(3, bb.msg.domain.RunQueue, " (%s)%s - %s: %s   Deps %s RevDeps %s" % (task,
+                logger.debug(3, " (%s)%s - %s: %s   Deps %s RevDeps %s" % (task,
                     taskQueue.fn_index[self.rqdata.runq_fnid[task]],
                     self.rqdata.runq_task[task],
                     self.rqdata.runq_weight[task],
@@ -913,12 +914,12 @@ class RunQueue:
 
         # If the stamp is missing its not current
         if not os.access(stampfile, os.F_OK):
-            bb.msg.debug(2, bb.msg.domain.RunQueue, "Stampfile %s not available\n" % stampfile)
+            logger.debug(2, "Stampfile %s not available\n" % stampfile)
             return False
         # If its a 'nostamp' task, it's not current
         taskdep = self.rqdata.dataCache.task_deps[fn]
         if 'nostamp' in taskdep and taskname in taskdep['nostamp']:
-            bb.msg.debug(2, bb.msg.domain.RunQueue, "%s.%s is nostamp\n" % (fn, taskname))
+            logger.debug(2, "%s.%s is nostamp\n" % (fn, taskname))
             return False
 
         if taskname.endswith("_setscene"):
@@ -938,10 +939,10 @@ class RunQueue:
                    continue
                 if fn == fn2 or (fulldeptree and fn2 not in stampwhitelist):
                     if not t2:
-                        bb.msg.debug(2, bb.msg.domain.RunQueue, "Stampfile %s does not exist" % (stampfile2))
+                        logger.debug(2, "Stampfile %s does not exist" % (stampfile2))
                         iscurrent = False
                     if t1 < t2:
-                        bb.msg.debug(2, bb.msg.domain.RunQueue, "Stampfile %s < %s" % (stampfile, stampfile2))
+                        logger.debug(2, "Stampfile %s < %s" % (stampfile, stampfile2))
                         iscurrent = False
 
         return iscurrent
@@ -972,7 +973,7 @@ class RunQueue:
             retval = self.rqexe.execute()
 
         if self.state is runQueueRunInit:
-            bb.msg.note(1, bb.msg.domain.RunQueue, "Executing RunQueue Tasks")
+            logger.info("Executing RunQueue Tasks")
             self.rqexe = RunQueueExecuteTasks(self)
             self.state = runQueueRunning
 
@@ -991,7 +992,7 @@ class RunQueue:
 
         if self.state is runQueueComplete:
             # All done
-            bb.msg.note(1, bb.msg.domain.RunQueue, "Tasks Summary: Attempted %d tasks of which %d didn't need to be rerun and %d failed." % (self.rqexe.stats.completed, self.rqexe.stats.skipped, self.rqexe.stats.failed))
+            logger.info("Tasks Summary: Attempted %d tasks of which %d didn't need to be rerun and %d failed." % (self.rqexe.stats.completed, self.rqexe.stats.skipped, self.rqexe.stats.failed))
             return False
 
         if self.state is runQueueChildProcess:
@@ -1059,7 +1060,7 @@ class RunQueueExecute:
 
     def finish_now(self):
         if self.stats.active:
-            bb.msg.note(1, bb.msg.domain.RunQueue, "Sending SIGTERM to remaining %s tasks" % self.stats.active)
+            logger.info("Sending SIGTERM to remaining %s tasks", self.stats.active)
             for k, v in self.build_pids.iteritems():
                 try:
                     os.kill(-k, signal.SIGTERM)
@@ -1101,7 +1102,7 @@ class RunQueueExecute:
             fakedirs = (the_data.getVar("FAKEROOTDIRS", True) or "").split()
             for p in fakedirs:
                 bb.mkdirhier(p)
-            bb.msg.debug(2, bb.msg.domain.RunQueue, "Running %s:%s under fakeroot, state dir is %s" % (fn, taskname, fakedirs))
+            logger.debug(2, "Running %s:%s under fakeroot, state dir is %s" % (fn, taskname, fakedirs))
 
         env['PATH'] = self.cooker.configuration.initial_path
 
@@ -1220,7 +1221,7 @@ class RunQueueExecuteTasks(RunQueueExecute):
         for scheduler in self.rqdata.schedulers:
             if self.scheduler == scheduler.name:
                 self.sched = scheduler(self, self.rqdata)
-                bb.msg.debug(1, bb.msg.domain.RunQueue, "Using runqueue scheduler '%s'" % scheduler.name)
+                logger.debug(1, "Using runqueue scheduler '%s'" % scheduler.name)
                 break
         else:
             bb.fatal("Invalid scheduler '%s'. Available schedulers: %s" %
@@ -1246,7 +1247,7 @@ class RunQueueExecuteTasks(RunQueueExecute):
                 self.runq_buildable[revdep] = 1
                 fn = self.rqdata.taskData.fn_index[self.rqdata.runq_fnid[revdep]]
                 taskname = self.rqdata.runq_task[revdep]
-                bb.msg.debug(1, bb.msg.domain.RunQueue, "Marking task %s (%s, %s) as buildable" % (revdep, fn, taskname))
+                logger.debug(1, "Marking task %s (%s, %s) as buildable" % (revdep, fn, taskname))
 
     def task_complete(self, task):
         self.stats.taskCompleted()
@@ -1258,7 +1259,7 @@ class RunQueueExecuteTasks(RunQueueExecute):
         Called when a task has failed
         Updates the state engine with the failure
         """
-        bb.msg.error(bb.msg.domain.RunQueue, "Task %s (%s) failed with %s" % (task, self.rqdata.get_user_idstring(task), exitcode))
+        logger.error("Task %s (%s) failed with %s" % (task, self.rqdata.get_user_idstring(task), exitcode))
         self.stats.taskFailed()
         fnid = self.rqdata.runq_fnid[task]
         self.failed_fnids.append(fnid)
@@ -1287,7 +1288,7 @@ class RunQueueExecuteTasks(RunQueueExecute):
 
             taskname = self.rqdata.runq_task[task]
             if self.rq.check_stamp_task(task, taskname):
-                bb.msg.debug(2, bb.msg.domain.RunQueue, "Stamp current task %s (%s)" % (task, self.rqdata.get_user_idstring(task)))
+                logger.debug(2, "Stamp current task %s (%s)" % (task, self.rqdata.get_user_idstring(task)))
                 self.task_skip(task)
                 return True
 
@@ -1295,8 +1296,7 @@ class RunQueueExecuteTasks(RunQueueExecute):
 
             taskdep = self.rqdata.dataCache.task_deps[fn]
             if 'noexec' in taskdep and taskname in taskdep['noexec']:
-                bb.msg.note(1, bb.msg.domain.RunQueue,
-                        "Noexec task %d of %d (ID: %s, %s)" % (self.stats.completed + self.stats.active + self.stats.failed + 1,
+                logger.info("Noexec task %d of %d (ID: %s, %s)" % (self.stats.completed + self.stats.active + self.stats.failed + 1,
                                                                 self.stats.total,
                                                                 task,
                                                                 self.rqdata.get_user_idstring(task)))
@@ -1306,8 +1306,7 @@ class RunQueueExecuteTasks(RunQueueExecute):
                 self.task_complete(task)
                 return True
 
-            bb.msg.note(1, bb.msg.domain.RunQueue,
-                        "Running task %d of %d (ID: %s, %s)" % (self.stats.completed + self.stats.active + self.stats.failed + 1,
+            logger.info("Running task %d of %d (ID: %s, %s)" % (self.stats.completed + self.stats.active + self.stats.failed + 1,
                                                                 self.stats.total,
                                                                 task,
                                                                 self.rqdata.get_user_idstring(task)))
@@ -1334,11 +1333,11 @@ class RunQueueExecuteTasks(RunQueueExecute):
         # Sanity Checks
         for task in range(self.stats.total):
             if self.runq_buildable[task] == 0:
-                bb.msg.error(bb.msg.domain.RunQueue, "Task %s never buildable!" % task)
+                logger.error("Task %s never buildable!" % task)
             if self.runq_running[task] == 0:
-                bb.msg.error(bb.msg.domain.RunQueue, "Task %s never ran!" % task)
+                logger.error("Task %s never ran!" % task)
             if self.runq_complete[task] == 0:
-                bb.msg.error(bb.msg.domain.RunQueue, "Task %s never completed!" % task)
+                logger.error("Task %s never completed!" % task)
         self.rq.state = runQueueComplete
         return True
 
@@ -1461,12 +1460,12 @@ class RunQueueExecuteScenequeue(RunQueueExecute):
 
             for task in range(len(self.sq_revdeps)):
                 if task not in valid_new and task not in noexec:
-                    bb.msg.debug(2, bb.msg.domain.RunQueue, "No package found so skipping setscene task %s" % (self.rqdata.get_user_idstring(self.rqdata.runq_setscene[task])))
+                    logger.debug(2, "No package found so skipping setscene task %s" % (self.rqdata.get_user_idstring(self.rqdata.runq_setscene[task])))
                     self.task_failoutright(task)
 
             #print(str(valid))
 
-        bb.msg.note(1, bb.msg.domain.RunQueue, "Executing SetScene Tasks")
+        logger.info("Executing SetScene Tasks")
 
         self.rq.state = runQueueSceneRun
 
@@ -1484,7 +1483,7 @@ class RunQueueExecuteScenequeue(RunQueueExecute):
         """
 
         index = self.rqdata.runq_setscene[task]
-        bb.msg.debug(1, bb.msg.domain.RunQueue, "Found task %s could be accelerated" % self.rqdata.get_user_idstring(index))
+        logger.debug(1, "Found task %s could be accelerated" % self.rqdata.get_user_idstring(index))
 
         self.scenequeue_covered.add(task)
         self.scenequeue_updatecounters(task)
@@ -1539,7 +1538,7 @@ class RunQueueExecuteScenequeue(RunQueueExecute):
 
             taskname = self.rqdata.runq_task[realtask] + "_setscene"
             if self.rq.check_stamp_task(realtask, self.rqdata.runq_task[realtask]):
-                bb.msg.debug(2, bb.msg.domain.RunQueue, "Stamp for underlying task %s (%s) is current so skipping setscene varient" % (task, self.rqdata.get_user_idstring(task)))
+                logger.debug(2, "Stamp for underlying task %s (%s) is current so skipping setscene varient" % (task, self.rqdata.get_user_idstring(task)))
                 self.task_failoutright(task)
                 return True
 
@@ -1550,12 +1549,11 @@ class RunQueueExecuteScenequeue(RunQueueExecute):
                         return True
 
             if self.rq.check_stamp_task(realtask, taskname):
-                bb.msg.debug(2, bb.msg.domain.RunQueue, "Setscene stamp current task %s (%s) so skip it and its dependencies" % (task, self.rqdata.get_user_idstring(realtask)))
+                logger.debug(2, "Setscene stamp current task %s (%s) so skip it and its dependencies" % (task, self.rqdata.get_user_idstring(realtask)))
                 self.task_skip(task)
                 return True
 
-            bb.msg.note(1, bb.msg.domain.RunQueue,
-                        "Running setscene task %d of %d (%s:%s)" % (self.stats.completed + self.stats.active + self.stats.failed + 1,
+            logger.info("Running setscene task %d of %d (%s:%s)" % (self.stats.completed + self.stats.active + self.stats.failed + 1,
                                                                          self.stats.total, fn, taskname))
 
             pid, pipein, pipeout = self.fork_off_task(fn, realtask, taskname)