sync: Log repo sync state events as 'data' events.

git_trace2_event_log.py:
+ Added LogDataConfigEvents method to log 'data' events.
  Sync's current_sync_state and previous_sync_state are logged
  as 'data' events in the current log.

  It logs are key/value in the |config| argument. Each key is
  prefixed with |prefix| argument.

  The following are sample events that are logged during repo sync.

   {"event":"data",
   "sid":"repo-20210914T181545Z-P000330c0/repo-20210914T181545Z-P000330c0",
   "thread":"MainThread",
   "time":"2021-09-14T18:16:19.935846Z",
   "key":"previous_sync_state/repo.syncstate.main.synctime",
   "value":"2021-09-14T17:27:11.573717Z"}

   {"event":"data",
   "sid":"repo-20210914T181545Z-P000330c0/repo-20210914T181545Z-P000330c0",
   "thread":"MainThread",
   "time":"2021-09-14T18:16:19.955546Z",
   "key":"current_sync_state/repo.syncstate.main.synctime",
   "value":"2021-09-14T18:16:19.935979Z"}

tests/test_git_trace2_event_log.py:
+ Added unit tests

sync.py:
+ Changed logging calls to LogDataConfigEvents.

Tested:
$ ./run_tests

Tested it by running the following command multiple times.
$ repo_dev sync -j 20
  repo sync has finished successfully

  Verified config data is looged in trace2 event logs.

Bug: [google internal] b/199758376
Change-Id: I75fd830e90c1811ec28510538c99a2632b104e85
Reviewed-on: https://gerrit-review.googlesource.com/c/git-repo/+/317823
Reviewed-by: Josh Steadmon <steadmon@google.com>
Reviewed-by: Xin Li <delphij@google.com>
Tested-by: Raman Tenneti <rtenneti@google.com>

4 files changed, 54 insertions, 5 deletions

diff --git a/git_trace2_event_log.py b/git_trace2_event_log.py
index 9c9e5a70..92c4cc6b 100644
--- a/git_trace2_event_log.py
+++ b/git_trace2_event_log.py
@@ -167,6 +167,22 @@ class EventLog(object):
     repo_config = {k: v for k, v in config.items() if k.startswith('repo.')}
     self.LogConfigEvents(repo_config, 'def_param')
 
+  def LogDataConfigEvents(self, config, prefix):
+    """Append a 'data' event for each config key/value in |config| to the current log.
+
+    For each keyX and valueX of the config, "key" field of the event is '|prefix|/keyX'
+    and the "value" of the "key" field is valueX.
+
+    Args:
+      config: Configuration dictionary.
+      prefix: Prefix for each key that is logged.
+    """
+    for key, value in config.items():
+      event = self._CreateEventDict('data')
+      event['key'] = f'{prefix}/{key}'
+      event['value'] = value
+      self._log.append(event)
+
   def ErrorEvent(self, msg, fmt):
     """Append a 'error' event to the current log."""
     error_event = self._CreateEventDict('error')
diff --git a/subcmds/sync.py b/subcmds/sync.py
index 2a0de0a9..c99b06ca 100644
--- a/subcmds/sync.py
+++ b/subcmds/sync.py
@@ -1092,13 +1092,13 @@ later is required to fix a server side protocol bug.
       sys.exit(1)
 
     # Log the previous sync analysis state from the config.
-    self.git_event_log.LogConfigEvents(mp.config.GetSyncAnalysisStateData(),
-                                       'previous_sync_state')
+    self.git_event_log.LogDataConfigEvents(mp.config.GetSyncAnalysisStateData(),
+                                           'previous_sync_state')
 
     # Update and log with the new sync analysis state.
     mp.config.UpdateSyncAnalysisState(opt, superproject_logging_data)
-    self.git_event_log.LogConfigEvents(mp.config.GetSyncAnalysisStateData(),
-                                       'current_sync_state')
+    self.git_event_log.LogDataConfigEvents(mp.config.GetSyncAnalysisStateData(),
+                                           'current_sync_state')
 
     if not opt.quiet:
       print('repo sync has finished successfully.')
diff --git a/tests/fixtures/test.gitconfig b/tests/fixtures/test.gitconfig
index 90afff04..b178cf60 100644
--- a/tests/fixtures/test.gitconfig
+++ b/tests/fixtures/test.gitconfig
@@ -12,7 +12,7 @@
         intm = 10m
         intg = 10g
 [repo "syncstate.main"]
-        synctime = 2021-08-13T18:37:43.928600Z
+        synctime = 2021-09-14T17:23:43.537338Z
         version = 1
 [repo "syncstate.sys"]
         argv = ['/usr/bin/pytest-3']
diff --git a/tests/test_git_trace2_event_log.py b/tests/test_git_trace2_event_log.py
index bee5865b..a5a6cbba 100644
--- a/tests/test_git_trace2_event_log.py
+++ b/tests/test_git_trace2_event_log.py
@@ -234,6 +234,39 @@ class EventLogTestCase(unittest.TestCase):
     self.assertEqual(len(self._log_data), 1)
     self.verifyCommonKeys(self._log_data[0], expected_event_name='version')
 
+  def test_data_event_config(self):
+    """Test 'data' event data outputs all config keys.
+
+    Expected event log:
+    <version event>
+    <data event>
+    <data event>
+    """
+    config = {
+        'git.foo': 'bar',
+        'repo.partialclone': 'false',
+        'repo.syncstate.superproject.hassuperprojecttag': 'true',
+    }
+    prefix_value = 'prefix'
+    self._event_log_module.LogDataConfigEvents(config, prefix_value)
+
+    with tempfile.TemporaryDirectory(prefix='event_log_tests') as tempdir:
+      log_path = self._event_log_module.Write(path=tempdir)
+      self._log_data = self.readLog(log_path)
+
+    self.assertEqual(len(self._log_data), 4)
+    data_events = self._log_data[1:]
+    self.verifyCommonKeys(self._log_data[0], expected_event_name='version')
+
+    for event in data_events:
+      self.verifyCommonKeys(event, expected_event_name='data')
+      # Check for 'data' event specific fields.
+      self.assertIn('key', event)
+      self.assertIn('value', event)
+      key = event['key'].removeprefix(f'{prefix_value}/')
+      value = event['value']
+      self.assertTrue(key in config and value == config[key])
+
   def test_error_event(self):
     """Test and validate 'error' event data is valid.