[Logging] Add new log context for grouper-related structured logging (#4785)

Changes to the logs module in order to enable structured logging for the
grouper task:
* Adapting the testcase-based context to also accept the
`TestcaseAttributes` class (used by the grouper).
* Adding a new log context for grouping, which is an edge case where
pairs of testcases are processed each step.

In addition, this PR also adds unit tests and comments that were missing
in the logs module.

Author: ViniciustCosta

src/clusterfuzz/_internal/metrics/logs.py

@@ -33,6 +33,7 @@
 
 # This is needed to avoid circular import
 if TYPE_CHECKING:
+  from clusterfuzz._internal.cron.grouper import TestcaseAttributes
   from clusterfuzz._internal.datastore.data_types import FuzzTarget
   from clusterfuzz._internal.datastore.data_types import Testcase
 
@@ -663,6 +664,7 @@ def log_fatal_and_exit(message, **extras):
 
 def get_common_log_context() -> dict[str, str]:
   """Return common context to be propagated by logs."""
+  # Avoid circular imports on the top level.
   from clusterfuzz._internal.base import utils
   from clusterfuzz._internal.system import environment
 
@@ -694,6 +696,18 @@ def get_common_log_context() -> dict[str, str]:
     return {}
 
 
+def get_testcase_id(
+    testcase: 'Testcase | TestcaseAttributes') -> int | str | None:
+  """Return the ID for a testcase or testcase attributes object."""
+  # Importing here as 3P libs becomes accessible during runtime, after modules
+  # path search is resolved (and logs may be imported before that).
+  from google.cloud import ndb
+
+  if isinstance(testcase, ndb.Model):
+    return testcase.key.id()  # type: ignore
+  return getattr(testcase, 'id', None)
+
+
 class GenericLogStruct(NamedTuple):
   pass
 
@@ -729,6 +743,13 @@ class TestcaseLogStruct(NamedTuple):
   testcase_id: str
 
 
+class GrouperLogStruct(NamedTuple):
+  testcase_1_id: str
+  testcase_1_group: str | int
+  testcase_2_id: str
+  testcase_2_group: str | int
+
+
 class LogContextType(enum.Enum):
   """Log context types.
   
@@ -740,6 +761,7 @@ class LogContextType(enum.Enum):
   FUZZER = 'fuzzer'
   TESTCASE = 'testcase'
   CRON = 'cron'
+  GROUPER = 'grouper'
 
   def get_extras(self) -> NamedTuple:
     """Get the structured log for a given context"""
@@ -793,15 +815,8 @@ def get_extras(self) -> NamedTuple:
 
     if self == LogContextType.TESTCASE:
       try:
-        testcase: 'Testcase | None' = log_contexts.meta.get('testcase')
-        if not testcase:
-          error(
-              'Testcase not found in log context metadata.',
-              ignore_context=True)
-          return GenericLogStruct()
-
-        return TestcaseLogStruct(testcase_id=testcase.key.id())  # type: ignore
-
+        return TestcaseLogStruct(
+            testcase_id=log_contexts.meta.get('testcase_id', 'null'))
       except:
         error(
             'Error retrieving context for testcase-based logs.',
@@ -819,6 +834,19 @@ def get_extras(self) -> NamedTuple:
             ignore_context=True)
         return GenericLogStruct()
 
+    if self == LogContextType.GROUPER:
+      try:
+        return GrouperLogStruct(
+            testcase_1_id=log_contexts.meta.get('testcase_1_id', 'null'),
+            testcase_2_id=log_contexts.meta.get('testcase_2_id', 'null'),
+            testcase_1_group=log_contexts.meta.get('testcase_1_group', 'null'),
+            testcase_2_group=log_contexts.meta.get('testcase_2_group', 'null'))
+      except:
+        error(
+            'Error retrieving context for grouper-based logs.',
+            ignore_context=True)
+        return GenericLogStruct()
+
     return GenericLogStruct()
 
 
@@ -925,7 +953,7 @@ def fuzzer_log_context(fuzzer_name: str, job_type: str,
 
 
 @contextlib.contextmanager
-def testcase_log_context(testcase: 'Testcase',
+def testcase_log_context(testcase: 'Testcase | TestcaseAttributes',
                          fuzz_target: 'FuzzTarget | None'):
   """Creates a testcase-based context for a given testcase.
 
@@ -936,10 +964,12 @@ def testcase_log_context(testcase: 'Testcase',
   with wrap_log_context(
       contexts=[LogContextType.FUZZER, LogContextType.TESTCASE]):
     try:
-      log_contexts.add_metadata('testcase', testcase)  # type: ignore
+      log_contexts.add_metadata('testcase', testcase)
       if testcase:
-        log_contexts.add_metadata('fuzzer_name', testcase.fuzzer_name)
-        log_contexts.add_metadata('job_type', testcase.job_type)
+        log_contexts.add_metadata('testcase_id', get_testcase_id(testcase))
+        log_contexts.add_metadata('fuzzer_name',
+                                  testcase.fuzzer_name)  # type: ignore
+        log_contexts.add_metadata('job_type', testcase.job_type)  # type: ignore
         if fuzz_target and fuzz_target.binary:
           fuzz_target_bin = fuzz_target.binary
         else:
@@ -955,16 +985,43 @@ def testcase_log_context(testcase: 'Testcase',
       raise e
     finally:
       log_contexts.delete_metadata('testcase')
+      log_contexts.delete_metadata('testcase_id')
       log_contexts.delete_metadata('fuzzer_name')
       log_contexts.delete_metadata('job_type')
       log_contexts.delete_metadata('fuzz_target')
 
 
 @contextlib.contextmanager
 def cron_log_context():
+  """Creates a cronjob log context, mainly for triage/cleanup tasks."""
   with wrap_log_context(contexts=[LogContextType.CRON]):
     try:
       yield
     except Exception as e:
       warning(message='Error during cronjob context.')
       raise e
+
+
+@contextlib.contextmanager
+def grouper_log_context(testcase_1: 'Testcase | TestcaseAttributes',
+                        testcase_2: 'Testcase | TestcaseAttributes'):
+  """Creates a grouper context for a given pair of testcases."""
+  with wrap_log_context(contexts=[LogContextType.GROUPER]):
+    try:
+      if testcase_1:
+        log_contexts.add_metadata('testcase_1_id', get_testcase_id(testcase_1))
+        log_contexts.add_metadata('testcase_1_group',
+                                  getattr(testcase_1, 'group_id', 0))
+      if testcase_2:
+        log_contexts.add_metadata('testcase_2_id', get_testcase_id(testcase_2))
+        log_contexts.add_metadata('testcase_2_group',
+                                  getattr(testcase_2, 'group_id', 0))
+      yield
+    except Exception as e:
+      warning(message='Error during grouper context.')
+      raise e
+    finally:
+      log_contexts.delete_metadata('testcase_1_id')
+      log_contexts.delete_metadata('testcase_2_id')
+      log_contexts.delete_metadata('testcase_1_group')
+      log_contexts.delete_metadata('testcase_2_group')

src/clusterfuzz/_internal/tests/core/metrics/logs_test.py

@@ -606,6 +606,7 @@ def test_testcase_log_context(self):
           logs.log_contexts.meta, {
               'common_ctx': self.common_context,
               'testcase': testcase,
+              'testcase_id': 1,
               'fuzz_target': fuzz_target.binary,
               'fuzzer_name': testcase.fuzzer_name,
               'job_type': testcase.job_type
@@ -772,6 +773,7 @@ def test_missing_fuzz_target_in_testcase_context(self):
           logs.log_contexts.meta, {
               'common_ctx': self.common_context,
               'testcase': testcase,
+              'testcase_id': 1,
               'fuzz_target': testcase.get_metadata('fuzzer_binary_name'),
               'fuzzer_name': testcase.fuzzer_name,
               'job_type': testcase.job_type
@@ -790,7 +792,7 @@ def test_missing_fuzz_target_in_testcase_context(self):
             },
         })
 
-  def test_fuzzer_logs_context(self):
+  def test_fuzzer_log_context(self):
     """Test the correct logger call for the fuzzer-based log context."""
     from clusterfuzz._internal.datastore import data_types
     logger = mock.MagicMock()
@@ -832,7 +834,107 @@ def test_fuzzer_logs_context(self):
             'location': {
                 'path': os.path.abspath(__file__).rstrip('c'),
                 'line': statement_line,
-                'method': 'test_fuzzer_logs_context'
+                'method': 'test_fuzzer_log_context'
+            },
+        })
+
+  @logs.cron_log_context()
+  def test_cron_log_context(self):
+    """Test the correct logger call for the cron-based log context."""
+    from clusterfuzz._internal.system.environment import set_task_id_vars
+    task_name = 'cleanup'
+    task_id = '12345-6789'
+    set_task_id_vars(task_name, task_id)
+
+    logger = mock.MagicMock()
+    self.mock.get_logger.return_value = logger
+    self.assertEqual(logs.log_contexts.contexts,
+                     [logs.LogContextType.COMMON, logs.LogContextType.CRON])
+    logs_extra = {'target': 'bot', 'test': 'yes'}
+    logs_extra.update(self.common_context)
+    logs_extra.update({
+        'task_id': task_id,
+        'task_name': task_name,
+    })
+    statement_line = inspect.currentframe().f_lineno + 1
+    logs.emit(logging.ERROR, 'msg', exc_info='ex', target='bot', test='yes')
+    # Assert that the common context was added after the first logs call.
+    self.assertEqual(logs.log_contexts.meta, {
+        'common_ctx': self.common_context,
+    })
+    logger.log.assert_called_once_with(
+        logging.ERROR,
+        'msg',
+        exc_info='ex',
+        extra={
+            'extras': logs_extra,
+            'location': {
+                'path': os.path.abspath(__file__).rstrip('c'),
+                'line': statement_line,
+                'method': 'test_cron_log_context'
+            },
+        })
+
+  @logs.cron_log_context()
+  def test_grouper_log_context(self):
+    """Test the logger call and metadata for a grouper-based context."""
+    from clusterfuzz._internal.cron.grouper import TestcaseAttributes
+    from clusterfuzz._internal.datastore import data_types
+    from clusterfuzz._internal.system.environment import set_task_id_vars
+    task_name = 'triage'
+    task_id = 'abcd-12345'
+    set_task_id_vars(task_name, task_id)
+
+    testcase_1 = data_types.Testcase()
+    testcase_2 = data_types.Testcase(group_id=112233)
+    testcase_1.put()
+    testcase_2.put()
+
+    testcase_1_attr = TestcaseAttributes(testcase_1.key.id())
+    testcase_1_attr.group_id = testcase_1.group_id
+    testcase_2_attr = TestcaseAttributes(testcase_2.key.id())
+    testcase_2_attr.group_id = testcase_2.group_id
+
+    logger = mock.MagicMock()
+    self.mock.get_logger.return_value = logger
+
+    with logs.grouper_log_context(testcase_1_attr, testcase_2_attr):
+      self.assertEqual(logs.log_contexts.contexts, [
+          logs.LogContextType.COMMON, logs.LogContextType.CRON,
+          logs.LogContextType.GROUPER
+      ])
+      statement_line = inspect.currentframe().f_lineno + 1
+      logs.emit(logging.ERROR, 'msg', exc_info='ex', target='bot', test='yes')
+      # Assert metadata after emit to ensure that `common_ctx` has been added.
+      self.assertEqual(
+          logs.log_contexts.meta, {
+              'common_ctx': self.common_context,
+              'testcase_1_id': 1,
+              'testcase_2_id': 2,
+              'testcase_1_group': 0,
+              'testcase_2_group': 112233
+          })
+
+    logs_extra = {'target': 'bot', 'test': 'yes'}
+    logs_extra.update(self.common_context)
+    logs_extra.update({
+        'task_id': task_id,
+        'task_name': task_name,
+        'testcase_1_id': 1,
+        'testcase_2_id': 2,
+        'testcase_1_group': 0,
+        'testcase_2_group': 112233
+    })
+    logger.log.assert_called_with(
+        logging.ERROR,
+        'msg',
+        exc_info='ex',
+        extra={
+            'extras': logs_extra,
+            'location': {
+                'path': os.path.abspath(__file__).rstrip('c'),
+                'line': statement_line,
+                'method': 'test_grouper_log_context'
             },
         })