CFE-4726: Fixed a commands: promise being reported as compliant after exec_timeout fired

cf-agent/verify_exec.c

@@ -288,6 +288,9 @@ static ActionResult RepairExec(EvalContext *ctx, const Attributes *a,
 
     CommandPrefix(cmdline, comm);
 
+    /* Set once the command has been reaped, if its exec_timeout fired. */
+    bool timed_out = false;
+
     bool do_work_here = true;
 
 #ifndef __MINGW32__
@@ -448,7 +451,31 @@ static ActionResult RepairExec(EvalContext *ctx, const Attributes *a,
         {
             int ret = cf_pclose(pfp);
 
-            if (ret == -1)
+            /* Sample only now, and never earlier. The read loop above ends as
+             * soon as the command closes its output, which it can do long
+             * before it exits -- so the alarm may not fire until cf_pclose()
+             * is already waiting for the child. Reading the flag before that
+             * wait misses exactly the case this is here to catch. It is still
+             * read before the alarm is disarmed further down. */
+            timed_out = (a->contain.timeout != CF_NOINT) && TimeOutHasFired();
+
+            if (timed_out)
+            {
+                /* The command exceeded exec_timeout and was signalled, so its
+                 * exit status cannot be trusted to say so. A command killed
+                 * after it has written its last output, or one that exits
+                 * normally while only its children are killed, is reaped with a
+                 * status VerifyCommandRetcode() reads as success -- and the
+                 * promise is then reported kept or repaired even though the
+                 * command never completed. Classify on the timeout instead. */
+                cfPS(ctx, LOG_LEVEL_ERR, PROMISE_RESULT_TIMEOUT, pp, a,
+                     TimeOutSignalledProcess()
+                         ? "Command '%s' exceeded exec_timeout of %d seconds and was terminated"
+                         : "Command '%s' exceeded exec_timeout of %d seconds; it was NOT terminated and ran to completion",
+                     pp->promiser, a->contain.timeout);
+                *result = PromiseResultUpdate(*result, PROMISE_RESULT_TIMEOUT);
+            }
+            else if (ret == -1)
             {
                 cfPS(ctx, LOG_LEVEL_ERR, PROMISE_RESULT_FAIL, pp, a, "Finished script '%s' - failed (abnormal termination)", pp->promiser);
                 *result = PromiseResultUpdate(*result, PROMISE_RESULT_FAIL);
@@ -492,7 +519,7 @@ static ActionResult RepairExec(EvalContext *ctx, const Attributes *a,
     }
 #endif /* !__MINGW32__ */
 
-    return ACTION_RESULT_OK;
+    return timed_out ? ACTION_RESULT_TIMEOUT : ACTION_RESULT_OK;
 }
 
 /*************************************************************/

libpromises/timeout.c

@@ -26,21 +26,46 @@
 #include <timeout.h>
 #include <process_lib.h>
 
+/* Set by TimeOut() when the alarm fires, so that the caller can tell "the
+ * command timed out" from "the command finished". Written from a signal
+ * handler, hence volatile sig_atomic_t. */
+static volatile sig_atomic_t TIMEOUT_FIRED = 0; /* GLOBAL_X */
+
+/* Set only when TimeOut() actually had a process to signal. The alarm can fire
+ * with ALARM_PID already cleared -- cf_pclose() clears it before waiting -- in
+ * which case the command timed out but was never terminated, and saying
+ * otherwise would be a false statement in an error message. */
+static volatile sig_atomic_t TIMEOUT_SIGNALLED = 0; /* GLOBAL_X */
+
 void SetTimeOut(int timeout)
 {
     ALARM_PID = -1;
+    TIMEOUT_FIRED = 0;
+    TIMEOUT_SIGNALLED = 0;
     signal(SIGALRM, (void *) TimeOut);
     alarm(timeout);
 }
 
+bool TimeOutHasFired(void)
+{
+    return TIMEOUT_FIRED != 0;
+}
+
+bool TimeOutSignalledProcess(void)
+{
+    return TIMEOUT_SIGNALLED != 0;
+}
+
 /*************************************************************************/
 
 void TimeOut()
 {
     alarm(0);
+    TIMEOUT_FIRED = 1;
 
     if (ALARM_PID != -1)
     {
+        TIMEOUT_SIGNALLED = 1;
         Log(LOG_LEVEL_VERBOSE, "Time out of process %jd", (intmax_t)ALARM_PID);
         GracefulTerminate(ALARM_PID, PROCESS_START_TIME_UNKNOWN);
     }

libpromises/timeout.h

@@ -26,6 +26,16 @@
 #define CFENGINE_TIMEOUT_H
 
 void SetTimeOut(int timeout);
+
+/* True if the alarm armed by the last SetTimeOut() actually fired. Lets a
+ * caller report that a command was timed out even when the command's own exit
+ * status would otherwise read as success. Cleared by SetTimeOut(). */
+bool TimeOutHasFired(void);
+
+/* True if that alarm also had a process to signal. False means the command
+ * exceeded its timeout but was never terminated, which callers must not
+ * describe as a termination. */
+bool TimeOutSignalledProcess(void);
 void TimeOut(void);
 time_t SetReferenceTime(void);
 

tests/acceptance/08_commands/04_exec_timeout/timeout_after_output_closed.cf

@@ -0,0 +1,61 @@
+#######################################################
+#
+# Test that exec_timeout is detected even when the command
+# closes its output long before it exits. The agent's read
+# loop ends at EOF, so it is already waiting for the child
+# when the alarm fires; a timeout sampled while output was
+# still open misses exactly this shape. The command then runs
+# to completion and exits 0, and must still be reported as
+# timed out.
+#
+# Deliberately slow: with its output already closed there is
+# no process left registered for the alarm to signal, so the
+# child's full 10 second sleep runs out before it is reaped.
+# Expect around 12 seconds of wall clock.
+#
+#######################################################
+body common control
+{
+  inputs => { "../../default.sub.cf" };
+  bundlesequence => { default("$(this.promise_filename)") };
+  version => "1.0";
+}
+
+#######################################################
+bundle agent test
+{
+  meta:
+    "description"
+      string => "exec_timeout is detected when the command closes its output before it exits";
+
+    "test_skip_unsupported"
+      string => "windows",
+      comment => "Drives /bin/sh with a POSIX shell payload";
+
+  commands:
+    "/bin/sh"
+      arglist => { "-c", "exec 1>&- 2>&-; sleep 10; exit 0" },
+      contain => exec_timeout_2,
+      classes => dcs_all_classes("output_closed");
+}
+
+body contain exec_timeout_2
+{
+  exec_timeout => "2";
+}
+
+#######################################################
+bundle agent check
+{
+  methods:
+    "any"
+      usebundle => dcs_passif_expected(
+        "output_closed_repair_timeout",
+        "output_closed_promise_kept,output_closed_promise_repaired",
+        $(this.promise_filename)
+      ),
+      inherit => "true";
+}
+
+### PROJECT_ID: core
+### CATEGORY_ID: 26

tests/acceptance/08_commands/04_exec_timeout/timeout_does_not_leak_to_next_promise.cf

@@ -0,0 +1,66 @@
+#######################################################
+#
+# Test that a fired exec_timeout is charged to the promise
+# whose command timed out, and only that promise: a
+# subsequent commands: promise that finishes inside its own
+# timeout must come out repaired, not timed out.
+#
+#######################################################
+body common control
+{
+  inputs => { "../../default.sub.cf" };
+  bundlesequence => { default("$(this.promise_filename)") };
+  version => "1.0";
+}
+
+#######################################################
+bundle agent test
+{
+  meta:
+    "description"
+      string => "A fired exec_timeout does not leak into the next commands promise";
+
+    "test_skip_unsupported"
+      string => "windows",
+      comment => "Drives /bin/sh with POSIX shell payloads";
+
+  commands:
+    "/bin/sh"
+      arglist => { "-c", "sleep 2.4; exit 0" },
+      contain => exec_timeout_2,
+      classes => dcs_all_classes("leak_first");
+
+    # Runs after the first command has already timed out, armed with
+    # its own timeout so that a stale flag surviving from the first
+    # promise would be sampled here if it leaked.
+    "/bin/sh"
+      arglist => { "-c", "exit 0" },
+      contain => exec_timeout_10,
+      classes => dcs_all_classes("leak_second");
+}
+
+body contain exec_timeout_2
+{
+  exec_timeout => "2";
+}
+
+body contain exec_timeout_10
+{
+  exec_timeout => "10";
+}
+
+#######################################################
+bundle agent check
+{
+  methods:
+    "any"
+      usebundle => dcs_passif_expected(
+        "leak_first_repair_timeout,leak_second_promise_repaired",
+        "leak_first_promise_kept,leak_first_promise_repaired,leak_second_repair_timeout",
+        $(this.promise_filename)
+      ),
+      inherit => "true";
+}
+
+### PROJECT_ID: core
+### CATEGORY_ID: 26

tests/acceptance/08_commands/04_exec_timeout/timeout_overrides_exit_zero.cf

@@ -0,0 +1,58 @@
+#######################################################
+#
+# Test that a commands: promise whose exec_timeout fires is
+# reported as timed out even though the command exits 0. The
+# exit status of a command that was signalled does not say
+# whether it ran to completion, so a fired timeout must take
+# precedence over a successful exit status.
+#
+#######################################################
+body common control
+{
+  inputs => { "../../default.sub.cf" };
+  bundlesequence => { default("$(this.promise_filename)") };
+  version => "1.0";
+}
+
+#######################################################
+bundle agent test
+{
+  meta:
+    "description"
+      string => "A fired exec_timeout takes precedence over a successful exit status";
+
+    "test_skip_unsupported"
+      string => "windows",
+      comment => "Drives /bin/sh with a POSIX shell payload";
+
+  commands:
+    # The sleep outlives the 2 second timeout by less than the
+    # termination ladder's grace period, so the signalled shell
+    # still reaps its child and exits 0 -- the shape in which the
+    # exit status used to win over the fired timeout.
+    "/bin/sh"
+      arglist => { "-c", "sleep 2.4; exit 0" },
+      contain => exec_timeout_2,
+      classes => dcs_all_classes("timeout_exit0");
+}
+
+body contain exec_timeout_2
+{
+  exec_timeout => "2";
+}
+
+#######################################################
+bundle agent check
+{
+  methods:
+    "any"
+      usebundle => dcs_passif_expected(
+        "timeout_exit0_repair_timeout",
+        "timeout_exit0_promise_kept,timeout_exit0_promise_repaired",
+        $(this.promise_filename)
+      ),
+      inherit => "true";
+}
+
+### PROJECT_ID: core
+### CATEGORY_ID: 26

tests/acceptance/08_commands/04_exec_timeout/timeout_overrides_kept_returncodes.cf

@@ -0,0 +1,66 @@
+#######################################################
+#
+# Test that kept_returncodes does not resurrect "kept" when
+# exec_timeout fired: the timed-out command exits 0, and 0 is
+# listed in kept_returncodes, but the promise must still be
+# reported as timed out, not kept.
+#
+#######################################################
+body common control
+{
+  inputs => { "../../default.sub.cf" };
+  bundlesequence => { default("$(this.promise_filename)") };
+  version => "1.0";
+}
+
+#######################################################
+bundle agent test
+{
+  meta:
+    "description"
+      string => "kept_returncodes does not resurrect kept when exec_timeout fired";
+
+    "test_skip_unsupported"
+      string => "windows",
+      comment => "Drives /bin/sh with a POSIX shell payload";
+
+  commands:
+    "/bin/sh"
+      arglist => { "-c", "sleep 2.4; exit 0" },
+      contain => exec_timeout_2,
+      classes => all_classes_kept_0("timeout_kept0");
+}
+
+body contain exec_timeout_2
+{
+  exec_timeout => "2";
+}
+
+# dcs_all_classes (dcs.sub.cf) carries no returncode attributes and
+# classes bodies do not compose, so this is dcs_all_classes plus
+# kept_returncodes.
+body classes all_classes_kept_0(prefix)
+{
+  promise_kept => { "$(prefix)_promise_kept" };
+  promise_repaired => { "$(prefix)_promise_repaired" };
+  repair_failed => { "$(prefix)_repair_failed" };
+  repair_denied => { "$(prefix)_repair_denied" };
+  repair_timeout => { "$(prefix)_repair_timeout" };
+  kept_returncodes => { "0" };
+}
+
+#######################################################
+bundle agent check
+{
+  methods:
+    "any"
+      usebundle => dcs_passif_expected(
+        "timeout_kept0_repair_timeout",
+        "timeout_kept0_promise_kept,timeout_kept0_promise_repaired",
+        $(this.promise_filename)
+      ),
+      inherit => "true";
+}
+
+### PROJECT_ID: core
+### CATEGORY_ID: 26