Timeout configuration in validation and error message (#1730)

* Fix setting of cell execution timeout in validation

* Make timeout error configurable and visible to users

* Added tests for timeout configuration

nbgrader/preprocessors/execute.py

@@ -1,5 +1,5 @@
 from nbconvert.preprocessors import ExecutePreprocessor, CellExecutionError
-from traitlets import Bool, List, Integer, validate, TraitError
+from traitlets import Bool, List, Dict, Integer, validate, TraitError
 from textwrap import dedent
 
 from . import NbGraderPreprocessor
@@ -41,11 +41,15 @@ class Execute(NbGraderPreprocessor, ExecutePreprocessor):
         help=ExecutePreprocessor.raise_on_iopub_timeout.help
     ).tag(config=True)
 
-    error_on_timeout = {
-        "ename": "CellTimeoutError",
-        "evalue": "",
-        "traceback": ["ERROR: No reply from kernel"]
-    }
+    error_on_timeout = Dict(
+        default_value={
+            "ename": "CellTimeoutError",
+            "evalue": "",
+            # ANSI red color around error name
+            "traceback": ["\x1b[0;31mCellTimeoutError\x1b[0m: No reply from kernel before timeout"]
+        },
+        help=ExecutePreprocessor.error_on_timeout.help,
+    ).tag(config=True)
 
     extra_arguments = List([], help=dedent(
         """
@@ -69,12 +73,11 @@ def on_cell_executed(self, **kwargs):
         if reply['content']['status'] == 'error':
             error_recorded = False
             for output in cell.outputs:
-                if output.output_type == 'error':
+                # If reply ename matches to an output, then they are (probably) the same error
+                if output.output_type == 'error' and output.ename == reply["content"]["ename"]:
                     error_recorded = True
             if not error_recorded:
-                # Occurs when
-                # IPython.core.interactiveshell.InteractiveShell.showtraceback
-                # = lambda *args, **kwargs : None
+                # If enames don't match (i.e. when there is a timeout), then append reply error, so it will be printed
                 error_output = NotebookNode(output_type='error')
                 error_output.ename = reply['content']['ename']
                 error_output.evalue = reply['content']['evalue']

nbgrader/tests/apps/files/timeout.ipynb

@@ -0,0 +1,70 @@
+{
+ "cells": [
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {
+    "deletable": false,
+    "nbgrader": {
+     "cell_type": "code",
+     "checksum": "cc6463a7b1770423bdf8bc8b01bee931",
+     "grade": false,
+     "grade_id": "squares",
+     "locked": false,
+     "schema_version": 3,
+     "solution": true
+    }
+   },
+   "outputs": [],
+   "source": [
+    "import time\n",
+    "def foo():\n",
+    "    time.sleep(5)\n",
+    "    return True"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {
+    "deletable": false,
+    "editable": false,
+    "nbgrader": {
+     "cell_type": "code",
+     "checksum": "a6a51275965b572fa21c2f06be0fccff",
+     "grade": true,
+     "grade_id": "correct_squares",
+     "locked": false,
+     "points": 1,
+     "schema_version": 3,
+     "solution": false
+    }
+   },
+   "outputs": [],
+   "source": [
+    "assert foo()"
+   ]
+  }
+ ],
+ "metadata": {
+  "kernelspec": {
+   "display_name": "Python 3 (ipykernel)",
+   "language": "python",
+   "name": "python3"
+  },
+  "language_info": {
+   "codemirror_mode": {
+    "name": "ipython",
+    "version": 3
+   },
+   "file_extension": ".py",
+   "mimetype": "text/x-python",
+   "name": "python",
+   "nbconvert_exporter": "python",
+   "pygments_lexer": "ipython3",
+   "version": "3.10.10"
+  }
+ },
+ "nbformat": 4,
+ "nbformat_minor": 4
+}

nbgrader/tests/apps/test_nbgrader_autograde.py

@@ -1081,3 +1081,27 @@ def test_grade_with_validating_envvar(self, db, course_dir):
             submission = gb.find_submission("ps1", "foo")
             nb1, = submission.notebooks
             assert nb1.score == 0
+
+    def test_autograde_timeout(self, db, course_dir):
+        """Does autograde accept timeout configuration correctly?"""
+        run_nbgrader(["db", "assignment", "add", "ps1", "--db", db, "--duedate",
+                      "2015-02-02 14:58:23.948203 America/Los_Angeles"])
+        run_nbgrader(["db", "student", "add", "foo", "--db", db])
+        run_nbgrader(["db", "student", "add", "bar", "--db", db])
+
+        self._copy_file(join("files", "timeout.ipynb"), join(course_dir, "source", "ps1", "p1.ipynb"))
+        run_nbgrader(["generate_assignment", "ps1", "--db", db])
+
+        self._copy_file(join("files", "timeout.ipynb"), join(course_dir, "submitted", "foo", "ps1", "p1.ipynb"))
+        self._copy_file(join("files", "timeout.ipynb"), join(course_dir, "submitted", "bar", "ps1", "p1.ipynb"))
+
+        output = run_nbgrader(["autograde", "ps1", "--db", db, "--student", "foo"])
+        # timeout=2 secs, 1 was causing an asyncio error on Windows
+        output = run_nbgrader(["autograde", "ps1", "--db", db, "--student", "bar", "--Execute.timeout=2"])
+
+        # Check timeout config changes function based on timeout config
+        with Gradebook(db) as gb:
+            notebook = gb.find_submission_notebook("p1", "ps1", "foo")
+            assert notebook.score == 1
+            notebook = gb.find_submission_notebook("p1", "ps1", "bar")
+            assert notebook.score == 0

nbgrader/tests/apps/test_nbgrader_validate.py

@@ -1,4 +1,5 @@
 from os.path import join
+from textwrap import dedent
 
 from .. import run_nbgrader
 from .base import BaseTestApp
@@ -14,7 +15,10 @@ def test_validate_unchanged(self):
         """Does the validation fail on an unchanged notebook?"""
         self._copy_file(join("files", "submitted-unchanged.ipynb"), "submitted-unchanged.ipynb")
         output = run_nbgrader(["validate", "submitted-unchanged.ipynb"], stdout=True)
-        assert output.splitlines()[0] == "VALIDATION FAILED ON 3 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        assert (
+            output.splitlines()[0]
+            == "VALIDATION FAILED ON 3 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        )
 
     def test_validate_changed(self):
         """Does the validation pass on an changed notebook?"""
@@ -33,7 +37,10 @@ def test_validate_zero_points(self):
       """Does validation correctly fail when cell has zero points?"""
       self._copy_file(join("files", "validation-zero-points.ipynb"), "validation-zero-points.ipynb")
       output = run_nbgrader(["validate", "validation-zero-points.ipynb"], stdout=True)
-      assert output.splitlines()[0] == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+      assert (
+            output.splitlines()[0]
+            == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+      )
 
     def test_invert_validate_unchanged(self):
         """Does the inverted validation pass on an unchanged notebook?"""
@@ -51,7 +58,10 @@ def test_grade_cell_changed(self):
         """Does the validate fail if a grade cell has changed?"""
         self._copy_file(join("files", "submitted-grade-cell-changed.ipynb"), "submitted-grade-cell-changed.ipynb")
         output = run_nbgrader(["validate", "submitted-grade-cell-changed.ipynb"], stdout=True)
-        assert output.splitlines()[0] == "THE CONTENTS OF 1 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        assert (
+            output.splitlines()[0]
+            == "THE CONTENTS OF 1 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        )
 
     def test_grade_cell_changed_ignore_checksums(self):
         """Does the validate pass if a grade cell has changed but we're ignoring checksums?"""
@@ -66,7 +76,10 @@ def test_invert_grade_cell_changed(self):
         """Does the validate fail if a grade cell has changed, even with --invert?"""
         self._copy_file(join("files", "submitted-grade-cell-changed.ipynb"), "submitted-grade-cell-changed.ipynb")
         output = run_nbgrader(["validate", "submitted-grade-cell-changed.ipynb", "--invert"], stdout=True)
-        assert output.splitlines()[0] == "THE CONTENTS OF 1 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        assert (
+            output.splitlines()[0]
+            == "THE CONTENTS OF 1 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        )
 
     def test_invert_grade_cell_changed_ignore_checksums(self):
         """Does the validate fail if a grade cell has changed with --invert and ignoring checksums?"""
@@ -85,13 +98,19 @@ def test_validate_unchanged_ignore_checksums(self):
             "validate", "submitted-unchanged.ipynb",
             "--Validator.ignore_checksums=True"
         ], stdout=True)
-        assert output.splitlines()[0] == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        assert (
+            output.splitlines()[0]
+            == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        )
 
     def test_locked_cell_changed(self):
         """Does the validate fail if a locked cell has changed?"""
         self._copy_file(join("files", "submitted-locked-cell-changed.ipynb"), "submitted-locked-cell-changed.ipynb")
         output = run_nbgrader(["validate", "submitted-locked-cell-changed.ipynb"], stdout=True)
-        assert output.splitlines()[0] == "THE CONTENTS OF 2 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        assert (
+            output.splitlines()[0]
+            == "THE CONTENTS OF 2 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        )
 
     def test_locked_cell_changed_ignore_checksums(self):
         """Does the validate pass if a locked cell has changed but we're ignoring checksums?"""
@@ -100,13 +119,19 @@ def test_locked_cell_changed_ignore_checksums(self):
             "validate", "submitted-locked-cell-changed.ipynb",
             "--Validator.ignore_checksums=True"
         ], stdout=True)
-        assert output.splitlines()[0] == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        assert (
+                output.splitlines()[0]
+                == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        )
 
     def test_invert_locked_cell_changed(self):
         """Does the validate fail if a locked cell has changed, even with --invert?"""
         self._copy_file(join("files", "submitted-locked-cell-changed.ipynb"), "submitted-locked-cell-changed.ipynb")
         output = run_nbgrader(["validate", "submitted-locked-cell-changed.ipynb", "--invert"], stdout=True)
-        assert output.splitlines()[0] == "THE CONTENTS OF 2 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        assert (
+                output.splitlines()[0]
+                == "THE CONTENTS OF 2 TEST CELL(S) HAVE CHANGED! This might mean that even though the tests"
+        )
 
     def test_invert_locked_cell_changed_ignore_checksums(self):
         """Does the validate fail if a locked cell has changed with --invert and ignoring checksums?"""
@@ -131,5 +156,34 @@ def test_validate_glob(self):
     def test_validate_with_validating_envvar(self, db, course_dir):
         self._copy_file(join("files", "validating-environment-variable.ipynb"), "nb1.ipynb")
         output = run_nbgrader(["validate", "nb1.ipynb"], stdout=True)
-        assert output.splitlines()[0] == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        assert (
+                output.splitlines()[0]
+                == "VALIDATION FAILED ON 1 CELL(S)! If you submit your assignment as it is, you WILL NOT"
+        )
+
+    def test_validate_timeout(self, db, course_dir):
+        """Does validate accept timeout configuration correctly?"""
+        self._copy_file(join("files", "timeout.ipynb"), "nb1.ipynb")
+        output = run_nbgrader(["validate", "nb1.ipynb"], stdout=True)
+        assert output.strip() == "Success! Your notebook passes all the tests."
 
+        # timeout=1 leads to an asyncio error on Windows
+        output = run_nbgrader(["validate", "--Execute.timeout=2", "nb1.ipynb"], stdout=True)
+        assert output.splitlines()[-2].strip() == "CellTimeoutError: No reply from kernel before timeout"
+
+    def test_validate_timeout_config(self, db, course_dir):
+        """Is the timeout error message configurable"""
+        self._copy_file(join("files", "timeout.ipynb"), "nb1.ipynb")
+        # supplying a list as dict value (for traceback) on cli was annoying
+        # writing this into a config file is easier
+        self._make_file("nbgrader_config.py",
+                        dedent("""
+                        c = get_config()
+                        c.Execute.error_on_timeout = {
+                            "ename": "CustomError",
+                            "evalue": "",
+                            "traceback": ["Custom"],
+                        }
+                        """))
+        output = run_nbgrader(["validate", "--Execute.timeout=2", "nb1.ipynb"], stdout=True)
+        assert output.splitlines()[-2].strip() == "Custom"

nbgrader/validator.py

@@ -286,11 +286,8 @@ def _preprocess(self, nb: NotebookNode) -> NotebookNode:
         resources = {}
         with utils.setenv(NBGRADER_VALIDATING='1', NBGRADER_EXECUTION='validate'):
             for preprocessor in self.preprocessors:
-                # https://github.com/jupyter/nbgrader/pull/1075
-                # It seemes that without the self.config passed below,
-                # --ExecutePreprocessor.timeout doesn't work.  Better solution
-                # requested, unknown why this is needed.
-                pp = preprocessor(**self.config[preprocessor.__name__])
+                # Let configuration be handled by traitlets
+                pp = preprocessor(parent=self)
                 nb, resources = pp.preprocess(nb, resources)
         return nb