From 6448a4f2af53c241594b5d12eb0d03b18f889eda Mon Sep 17 00:00:00 2001 From: Raman Tenneti Date: Mon, 13 Sep 2021 17:40:07 -0700 Subject: [PATCH] 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 Reviewed-by: Xin Li Tested-by: Raman Tenneti --- git_trace2_event_log.py | 16 +++++++++++++++ subcmds/sync.py | 8 ++++---- tests/fixtures/test.gitconfig | 2 +- tests/test_git_trace2_event_log.py | 33 ++++++++++++++++++++++++++++++ 4 files changed, 54 insertions(+), 5 deletions(-) diff --git a/git_trace2_event_log.py b/git_trace2_event_log.py index 9c9e5a7..92c4cc6 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 2a0de0a..c99b06c 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 90afff0..b178cf6 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 bee5865..a5a6cbb 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: + + + + """ + 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.