From 8a5e649691c9653407e2d91f74df7b0f9228daf6 Mon Sep 17 00:00:00 2001 From: Rudi Grinberg Date: Mon, 25 Aug 2025 20:36:51 +0100 Subject: [PATCH] feature(cram): include failed command in cram timeouts Signed-off-by: Rudi Grinberg Signed-off-by: Rudi Grinberg --- doc/changes/12307.md | 2 + src/dune_rules/cram/cram_exec.ml | 37 ++++++++++++++++--- .../test-cases/cram/timeout-no-command.t | 36 ++++++++++++++++++ test/blackbox-tests/test-cases/cram/timeout.t | 5 ++- 4 files changed, 73 insertions(+), 7 deletions(-) create mode 100644 doc/changes/12307.md create mode 100644 test/blackbox-tests/test-cases/cram/timeout-no-command.t diff --git a/doc/changes/12307.md b/doc/changes/12307.md new file mode 100644 index 00000000000..230bafc0a6f --- /dev/null +++ b/doc/changes/12307.md @@ -0,0 +1,2 @@ +- Feature: Include shell command that was executed when a cram test has + occurred in the error message (#12307, @rgrinberg) diff --git a/src/dune_rules/cram/cram_exec.ml b/src/dune_rules/cram/cram_exec.ml index 6e07a0de077..9755946c813 100644 --- a/src/dune_rules/cram/cram_exec.ml +++ b/src/dune_rules/cram/cram_exec.ml @@ -409,14 +409,39 @@ let run_cram_test env ~src ~script ~cram_stanzas ~temp_dir ~cwd ~timeout = | Ok () -> read_and_attach_exit_codes sh_script |> sanitize ~parent_script:script | Error `Timed_out -> let timeout_loc, timeout = Option.value_exn timeout in + let timeout_set_message = + [ Pp.textf "A time limit of %.2fs has been set in " timeout + ; Pp.tag User_message.Style.Loc @@ Loc.pp_file_colon_line timeout_loc + ] + in + let timeout_msg = + match + let completed_count = + read_exit_codes_and_prefix_maps sh_script.metadata_file |> List.length + in + let command_blocks_only = + List.filter_map sh_script.cram_to_output ~f:(function + | Cram_lexer.Comment _ -> None + | Cram_lexer.Command block_result -> Some block_result) + in + let total_commands = List.length command_blocks_only in + if completed_count < total_commands + then ( + (* Find the command that got stuck - it's the one at index completed_count *) + match List.nth command_blocks_only completed_count with + | Some { command; _ } -> Some (String.concat ~sep:" " command) + | None -> None) + else None + with + | None -> [ Pp.text "Cram test timed out" ] + | Some cmd -> + [ Pp.textf "Cram test timed out while running command:" + ; Pp.verbatimf " $ %s" cmd + ] + in User_error.raise ~loc:(Loc.in_file (Path.drop_optional_build_context_maybe_sandboxed src)) - [ Pp.concat - [ Pp.textf "Cram test timed out. A time limit of %.2fs has been set in " timeout - ; Pp.tag User_message.Style.Loc @@ Loc.pp_file_colon_line timeout_loc - ; Pp.verbatim "." - ] - ] + (timeout_msg @ timeout_set_message) ;; let run_produce_correction ~src ~env ~script ~timeout lexbuf = diff --git a/test/blackbox-tests/test-cases/cram/timeout-no-command.t b/test/blackbox-tests/test-cases/cram/timeout-no-command.t new file mode 100644 index 00000000000..6e19f500762 --- /dev/null +++ b/test/blackbox-tests/test-cases/cram/timeout-no-command.t @@ -0,0 +1,36 @@ +Testing that timeout errors don't include the command that caused the timeout. + +This test demonstrates the current behavior where timeout error messages +don't include information about which specific command caused the timeout. + + $ cat > dune-project < (lang dune 3.20) + > EOF + + $ cat > dune < (cram + > (timeout 0.1)) + > EOF + +Create a cram test with multiple commands, where the second one will timeout: + + $ cat > test.t < $ echo "This command runs fine" + > $ echo "This is the problematic command" && sleep 2 + > EOF + +Run the test and verify that the timeout error doesn't mention +which specific command caused the timeout: + + $ dune test test.t + File "test.t", line 1, characters 0-0: + Error: Cram test timed out while running command: + $ echo "This is the problematic command" && sleep 2 + A time limit of 0.10s has been set in + dune:2 + [1] + +The error message above shows that we get a generic timeout message but no +indication that it was the "echo && sleep 2" command that caused the timeout. +This makes debugging timeout issues difficult when there are multiple commands +in a test. diff --git a/test/blackbox-tests/test-cases/cram/timeout.t b/test/blackbox-tests/test-cases/cram/timeout.t index 313ee97abd1..cb081b921c7 100644 --- a/test/blackbox-tests/test-cases/cram/timeout.t +++ b/test/blackbox-tests/test-cases/cram/timeout.t @@ -41,6 +41,9 @@ behaviour is for dune to kill the cram test immediately. $ timeout 1 dune test test.t File "test.t", line 1, characters 0-0: - Error: Cram test timed out. A time limit of 0.00s has been set in dune:2. + Error: Cram test timed out while running command: + $ echo hi + A time limit of 0.00s has been set in + dune:2 [1]