From 81d9cbd02a32ba7a4b4fd637cd3d14aeea7fcbc9 Mon Sep 17 00:00:00 2001 From: Alejandro R Mosteo Date: Fri, 14 Feb 2025 13:42:22 +0100 Subject: [PATCH] fix: action error masked by following successful action (#1841) * fix action error being masked by following action * Self-review * Fix uninitialized out parameter --- src/alire/alire-os_lib-subprocess.adb | 10 +++ src/alire/alire-os_lib-subprocess.ads | 6 ++ .../alire-properties-actions-executor.adb | 65 +++++++++++++++++-- src/alire/alire-properties-actions.ads | 2 +- src/alire/alire-roots.adb | 3 +- src/alr/alr-commands-action.adb | 4 ++ src/alr/alr-commands-test.adb | 21 +++--- testsuite/tests/action/masked-error/test.py | 35 ++++++++++ testsuite/tests/action/masked-error/test.yaml | 4 ++ 9 files changed, 133 insertions(+), 17 deletions(-) create mode 100644 testsuite/tests/action/masked-error/test.py create mode 100644 testsuite/tests/action/masked-error/test.yaml diff --git a/src/alire/alire-os_lib-subprocess.adb b/src/alire/alire-os_lib-subprocess.adb index 5b855340..c0881512 100644 --- a/src/alire/alire-os_lib-subprocess.adb +++ b/src/alire/alire-os_lib-subprocess.adb @@ -164,6 +164,16 @@ package body Alire.OS_Lib.Subprocess is Understands_Verbose => Understands_Verbose, Err_To_Out => Err_To_Out)); + --------------------- + -- Unchecked_Spawn -- + --------------------- + + function Unchecked_Spawn + (Command : String; + Arguments : AAA.Strings.Vector; + Understands_Verbose : Boolean := False) return Integer + is (Spawn (Command, Arguments, Understands_Verbose)); + ----------- -- Spawn -- ----------- diff --git a/src/alire/alire-os_lib-subprocess.ads b/src/alire/alire-os_lib-subprocess.ads index 16e30b47..f33de12b 100644 --- a/src/alire/alire-os_lib-subprocess.ads +++ b/src/alire/alire-os_lib-subprocess.ads @@ -35,4 +35,10 @@ package Alire.OS_Lib.Subprocess is Err_To_Out : Boolean := False) return Integer; -- Returns the output and exit code of the spawned command + function Unchecked_Spawn + (Command : String; + Arguments : AAA.Strings.Vector; + Understands_Verbose : Boolean := False) return Integer; + -- Doesn't capture output but doesn't fail on error either + end Alire.OS_Lib.Subprocess; diff --git a/src/alire/alire-properties-actions-executor.adb b/src/alire/alire-properties-actions-executor.adb index 61dbc86d..01fa7372 100644 --- a/src/alire/alire-properties-actions-executor.adb +++ b/src/alire/alire-properties-actions-executor.adb @@ -42,7 +42,7 @@ package body Alire.Properties.Actions.Executor is Flags.Post_Fetch (CWD).Mark_Done; end if; exception - when Checked_Error => + when Action_Failed | Checked_Error => raise; when E : others => Log_Exception (E); @@ -78,6 +78,8 @@ package body Alire.Properties.Actions.Executor is Exec : String renames Cmd.First_Element; begin + Code := 0; + if Alire.OS_Lib.Locate_Exec_On_Path (Exec) = "" and then not GNAT.OS_Lib.Is_Executable_File (Exec) then @@ -96,7 +98,7 @@ package body Alire.Properties.Actions.Executor is Understands_Verbose => False, Err_To_Out => Err_To_Out); else - Subprocess.Checked_Spawn + Code := Subprocess.Unchecked_Spawn (Command => Cmd.First_Element, Arguments => Cmd.Tail, Understands_Verbose => False); @@ -111,8 +113,9 @@ package body Alire.Properties.Actions.Executor is Env : Properties.Vector; Moment : Moments) is - Unused_Code : Integer; + Code : Integer := 0; Unused_Output : AAA.Strings.Vector; + -- Those are checked in the call to Execute_Actions below begin Execute_Actions (Release => Release, @@ -120,10 +123,16 @@ package body Alire.Properties.Actions.Executor is Moment => Moment, Capture => False, Err_To_Out => False, - Code => Unused_Code, + Code => Code, Output => Unused_Output); + + if Code /= 0 then + raise Action_Failed with + "Action failed with exit code " & AAA.Strings.Trim (Code'Image); + -- Details already printed by Execute_Actions + end if; exception - when Checked_Error => + when Action_Failed | Checked_Error => raise; when E : others => Log_Exception (E); @@ -148,18 +157,33 @@ package body Alire.Properties.Actions.Executor is Output : out AAA.Strings.Vector; Prefix : AAA.Strings.Vector := AAA.Strings.Empty_Vector) is + use AAA.Strings; Now : Releases.Moment_Array := (others => False); + Count, Current : Natural; begin Now (Moment) := True; -- Cannot be done in the initialization - if not Release.On_Platform_Actions (Env, Now).Is_Empty then + Output.Clear; + + if Release.On_Platform_Actions (Env, Now).Is_Empty then + Code := 0; + return; + else Put_Info ("Running " & Utils.TTY.Name (TOML_Adapters.Tomify (Moment'Image)) & " actions for " & Release.Milestone.TTY_Image & "..."); end if; + Count := Natural (Release.On_Platform_Actions (Env, Now).Length); + Current := 0; + for Act of Release.On_Platform_Actions (Env, Now) loop - Trace.Detail ("Running action: " & Act.Image + Current := Current + 1; + Code := 0; + + Trace.Detail ("Running action " + & Trim (Current'Image) & "/" & Trim (Count'Image) + & ": " & Act.Image & " (cwd:" & Directories.Current & ")"); Execute_Run (This => Runners.Run (Act), Capture => Capture, @@ -167,6 +191,33 @@ package body Alire.Properties.Actions.Executor is Code => Code, Output => Output, Prefix => Prefix); + + if Code /= 0 then + if Capture then + + -- This is at debug level because sometimes we want silent + -- failure (e.g. during `alr test`), so the final reporting + -- must be done upstream (by using code/output). + + Trace.Debug ("Execution failed for action: " & Act.Image); + Trace.Debug ("Exit code: " & AAA.Strings.Trim (Code'Image)); + if Output.Is_Empty then + Trace.Debug + ("Actions produced no output up to error occurrence"); + else + Trace.Debug ("Action output begin:"); + Trace.Debug (Output.Flatten (New_Line)); + Trace.Debug ("Action output end."); + end if; + + else -- Don't capture + Trace.Warning ("Execution failed for action: " & Act.Image); + Trace.Warning ("Exit code: " & AAA.Strings.Trim (Code'Image)); + Trace.Warning ("Action output not captured, check it above."); + end if; + + return; -- With exit code /= 0 + end if; end loop; end Execute_Actions; diff --git a/src/alire/alire-properties-actions.ads b/src/alire/alire-properties-actions.ads index d802ca96..84caef52 100644 --- a/src/alire/alire-properties-actions.ads +++ b/src/alire/alire-properties-actions.ads @@ -5,7 +5,7 @@ with Alire.TOML_Keys; package Alire.Properties.Actions with Preelaborate is Action_Failed : exception; - -- Raised by the action runner when an action fails + -- Raised by the action runner when action execution fails (exit code /= 0) type Moments is ( diff --git a/src/alire/alire-roots.adb b/src/alire/alire-roots.adb index 722fb833..9995735c 100644 --- a/src/alire/alire-roots.adb +++ b/src/alire/alire-roots.adb @@ -287,7 +287,8 @@ package body Alire.Roots is return True; exception - when Properties.Actions.Action_Failed | Build_Failed => + when E : Properties.Actions.Action_Failed | Build_Failed => + Log_Exception (E); return False; end Build; diff --git a/src/alr/alr-commands-action.adb b/src/alr/alr-commands-action.adb index fb62cef0..30fb9290 100644 --- a/src/alr/alr-commands-action.adb +++ b/src/alr/alr-commands-action.adb @@ -135,6 +135,10 @@ package body Alr.Commands.Action is (Rel, Env => Cmd.Root.Environment, Moment => Moment); + exception + when Alire.Properties.Actions.Action_Failed => + Reportaise_Command_Failed + ("An action exited with error"); end; end if; end Run_Release; diff --git a/src/alr/alr-commands-test.adb b/src/alr/alr-commands-test.adb index 6ddf2fb1..c8a9598d 100644 --- a/src/alr/alr-commands-test.adb +++ b/src/alr/alr-commands-test.adb @@ -37,6 +37,8 @@ package body Alr.Commands.Test is package Platform renames Alire.Platforms.Current; package Query renames Alire.Solver; + Prefix : constant String := "[alr test] "; + ----------------- -- Check_Files -- ----------------- @@ -190,7 +192,7 @@ package body Alr.Commands.Test is -- release mode. Output.Append_Line - ("[alr test] Spawning default local test: " + (Prefix & "Spawning default local test: " & Command.Flatten); Code := Unchecked_Spawn_And_Capture @@ -216,7 +218,7 @@ package body Alr.Commands.Test is -- Start with a standard crate retrieval Output.Append_Line - ("[alr test] Spawning retrieval for remote crate: " + (Prefix & "Spawning retrieval for remote crate: " & Command.Flatten); Code := Unchecked_Spawn_And_Capture @@ -251,7 +253,7 @@ package body Alr.Commands.Test is & "-gnatwn"; begin Output.Append_Line - ("[alr test] Spawning default test for remote crate: " + (Prefix & "Spawning default test for remote crate: " & Command.Flatten); Code := Unchecked_Spawn_And_Capture @@ -288,7 +290,7 @@ package body Alr.Commands.Test is ----------------- procedure Custom_Test is - Exit_Code : Integer; + Exit_Code : Integer := 0; Alr_Custom_Cmd : constant Vector := "alr" & Regular_Alr_Switches @@ -324,7 +326,7 @@ package body Alr.Commands.Test is with Unreferenced; begin Alire.Properties.Actions.Executor.Execute_Actions - (Release => R, + (Release => R, Env => Platform.Properties, Moment => Alire.Properties.Actions.Test, Capture => True, @@ -333,6 +335,9 @@ package body Alr.Commands.Test is Output => Output); if Exit_Code /= 0 then + Output.Append_Line + (Prefix & "Test action exited with error code " + & AAA.Strings.Trim (Exit_Code'Image)); raise Child_Failed; end if; end; @@ -378,13 +383,13 @@ package body Alr.Commands.Test is Trace.Detail ("Skipping already tested " & R.Milestone.Image); else begin - Output.Append ("[alr test] Testing " & R.Milestone.Image); + Output.Append (Prefix & "Testing " & R.Milestone.Image); -- Perform default or custom actions Test_Action; -- At this point the test ended successfully - Output.Append ("[alr test] Test completed SUCCESSFULLY"); + Output.Append (Prefix & "Test completed SUCCESSFULLY"); Reporters.End_Test (R, Testing.Pass, Clock - Start, Output); Trace.Detail (Output.Flatten (Newline)); @@ -400,7 +405,7 @@ package body Alr.Commands.Test is Output.Append (Ada.Exceptions.Exception_Information (E)); Output.Append ("****** TRACE END"); - when Child_Failed => + when Child_Failed | Alire.Properties.Actions.Action_Failed => Reporters.End_Test (R, Testing.Fail, Clock - Start, Output); Trace.Detail (Output.Flatten (Newline)); Some_Failed := True; diff --git a/testsuite/tests/action/masked-error/test.py b/testsuite/tests/action/masked-error/test.py new file mode 100644 index 00000000..c1e13264 --- /dev/null +++ b/testsuite/tests/action/masked-error/test.py @@ -0,0 +1,35 @@ +""" +https://github.com/alire-project/alire/issues/1806 +Ensure that an error in an action is not masked by success in a following one. +""" + +import os +import uuid +from drivers.alr import init_local_crate, run_alr, add_action +from drivers.asserts import assert_substring + + +def check_errors(): + assert_substring("failed", + run_alr("test", complain_on_error=False).out) + assert_substring("action exited with error", + run_alr("action", "test", complain_on_error=False).out) + + +init_local_crate() + +# Verify a successful action +add_action("test", ["echo", "OK"]) +run_alr("test") + +# Verify a failing action both via `alr test` and `alr action` +uuid = uuid.uuid4().hex +assert not os.path.exists(uuid) +add_action("test", ["ls", uuid]) +check_errors() + +# Verify that a subsequent successful action does not mask the error +add_action("test", ["echo", "OK"]) +check_errors() + +print("SUCCESS") diff --git a/testsuite/tests/action/masked-error/test.yaml b/testsuite/tests/action/masked-error/test.yaml new file mode 100644 index 00000000..70201052 --- /dev/null +++ b/testsuite/tests/action/masked-error/test.yaml @@ -0,0 +1,4 @@ +driver: python-script +build_mode: both +indexes: + compiler_only_index: {} -- 2.39.5