Improve logging to include library name and job id

automation.py

@@ -225,6 +225,7 @@ def run(self, library_filter=""):
                     continue
 
                 for task in lib.tasks:
+                    self.logger.set_context(lib.name)
                     try:
                         taskRunner = self.taskRunners[task.type]
 
@@ -244,6 +245,7 @@ def run(self, library_filter=""):
                             self.logger.log_exception(Exception("Reached soft timeout"))
                             return
 
+                    self.logger.clear_context()
         except Exception as e:
             self.logger.log_exception(e)
             raise(e)

components/logging.py

@@ -53,6 +53,8 @@ def func_wrapper(*args, **kwargs):
 
 
 class LoggingProvider(BaseProvider):
+    context = ""
+
     def __init__(self, config):
         self.loggers = []
         if 'local' in config and config['local']:
@@ -65,13 +67,25 @@ def _update_config(self, additional_config):
             logger.update_config(additional_config)
 
     def log(self, *args, level=LogLevel.Info, category=None):
+        if LoggingProvider.context != "":
+            category = f"{category} {LoggingProvider.context}"
         for logger in self.loggers:
             logger.log(*args, level=level, category=category)
 
     def log_exception(self, e):
         for logger in self.loggers:
             logger.log_exception(e)
 
+    @staticmethod
+    def set_context(library_name, job_id=None):
+        LoggingProvider.context = library_name
+        if job_id:
+            LoggingProvider.context += " job_id=" + str(job_id)
+
+    @staticmethod
+    def clear_context():
+        LoggingProvider.context = ""
+
 
 class LoggerInstance(BaseProvider):
     def __init__(self):
@@ -102,7 +116,7 @@ def log(self, *args, level, category):
             return
         if level.value <= self.min_log_level:
             prefix = ("[" + level.name + "]").ljust(9)
-            prefix += (" " + category + ":") if category else ""
+            prefix += ("(" + category + ")") if category else ""
             print(prefix, *args, flush=True)
 
     def log_exception(self, e):

tasktypes/commitalert.py

@@ -43,13 +43,15 @@ def process_task(self, library, task):
         jobs_with_open_bugs = [j for j in all_library_jobs if j.bugzilla_id in open_bugs]
         self.logger.log("We need to potentially update the FF version on %s open bugs." % len(open_bugs), level=LogLevel.Info)
         for j in jobs_with_open_bugs:
+            self.logger.set_context(library.name, j.id)
             if my_ff_version not in j.ff_versions:
                 is_affected = _contains_commit(all_upstream_commits, j.version)
                 self.logger.log("Updating bug %s to set FF version %s as %s." % (
                     j.bugzilla_id, my_ff_version, "affected" if is_affected else "unaffected"), level=LogLevel.Info)
                 self.bugzillaProvider.mark_ff_version_affected(j.bugzilla_id, my_ff_version, affected=is_affected)
                 j.ff_versions.add(my_ff_version)
                 self.dbProvider.update_job_ff_versions(j, my_ff_version)
+        self.logger.set_context(library.name)
 
         # ==========================================================================================
         if not unseen_upstream_commits:
@@ -60,6 +62,8 @@ def process_task(self, library, task):
         newest_commit = unseen_upstream_commits[-1]
         existing_job = self.dbProvider.get_job(library, newest_commit.revision)
         if existing_job:
+            self.logger.set_context(library.name, existing_job.id)
+
             if my_ff_version in existing_job.ff_versions:
                 # We've already seen this revision, and we've already associated it with this FF version
                 self.logger.log("We found a job with id %s for revision %s that was already processed for this ff version (%s)." % (
@@ -82,6 +86,7 @@ def process_task(self, library, task):
     @logEntryExit
     def _process_new_commits(self, library, task, new_commits, all_library_jobs):
         assert new_commits
+        self.logger.set_context(library.name, "new")
 
         newest_commit = new_commits[-1]
 

tasktypes/vendoring.py

@@ -40,9 +40,11 @@ def process_task(self, library, task):
 
         # Then process all of them
         for j in all_jobs_not_done:
+            self.logger.set_context(library.name, j.id)
             self.logger.log("Processing job id %s for %s which is currently %s and has a %s bug" % (j.id, library.name, j.status, "open" if j.bugzilla_is_open else "closed"))
             self._process_existing_job(library, task, j)
             self._reset_for_new_job()
+        self.logger.set_context(library.name)
 
         # See if we have a new upstream commit to process
         new_version, timestamp = self.vendorProvider.check_for_update(library)
@@ -103,6 +105,7 @@ def _process_new_job(self, library, task, new_version, timestamp, most_recent_jo
 
         # Create the job ----------------------
         created_job = self.dbProvider.create_job(JOBTYPE.VENDORING, library, new_version, JOBSTATUS.CREATED, JOBOUTCOME.PENDING)
+        self.logger.set_context(library.name, created_job.id)
 
         # File the bug ------------------------
         all_upstream_commits, unseen_upstream_commits = self.scmProvider.check_for_update(library, task, new_version, most_recent_job)