feat: Improve codejail darklaunch logging (#36671)

This is intended to make logs more or less a standalone source for
analyzing mismatches.

- Only log mismatches or exceptions
- Merge local and remote log messages into one so they can be correlated
  more easily
- Different log messages for mismatch vs. unexpected exceptions
- Include course ID (as limit overrides context) in log message

Author: timmc-edx

xmodule/capa/safe_exec/safe_exec.py

@@ -272,7 +272,7 @@ def safe_exec(
                 local_exc_unexpected = None if isinstance(exception, SafeExecException) else exception
 
                 report_darklaunch_results(
-                    slug=slug,
+                    limit_overrides_context=limit_overrides_context, slug=slug,
                     globals_local=globals_dict, emsg_local=emsg, unexpected_exc_local=local_exc_unexpected,
                     globals_remote=darklaunch_globals, emsg_remote=remote_emsg, unexpected_exc_remote=remote_exception,
                 )
@@ -347,14 +347,19 @@ def normalize_error_message(emsg):
 
 
 def report_darklaunch_results(
-        *, slug,
+        *, limit_overrides_context, slug,
         globals_local, emsg_local, unexpected_exc_local,
         globals_remote, emsg_remote, unexpected_exc_remote,
 ):
     """Send telemetry for results of darklaunch."""
     can_compare_output = True
 
-    def report_arm(arm, globals_dict, emsg, unexpected_exception):
+    def report_arm(arm, emsg, unexpected_exception):
+        """
+        Set custom attributes for each arm of the darklaunch experiment.
+
+        `arm` should be 'local' or 'remote'.
+        """
         nonlocal can_compare_output
         if unexpected_exception:
             # .. custom_attribute_name: codejail.darklaunch.status.{local,remote}
@@ -373,25 +378,33 @@ def report_arm(arm, globals_dict, emsg, unexpected_exception):
             set_custom_attribute(f'codejail.darklaunch.status.{arm}', 'ok' if emsg is None else 'safe_error')
             set_custom_attribute(f'codejail.darklaunch.exception.{arm}', None)
 
-        # Logs include full globals and emsg
-        log.info(
-            f"Codejail darklaunch {arm} results for slug={slug}: globals={globals_dict!r}, "
-            f"emsg={emsg!r}, exception={unexpected_exception!r}"
-        )
-
-    report_arm('local', globals_local, emsg_local, unexpected_exc_local)
-    report_arm('remote', globals_remote, emsg_remote, unexpected_exc_remote)
+    report_arm('local', emsg_local, unexpected_exc_local)
+    report_arm('remote', emsg_remote, unexpected_exc_remote)
 
     # If the arms can't be compared (unexpected errors), stop early -- the rest
     # is about output comparison.
     if not can_compare_output:
         set_custom_attribute('codejail.darklaunch.globals_match', 'N/A')
         set_custom_attribute('codejail.darklaunch.emsg_match', 'N/A')
+        log.info(
+            "Codejail darklaunch had unexpected exception for "
+            f"course={limit_overrides_context!r}, slug={slug!r}:\n"
+            f"Local exception: {unexpected_exc_local!r}\n"
+            f"Remote exception: {unexpected_exc_remote!r}"
+        )
         return
 
     globals_match = globals_local == globals_remote
     emsg_match = normalize_error_message(emsg_local) == normalize_error_message(emsg_remote)
 
+    if not globals_match or not emsg_match:
+        log.info(
+            f"Codejail darklaunch had mismatch for course={limit_overrides_context!r}, slug={slug!r}:\n"
+            f"{emsg_match=}, {globals_match=}\n"
+            f"Local: globals={globals_local!r}, emsg={emsg_local!r}\n"
+            f"Remote: globals={globals_remote!r}, emsg={emsg_remote!r}"
+        )
+
     # .. custom_attribute_name: codejail.darklaunch.globals_match
     # .. custom_attribute_description: True if local and remote globals_dict
     #   values match, False otherwise. 'N/A' when either arm raised an

xmodule/capa/safe_exec/tests/test_safe_exec.py

@@ -195,7 +195,10 @@ def run_dark_launch(
             mock_remote_exec.side_effect = remote
 
             try:
-                safe_exec("<IGNORED BY MOCKS>", globals_dict)
+                safe_exec(
+                    "<IGNORED BY MOCKS>", globals_dict,
+                    limit_overrides_context="course-v1:org+course+run", slug="hw1",
+                )
             except BaseException as e:
                 safe_exec_e = e
             else:
@@ -215,8 +218,8 @@ def run_dark_launch(
 
     # These don't change between the tests
     standard_codejail_attr_calls = [
-        call('codejail.slug', None),
-        call('codejail.limit_overrides_context', None),
+        call('codejail.slug', 'hw1'),
+        call('codejail.limit_overrides_context', 'course-v1:org+course+run'),
         call('codejail.extra_files_count', 0),
     ]
 
@@ -256,12 +259,11 @@ def remote_exec(data):
             ],
             expect_log_info_calls=[
                 call(
-                    "Codejail darklaunch local results for slug=None: globals={'overwrite': 'mock local'}, "
-                    "emsg=None, exception=None"
-                ),
-                call(
-                    "Codejail darklaunch remote results for slug=None: globals={'overwrite': 'mock remote'}, "
-                    "emsg=None, exception=None"
+                    "Codejail darklaunch had mismatch for "
+                    "course='course-v1:org+course+run', slug='hw1':\n"
+                    "emsg_match=True, globals_match=False\n"
+                    "Local: globals={'overwrite': 'mock local'}, emsg=None\n"
+                    "Remote: globals={'overwrite': 'mock remote'}, emsg=None"
                 ),
             ],
             # Should only see behavior of local exec
@@ -296,12 +298,10 @@ def remote_exec(data):
             ],
             expect_log_info_calls=[
                 call(
-                    "Codejail darklaunch local results for slug=None: globals={}, "
-                    "emsg='unexpected', exception=BaseException('unexpected')"
-                ),
-                call(
-                    "Codejail darklaunch remote results for slug=None: globals={}, "
-                    "emsg=None, exception=None"
+                    "Codejail darklaunch had unexpected exception "
+                    "for course='course-v1:org+course+run', slug='hw1':\n"
+                    "Local exception: BaseException('unexpected')\n"
+                    "Remote exception: None"
                 ),
             ],
             expect_globals_contains={},
@@ -332,12 +332,11 @@ def remote_exec(data):
             ],
             expect_log_info_calls=[
                 call(
-                    "Codejail darklaunch local results for slug=None: globals={}, "
-                    "emsg='oops', exception=None"
-                ),
-                call(
-                    "Codejail darklaunch remote results for slug=None: globals={}, "
-                    "emsg='OH NO', exception=None"
+                    "Codejail darklaunch had mismatch for "
+                    "course='course-v1:org+course+run', slug='hw1':\n"
+                    "emsg_match=False, globals_match=True\n"
+                    "Local: globals={}, emsg='oops'\n"
+                    "Remote: globals={}, emsg='OH NO'"
                 ),
             ],
             expect_globals_contains={},
@@ -365,16 +364,7 @@ def remote_exec(data):
                 call('codejail.darklaunch.globals_match', True),
                 call('codejail.darklaunch.emsg_match', True),  # even though not exact match
             ],
-            expect_log_info_calls=[
-                call(
-                    "Codejail darklaunch local results for slug=None: globals={}, "
-                    "emsg='stack trace involving /tmp/codejail-1234567/whatever.py', exception=None"
-                ),
-                call(
-                    "Codejail darklaunch remote results for slug=None: globals={}, "
-                    "emsg='stack trace involving /tmp/codejail-abcd_EFG/whatever.py', exception=None"
-                ),
-            ],
+            expect_log_info_calls=[],
             expect_globals_contains={},
         )
         assert isinstance(results['raised'], SafeExecException)