Merge lp:~hloeung/ubuntu-repository-cache/improve-logging-of-juju-run-failures into lp:ubuntu-repository-cache

[Haw Loeung]

Improve logging and output of errors from juju-run failures

We save both STDOUT and STDERR then log it as well as output it for
inclusion in the cron e-mails.

[Barry Price (barryprice)]

LGTM +1

review: Approve

[🤖 Canonical IS Merge Bot (canonical-is-mergebot)]

This merge proposal is being monitored by mergebot. Change the status to Approved to merge.

[🤖 Canonical IS Merge Bot (canonical-is-mergebot)]

Change successfully merged at revision 368

=== modified file 'lib/ubuntu_repository_cache/metadata_sync.py'
--- lib/ubuntu_repository_cache/metadata_sync.py	2022-08-08 22:21:29 +0000
+++ lib/ubuntu_repository_cache/metadata_sync.py	2022-08-09 09:19:39 +0000
@@ -258,7 +258,7 @@
     return os.path.basename(dest)
 
 
-def main(environment, log, mirror_archive=mirror_archive, check_call=subprocess.check_call):
+def main(environment, log, mirror_archive=mirror_archive, check_output=subprocess.check_output):
     """The main function for this script.
 
     This is called at the very bottom of this file should the file be executed
@@ -293,19 +293,26 @@
 
     log("Executing hook: {}".format(cmd))
 
+    errors = []
     # Work around Juju instability issues causing juju-run to abort
     # (LP:1977798).
     max_retries = 10
     for attempt in range(1, max_retries):
         try:
-            check_call(cmd, stdout=subprocess.DEVNULL)
+            output = check_output(cmd, stderr=subprocess.STDOUT)
+            msg = "{}".format(output)
+            log(msg)
         except subprocess.CalledProcessError as e:
             # Save the exact exception and reuse when we need to
             # reraise it after exhausting all available attempts.
             exp = e
             # Exponential backoff.
-            sleep = attempt * random.randint(10, 60)
-            log("Attempt {} failed, sleeping {} - retrying with {}".format(attempt, sleep, meta_ver))
+            sleep = random.randint(attempt, 10 * attempt)
+            msg = "Attempt {} failed, sleeping {} - retrying with {}".format(attempt, sleep, meta_ver)
+            log(msg)
+            log(e.output.decode())
+            errors.append(msg)
+            errors.append(e.output.decode())
             metric_name = 'ubuntu_repository_cache_metadata_sync_failures'
             label = 'meta_ver={}'.format(meta_ver)
             send_to_influx(render_influx(metric_name, label, attempt))
@@ -315,7 +322,10 @@
     else:
         # Exhausted all available attempts, let's re-raise the
         # exception.
-        log("Failed after all available attempts with {}".format(meta_ver))
+        msg = "Failed after all available attempts with {}".format(meta_ver)
+        log(msg)
+        print(msg)
+        print('\n'.join(errors))
         metric_name = 'ubuntu_repository_cache_metadata_sync_failures'
         label = 'meta_ver={}'.format(meta_ver)
         send_to_influx(render_influx(metric_name, label, max_retries))

=== modified file 'lib/ubuntu_repository_cache/tests/test_metadata_sync.py'
--- lib/ubuntu_repository_cache/tests/test_metadata_sync.py	2021-06-08 01:19:59 +0000
+++ lib/ubuntu_repository_cache/tests/test_metadata_sync.py	2022-08-09 09:19:39 +0000
@@ -154,7 +154,7 @@
             "LOCAL_UNIT": "unit/0",
             "UNIT_PATH": "something",
         }
-        result = metadata_sync.main(env, InvocationRecorder(), mirror_archive=noop, check_call=noop)
+        result = metadata_sync.main(env, InvocationRecorder(), mirror_archive=noop, check_output=noop)
         self.assertEqual("Called", result)
 
     def test_main_calls_juju_run(self):
@@ -173,10 +173,10 @@
         def fake_mirror_archive(*args, **kwargs):
             return "some_meta_var"
 
-        fake_check_call = InvocationRecorder()
+        fake_check_output = InvocationRecorder()
 
         result = metadata_sync.main(
-            env, InvocationRecorder(), mirror_archive=fake_mirror_archive, check_call=fake_check_call
+            env, InvocationRecorder(), mirror_archive=fake_mirror_archive, check_output=fake_check_output
         )
 
         self.assertEqual("some_meta_var", result)
@@ -192,11 +192,11 @@
                         'ubuntu-repository-cache-sync some_meta_var',
                     ],
                 ),
-                {'stdout': -3},
+                {'stderr': -2},
             ]
         ]
 
-        self.assertEqual(expected, fake_check_call.invocations)
+        self.assertEqual(expected, fake_check_output.invocations)
 
 
 def _filter_dict(d, keys):