diff --git a/issue-202-diagnostic.md b/issue-202-diagnostic.md new file mode 100644 index 0000000..f64db68 --- /dev/null +++ b/issue-202-diagnostic.md @@ -0,0 +1,224 @@ +# Issue #202 — Precondition failure causes endless execution + +## Summary + +Two independent defects in the precondition machinery of `mrpython/StudentRunner.py`. +Both make an exception escape from *inside* the `except AssertionError` handler of +`_exec_or_eval`, which kills the interpreter subprocess loop and leaves the GUI +waiting forever — the "endless execution" reported in the issue. + +The interpreter runs in a separate process (`mrpython/PyInterpreter.py`). Its +`run_loop` does: + +```python +def run_loop(): + command = comm.recv() + if command == 'eval': + expr = comm.recv() + ok, report = interp.run_evaluation(expr) # <-- raises + comm.send((ok, report)) # <-- never reached + ... + root.after(10, run_loop) # <-- never reached +``` + +Any exception escaping `run_evaluation` means no answer is ever sent back **and** +the loop is never rescheduled. The proxy in the main process keeps polling +(`RUN_POLL_DELAY`) against a permanently silent interpreter. Nothing times out, +nothing is reported: the session hangs. + +## Defect 1 — `inspect.getsource()` on a string (the reported hang) + +`_exec_or_eval` is used in two modes: + +| caller | `code` argument | +| --- | --- | +| `run()` — full file | a compiled **code object** | +| `evaluate()` — interactive prompt | the raw **expression string** | + +The precondition branch of the `AssertionError` handler did: + +```python +source_code = inspect.getsource(code) +``` + +which works for a code object and raises for a string: + +``` +TypeError: module, class, method, function, traceback, frame, or code object + was expected, got str +``` + +Since this happens inside an `except` block, the `TypeError` propagates out of +`_exec_or_eval` → `evaluate` → `run_evaluation` → `run_loop`, and the interpreter +is dead. + +This is exactly the asymmetry described in the issue: `assert func(-1) == -1` in +the file works (exec mode), typing `func(-1)` at the prompt hangs (eval mode). + +**Reproduction** + +```python +def func(a:int) -> int: + """ + Renvoie un nombre positif tel quel + Precondition: a>=0 + """ + return a + +assert func(1)==1 +``` + +Run the file, then evaluate `func(-1)` in the console. + +## Defect 2 — line-number rewriting corrupts nested calls + +`FunctionDefVisitor` injected the precondition assertions and then did: + +```python +line_diff = new_end_lineno - node.lineno +ast.increment_lineno(node, n=line_diff) +``` + +`new_end_lineno` is just the number of preconditions (1, most of the time), so +`line_diff` is `1 - node.lineno`. Every function **not** starting on line 1 has +its whole body shifted to a bogus line range. A function defined at line 8 gets +its body reported around line 1. + +That single line is responsible for a cascade of symptoms: + +* **Wrong / missing error line.** The reported call site came from + `traceb[-2].lineno`, which now points anywhere. +* **Silently swallowed errors.** The report was only filled in when + `lineno in preconditionsLineno`. With corrupted line numbers this test fails, + the `AssertionError` is caught, *nothing* is reported, and the program appears + to run fine. (This is why `01_precondition_distance_KO`, `_lettre_KO` and + `_longueur_KO` reported "an error was expected (found none)".) +* **Second hang.** See below. + +The `TODO` comment above `add_FunctionPreconditions` ("because of changes in +python 3.11+ dynamic compilation we cannot add precondition checking code in +this way") was chasing this symptom; the line numbers were being destroyed by +MrPython itself, not by CPython. + +## Defect 3 — argument values reconstructed by parsing source text + +The error message was built by string-scanning the caller's source line +(`parse_assertion_arg_values`), and the parameter names by walking **every** +`FunctionDef` of the file: + +```python +for node in ast.walk(tree): + if isinstance(node, ast.FunctionDef): + for argg in node.args.args: + arg_names.append(argg.arg) # names of ALL functions +... +arg_values = parse_assertion_arg_values(func_name, code_tb) # text of the call + +if len(arg_names) <= len(arg_values): + ... +else: + raise ValueError("Precondition handling fails (wrong parameter/value, please report)") +``` + +Consequences: + +* **The `a=a` message.** When `func_1` calls `func`, the caller line is + `return func(b)`, so the printed "value" is the literal source text `b`, + not the value `-1`. +* **The secondary hang.** As soon as a second function has preconditions, + `arg_names` holds the parameters of *all* functions while `arg_values` holds + those of one call, so the counts mismatch and the `raise ValueError` fires — + inside the `except` handler, killing the interpreter again. If the line + numbers are corrupted (defect 2) the function name isn't even found in the + caller line, `parse_assertion_arg_values` returns `None`, and the failure is + a `TypeError: object of type 'NoneType' has no len()`. + +This matches the issue precisely: removing the preconditions from the *caller* +makes the error report work again. + +## Fix + +Commit `0a1c60a`, `mrpython/StudentRunner.py`. + +1. **Carry the precondition in the assertion message.** + The injected assert now uses `PRECONDITION_TAG + ast.unparse(precondition)` + as its message. The reported text no longer depends on reading the file back + or on line numbers, and it works identically in exec and eval mode. + +2. **Read the argument values from the frame.** + The precondition checks are the first statements of the function body, so + when one fails the locals of the deepest traceback frame *are* the call + arguments: + + ```python + arg_names = code.co_varnames[:code.co_argcount + code.co_kwonlyargcount] + ... repr(frame.f_locals.get(arg_name)) + ``` + + Real values, no source parsing, correct for nested calls. `a = -1` instead of + `a = a`. + +3. **Drop the line-number rewriting.** + `ast.increment_lineno` and the `ast.FunctionDef(...)` reconstruction are + gone; the visitor now mutates `node.body` in place, which also preserves + fields the reconstruction dropped (`type_params`, `end_lineno`, + decorator positions). + +4. **Never report a meaningless line.** + The call site is reported only when the frame belongs to the edited file, so + an interactive `func(-1)` no longer points at an unrelated line of the file. + +5. **Remove the swallow path.** + `preconditionsLineno` and `parse_assertion_arg_values` are deleted. Nothing + can escape the handler, and a precondition failure is always reported. + +Also fixed in `runtimeTest/test_runtime.py`: test programs were read with +`open(f, "r")`, i.e. the platform default encoding. On Windows (cp1252) the +accented `Précondition` was mis-decoded and never recognised, so four tests were +failing for that reason alone. Now read with `tokenize.open`, like the +application itself does. + +## Result + +Interactive evaluation, previously an infinite hang: + +``` +>>> func(-1) +Erreur de précondition + Fonction : func (Ligne 4) + Précondition : a >= 0 + Fausse avec + a = -1 +``` + +Nested case (`petit_positif` calls `positif`, both with preconditions), +previously an infinite hang: + +``` +Erreur: ligne 13 +==> Erreur de précondition + Fonction : positif (Ligne 5) + Précondition : a >= 0 + Fausse avec + a = -1 +``` + +Test suites: + +| suite | before | after | +| --- | --- | --- | +| `runtimeTest/test_runtime.py` | 20 / 24 | **26 / 26** | +| `test/test_typer.py` | 113 / 118 | 113 / 118 (unchanged) | + +Two regression programs were added, `01_precondition_nested_OK.py` and +`01_precondition_nested_KO.py`, covering a preconditioned function called from +another preconditioned function. + +The 5 remaining `test_typer.py` failures are pre-existing and unrelated to +preconditions. + +## Left aside + +`mrpython/PreconditionHandler.py` still contains `PreconditionErrorMessageHandler`, +dead code carrying the same broken source-parsing approach (and a call to an +undefined `tr`). It is unused and can be deleted separately. diff --git a/mrpython/StudentRunner.py b/mrpython/StudentRunner.py index 12e96c3..102c137 100644 --- a/mrpython/StudentRunner.py +++ b/mrpython/StudentRunner.py @@ -1,5 +1,4 @@ from code import InteractiveInterpreter -import inspect from RunReport import RunReport import ast import tokenize @@ -160,39 +159,19 @@ def _exec_or_eval(self, mode, code, globs, locs): #import pdb ; pdb.set_trace() if len(traceb) > 1: _, lineno, _, line = traceb[-1] - if len(traceb) > 1 and err.args and err.args[0] == "<<>>": + precondition = extract_precondition(err) + if len(traceb) > 1 and precondition is not None: s = "Precondition error\n\t Function : {} (Line {})\n\t Precondition : {}\n\t False with {}" func_name = traceb[-1].name - assert_lineno = traceb[-2].lineno - code_tb = traceb[-2].line - arg_names = [] - arg_values = [] - - source_code = inspect.getsource(code) - #matches = re.findall(r'\((.*?)\)', code_tb) - - try: - tree = ast.parse(source_code) - except SyntaxError as err: - print("Fatal Syntax error (precondition handling, please report)", file=sys.stderr) - raise err - for node in ast.walk(tree): - if isinstance(node, ast.FunctionDef): - for argg in node.args.args: - arg_name = argg.arg - arg_names.append(arg_name) - - arg_values = parse_assertion_arg_values(func_name, code_tb) - - if len(arg_names) <= len(arg_values) : - arg = "\n\t" - for i in range(len(arg_names)): - arg += "\t" + str(arg_names[i]) + " = " + str(arg_values[i]) + "\n\t" - else : - raise ValueError("Precondition handling fails (wrong parameter/value, please report)") - - if lineno in preconditionsLineno: - self.report.add_execution_error('error', tr(s).format(func_name, lineno, line.split(':', 1)[-1].strip(), arg), assert_lineno) + # the arguments of the faulty call are read from the frame itself + # (the precondition checks are the first statements of the function) + arg = describe_call_arguments(tb) + # the line of the call is only relevant if it belongs to the edited + # file : in the interactive interpreter the call is made from a + # string that has nothing to do with the file being edited + call_site = traceb[-2] + assert_lineno = call_site.lineno if call_site.filename == self.filename else None + self.report.add_execution_error('error', tr(s).format(func_name, lineno, precondition, arg), assert_lineno) else: self.report.add_execution_error('error', tr("Assertion error (failed test?)") + (f"\n ==> {str(err)}" if str(err) else ""), lineno) return (True, None) @@ -338,52 +317,36 @@ def check_types(self): return not fatal_error def add_FunctionPreconditions(self): - # TODO : because of changes in python 3.11+ dynamic compilation - # we cannot add precondition checking code in this - # way (hiding line numbers) - # a new scheme will be introduced self.AST = FunctionDefVisitor().visit(self.AST) self.AST = ast.fix_missing_locations(self.AST) -def parse_assertion_arg_values(func_name, code_str): - """Parsing argumentexpression in assertion call""" - - fn_index = code_str.find(func_name) - if fn_index == -1: +def extract_precondition(err): + """Return the source of the violated precondition, or None if the + assertion error does not come from a precondition check.""" + if not err.args or not isinstance(err.args[0], str): return None - - i = fn_index - while i < len(code_str) and code_str[i] != '(': - i += 1 - if i >= len(code_str): + if not err.args[0].startswith(PRECONDITION_TAG): return None + return err.args[0][len(PRECONDITION_TAG):] - arg_values = [] - i += 1 - level = 0 - arg = "" - while i < len(code_str) and not (level == 0 and code_str[i] == ')'): - - if code_str[i] == '(': - level += 1 - arg += code_str[i] - elif code_str[i] == ')': - level -= 1 - arg += code_str[i] - elif code_str[i] == ',' and level == 0: - arg_values.append(arg.strip()) - arg = "" - elif code_str[i] == ' ': - pass - else: - arg += code_str[i] - i += 1 +def describe_call_arguments(tb): + """Describe the arguments of the call that failed its precondition. - arg_values.append(arg) + The precondition checks are injected at the very beginning of the + function body, hence the locals of the deepest frame of the traceback + are exactly the arguments of the faulty call.""" + while tb.tb_next is not None: + tb = tb.tb_next + frame = tb.tb_frame + code = frame.f_code + arg_names = code.co_varnames[:code.co_argcount + code.co_kwonlyargcount] - return arg_values + descr = "\n\t" + for arg_name in arg_names: + descr += "\t" + arg_name + " = " + repr(frame.f_locals.get(arg_name)) + "\n\t" + return descr class FunCallsVisitor(ast.NodeVisitor): def __init__(self): @@ -400,7 +363,16 @@ def visit_Call(self, node): from typechecking.typechecker import preconditions -preconditionsLineno = [] +# marker prepended to the message of the injected assertions, so that a +# precondition failure can be told apart from a plain (test) assertion +PRECONDITION_TAG = "<<>>" + +def precondition_source(precondition_node): + """The source code of a precondition, as written by the student.""" + if hasattr(ast, "unparse"): # python 3.9+ + return ast.unparse(precondition_node) + else: + return ast.dump(precondition_node) class FunctionDefVisitor(ast.NodeTransformer): def visit_FunctionDef(self, node): @@ -408,29 +380,23 @@ def visit_FunctionDef(self, node): return node else: ast_asserts = [] - new_end_lineno = 0 for precondition_node in preconditions[node.name]: lineno = precondition_node.lineno # Is the right assertion lineno PreconditionAstLinenoUpdater(lineno).visit(precondition_node) - preconditionsLineno.append(lineno) # print(ast.dump(precondition_node, annotate_fields=True, include_attributes=True, indent=4)) assert_node = ast.Assert(test=precondition_node) - assert_node.msg = ast.Constant("<<>>") - assert_node.lineno = lineno + new_end_lineno - assert_node.end_lineno = assert_node.lineno + # the precondition is carried by the assertion message so that it + # can be reported without relying on (unreliable) line numbers + assert_node.msg = ast.Constant(PRECONDITION_TAG + precondition_source(precondition_node)) + assert_node.lineno = lineno + assert_node.end_lineno = lineno ast_asserts.append(assert_node) - new_end_lineno += 1 - - # Line number synchronization to avoid an overlapping scenario - line_diff = new_end_lineno - node.lineno - ast.increment_lineno(node, n=line_diff) - if hasattr(node, "type_comment"): - node_res = ast.FunctionDef(node.name,node.args,ast_asserts+node.body,node.decorator_list,node.returns,node.type_comment,lineno = node.lineno,col_offset = node.col_offset, end_lineno = node.lineno, end_col_offset = node.end_col_offset) - else: # python 3.7 - node_res = ast.FunctionDef(node.name,node.args,ast_asserts+node.body,node.decorator_list,node.returns,lineno = node.lineno,col_offset = node.col_offset, end_lineno = node.lineno) - - return node_res - + + # the checks are prepended to the body so that, when one of them + # fails, the locals of the function are exactly its arguments + node.body = ast_asserts + node.body + return node + if __name__ == "__main__": # for testing purpose only runner = StudentRunner(None, "toto.py",""" diff --git a/runtimeTest/progs/01_precondition_nested_KO.py b/runtimeTest/progs/01_precondition_nested_KO.py new file mode 100644 index 0000000..1578d4e --- /dev/null +++ b/runtimeTest/progs/01_precondition_nested_KO.py @@ -0,0 +1,18 @@ +##!FAIL: Erreur: ligne 13 + +def positif(a : int) -> int: + """Retourne a, qui doit être positif. + Précondition : a >= 0 + """ + return a + +def petit_positif(b : int) -> int: + """Retourne b, qui doit être positif et petit. + Précondition : b <= 10 + """ + return positif(b) + +# Jeu de tests +assert positif(1) == 1 +assert petit_positif(1) == 1 +assert petit_positif(-1) == -1 diff --git a/runtimeTest/progs/01_precondition_nested_OK.py b/runtimeTest/progs/01_precondition_nested_OK.py new file mode 100644 index 0000000..5bbf2bf --- /dev/null +++ b/runtimeTest/progs/01_precondition_nested_OK.py @@ -0,0 +1,16 @@ +def positif(a : int) -> int: + """Retourne a, qui doit être positif. + Précondition : a >= 0 + """ + return a + +def petit_positif(b : int) -> int: + """Retourne b, qui doit être positif et petit. + Précondition : b <= 10 + """ + return positif(b) + +# Jeu de tests +assert positif(1) == 1 +assert petit_positif(1) == 1 +assert petit_positif(10) == 10 diff --git a/runtimeTest/test_runtime.py b/runtimeTest/test_runtime.py index 98c5394..f5d14e8 100644 --- a/runtimeTest/test_runtime.py +++ b/runtimeTest/test_runtime.py @@ -1,5 +1,6 @@ import sys import glob +import tokenize import os.path sys.path.append("../mrpython") @@ -25,7 +26,7 @@ def testWithoutPreconditionError(prog_filename, prog_name, prog): print(" | " + error.fail_string()) nb_tests_fail+=1 else: - runner = studentRunner.StudentRunner(None, prog_filename,open(prog_filename,"r").read(), check_tk=False) + runner = studentRunner.StudentRunner(None, prog_filename,tokenize.open(prog_filename).read(), check_tk=False) runner.execute(dict(), capture_stdout=False) if runner.report.has_execution_error(): print(" ==> FAIL: precondition error has been raised") @@ -36,7 +37,7 @@ def testWithoutPreconditionError(prog_filename, prog_name, prog): def testWithPreconditionError(prog_filename, prog_name, prog): global nb_tests_abort, nb_tests_fail, nb_tests_pass - with open(prog_filename, 'r') as f: + with tokenize.open(prog_filename) as f: header = f.readline() if not header.startswith("##!FAIL:"): @@ -50,7 +51,7 @@ def testWithPreconditionError(prog_filename, prog_name, prog): for error in ctx.type_errors: print(" | " + error.fail_string()) nb_tests_fail+=1 - runner = studentRunner.StudentRunner(None, prog_filename,open(prog_filename,"r").read(), check_tk=False) + runner = studentRunner.StudentRunner(None, prog_filename,tokenize.open(prog_filename).read(), check_tk=False) runner.execute(dict(), capture_stdout=False) if not runner.report.has_execution_error(): print(" ==> FAIL: an error was expected (found none)")