ENT-14695: Record events promise outcome

cf-reactor/file_watcher.c

@@ -32,36 +32,54 @@
 
 // =========== code for EVENT_FILE_DELETED event type ===========
 
+/* Minimum time between two logs of a persisting lstat() failure, since the
+ * file is checked on every poll */
+#define LSTAT_ERROR_LOG_INTERVAL_SECS 60
+
 typedef struct
 {
     char *path;
     time_t last_seen; /* Time the file was last observed present, 0 if absent */
+    time_t lstat_error_logged; /* Time an lstat() failure was last logged, 0 if lstat() works */
 } FileWatcherState;
 
-/* Sets *deleted to whether the path exists. Only ENOENT/ENOTDIR mean the path
- * genuinely doesn't exist. Any other lstat() failure (e.g. EACCES, ESTALE) is
- * a transient/permission error, in which case we can't tell whether the file
- * was deleted, so false is returned and *deleted is left untouched.
+/* Sets *deleted to whether the path of the watcher exists. Only
+ * ENOENT/ENOTDIR mean the path genuinely doesn't exist. Any other lstat()
+ * failure (e.g. EACCES, ESTALE) is a transient/permission error, in which case
+ * we can't tell whether the file was deleted, so false is returned and
+ * *deleted is left untouched. A persisting failure is logged at most once
+ * every LSTAT_ERROR_LOG_INTERVAL_SECS.
  *
  * Doesn't follow symlinks, i.e. a dangling symlink is not considered deleted */
-static bool FileDeleted(const char *path, bool *deleted)
+static bool FileDeleted(FileWatcherState *fws, bool *deleted)
 {
+    assert(fws != NULL);
     assert(deleted != NULL);
 
     struct stat sb;
-    if (lstat(path, &sb) == 0)
+    if (lstat(fws->path, &sb) == 0)
     {
         *deleted = false;
+        fws->lstat_error_logged = 0;
         return true;
     }
 
     if (errno == ENOENT || errno == ENOTDIR)
     {
         *deleted = true;
+        fws->lstat_error_logged = 0;
         return true;
     }
 
-    Log(LOG_LEVEL_ERR, "Unable to lstat '%s' while checking for file deletion: %s", path, GetErrorStr());
+    const int lstat_errno = errno;
+    const time_t now = time(NULL);
+    if (fws->lstat_error_logged == 0 ||
+        now - fws->lstat_error_logged >= LSTAT_ERROR_LOG_INTERVAL_SECS)
+    {
+        Log(LOG_LEVEL_ERR, "Unable to lstat '%s' while checking for file deletion: %s",
+            fws->path, GetErrorStrFromCode(lstat_errno));
+        fws->lstat_error_logged = now;
+    }
     return false;
 }
 
@@ -70,24 +88,25 @@ void *FileWatcherStateNew(const char *path)
     FileWatcherState *fws = (FileWatcherState *) xmalloc(sizeof(FileWatcherState));
 
     fws->path = xstrdup(path);
+    fws->lstat_error_logged = 0;
 
     /* If the file's presence can't be determined, treat it as not yet seen */
     bool deleted;
-    fws->last_seen = (FileDeleted(path, &deleted) && !deleted) ? time(NULL) : 0;
+    fws->last_seen = (FileDeleted(fws, &deleted) && !deleted) ? time(NULL) : 0;
 
     return (void *) fws;
 }
 
-bool CheckFileDeleted(void *state)
+WatcherCheckResult CheckFileDeleted(void *state)
 {
     assert(state != NULL);
     FileWatcherState *fws = state;
 
     bool deleted_now;
-    if (!FileDeleted(fws->path, &deleted_now))
+    if (!FileDeleted(fws, &deleted_now))
     {
-        /* Unknown state, skip this check and keep last_seen as is */
-        return false;
+        /* Unknown state, keep last_seen as is */
+        return WATCHER_CHECK_ERROR;
     }
 
     const time_t now = time(NULL);
@@ -109,7 +128,7 @@ bool CheckFileDeleted(void *state)
     }
 
     fws->last_seen = deleted_now ? 0 : now;
-    return deleted;
+    return deleted ? WATCHER_CHECK_EVENT : WATCHER_CHECK_NO_EVENT;
 }
 
 void DestroyFileWatcherState(void *state)

cf-reactor/file_watcher.h

@@ -26,10 +26,11 @@
 #define CFENGINE_FILE_WATCHER_H
 
 #include <platform.h>
+#include <watcher.h>            /* WatcherCheckResult */
 
 
 void *FileWatcherStateNew(const char *path);
-bool CheckFileDeleted(void *state);
+WatcherCheckResult CheckFileDeleted(void *state);
 void DestroyFileWatcherState(void *state);
 
 #endif

cf-reactor/reactor_transform.c

@@ -35,7 +35,7 @@
 #include <watcher.h>
 #include <file_watcher.h>
 #include <agent_operations.h>   // ScheduleAgentOperations()
-#include <attributes.h>
+#include <attributes.h>          // GetClassContextAttributes()
 #include <conn_cache.h>          // ConnCache_Init(), ConnCache_Destroy()
 #include <mod_custom.h>          // Initialize/FinalizeCustomPromises()
 #include <timeout.h>             // SetReferenceTime()
@@ -98,6 +98,18 @@ static const Bundle *ResolveThenBundle(
     return bp;
 }
 
+/* Records the outcome of an iteration of an events promise: defines the
+ * classes of its 'classes' body, and logs it like cf-agent does for its
+ * promises. */
+static void RecordEventsPromiseOutcome(EvalContext *ctx, const Promise *pp, PromiseResult result)
+{
+    assert(pp != NULL);
+
+    Attributes a = GetClassContextAttributes(ctx, pp);
+    ClassAuditLog(ctx, pp, &a, result);
+    EvalContextLogPromiseIterationOutcome(ctx, pp, result);
+}
+
 // Temporary limitations:
 // - 'when' body: only a single constraint, 'file_deleted', is supported (no OR-ing of constraints yet)
 // - 'then': only a single bundle is supported, not a list of bundles yet
@@ -152,7 +164,9 @@ static PromiseResult KeepReactorPromise(EvalContext *ctx, const Promise *pp, ARG
 
     if (StringEqual(PromiseGetPromiseType(pp), "events"))
     {
-        return KeepEventsPromise(ctx, pp);
+        PromiseResult result = KeepEventsPromise(ctx, pp);
+        RecordEventsPromiseOutcome(ctx, pp, result);
+        return result;
     }
 
     return PROMISE_RESULT_NOOP;
@@ -237,10 +251,12 @@ static PromiseResult RunThenBundle(EvalContext *ctx, const Promise *pp)
 typedef struct
 {
     const char *promiser;
+    WatcherCheckResult check;
 } ReactorEventParam;
 
-/* Promise actuator for an events promise whose watcher fired. Only acts on
- * the iteration the watcher was registered for. */
+/* Promise actuator for an events promise whose watcher fired, or failed to
+ * check for its event. Only acts on the iteration the watcher was registered
+ * for. */
 static PromiseResult KeepEventsPromiseOnEvent(EvalContext *ctx, const Promise *pp, void *param)
 {
     assert(pp != NULL);
@@ -252,10 +268,28 @@ static PromiseResult KeepEventsPromiseOnEvent(EvalContext *ctx, const Promise *p
         return PROMISE_RESULT_SKIPPED;
     }
 
-    return RunThenBundle(ctx, pp);
+    PromiseResult result;
+    switch (event->check)
+    {
+    case WATCHER_CHECK_EVENT:
+        result = RunThenBundle(ctx, pp);
+        break;
+
+    case WATCHER_CHECK_ERROR:
+        Log(LOG_LEVEL_ERR, "Reactor events promise '%s' failed to check for its event", pp->promiser);
+        result = PROMISE_RESULT_FAIL;
+        break;
+
+    default:
+        ProgrammingError("Unexpected watcher check result %d for reactor events promise '%s'",
+                         (int) event->check, pp->promiser);
+    }
+
+    RecordEventsPromiseOutcome(ctx, pp, result);
+    return result;
 }
 
-void HandleReactorEvent(EvalContext *ctx, const Promise *pp, const char *promiser)
+void HandleReactorEvent(EvalContext *ctx, const Promise *pp, const char *promiser, WatcherCheckResult check)
 {
     assert(pp != NULL);
     assert(promiser != NULL);
@@ -270,7 +304,7 @@ void HandleReactorEvent(EvalContext *ctx, const Promise *pp, const char *promise
     VariableTable *variables = NULL;
     EvalContextSnapshotTake(ctx, &classes, &variables);
 
-    ReactorEventParam event = { .promiser = promiser };
+    ReactorEventParam event = { .promiser = promiser, .check = check };
 
     EvalContextStackPushBundleFrame(ctx, PromiseGetBundle(pp), NULL, false, NULL);
     EvalContextStackPushBundleSectionFrame(ctx, pp->parent_section);

cf-reactor/reactor_transform.h

@@ -27,6 +27,7 @@
 
 #include <eval_context.h>
 #include <policy.h>
+#include <watcher.h>     /* WatcherCheckResult */
 
 /**
  * @brief Evaluate every `bundle reactor NAME { ... }` in the given policy:
@@ -42,12 +43,16 @@ void KeepReactorPromises(EvalContext *ctx, const Policy *policy);
 
 /**
  * @brief Keep the events promise of a watcher that fired (see WatcherEventFn
- * in watcher.h): run the bundle of its 'then' attribute.
+ * in watcher.h): run the bundle of its 'then' attribute, and record the
+ * outcome of the bundle as the outcome of the events promise. If the watcher
+ * failed to check for its event, record a failure instead.
  *
  * @param pp the unexpanded events promise the watcher was registered for
  * @param promiser the expanded promiser the watcher was registered with,
  *                 selecting the iteration of the events promise to keep
+ * @param check whether the event happened or the watcher failed to check for
+ *              it (see WatcherEventFn)
  */
-void HandleReactorEvent(EvalContext *ctx, const Promise *pp, const char *promiser);
+void HandleReactorEvent(EvalContext *ctx, const Promise *pp, const char *promiser, WatcherCheckResult check);
 
 #endif

cf-reactor/watcher.c

@@ -51,8 +51,16 @@ typedef struct
     const Promise *promise; // the unexpanded events promise, owned by the policy
     time_t poll_interval_secs;
     time_t next_due;
+    WatcherCheckResult last_check; // only touched by the watcher thread
 } Watcher;
 
+/* Item of the event queue */
+typedef struct
+{
+    const Watcher *watcher;
+    WatcherCheckResult check; // see WatcherEventFn
+} WatcherEvent;
+
 static void WatcherDestroy(void *item);
 
 /* Guards `watchers` and `paused` against the watcher thread
@@ -65,10 +73,11 @@ static bool paused = false;         /* see EventWatcherPause() */
 
 static WakeupChannel wakeup_channel = { .fds = { -1, -1 } };
 
-/* Watchers that fired, queued by the watcher thread for the main thread to
- * handle. Not owned: the watcher thread only queues watchers of the registry
- * while holding watchers_mutex, and WatcherRegistryClear() requires the queue
- * to be empty, so the queued watchers are always registered. */
+/* Events of watchers (WatcherEvent), queued by the watcher thread for the
+ * main thread to handle. The watchers are not owned: the watcher thread only
+ * queues events of watchers of the registry while holding watchers_mutex, and
+ * WatcherRegistryClear() requires the queue to be empty, so the watchers of
+ * the queued events are always registered. */
 static ThreadedQueue *event_queue = NULL;
 static StoppableThread *watcher_thread = NULL;
 
@@ -163,6 +172,7 @@ bool WatcherRegister(const char *promiser, EventType type, void *state, const Pr
     w->promise = pp;
     w->poll_interval_secs = interval;
     w->next_due = 0; /* due immediately on the watcher thread's first pass */
+    w->last_check = WATCHER_CHECK_NO_EVENT;
     w->check_callback = check_callback;
     w->destroy_state = destroy_state;
 
@@ -209,13 +219,21 @@ static void WatcherThreadMain(StoppableThread *thread, ARG_UNUSED void *unused)
 
             if (now >= w->next_due)
             {
-                bool fired = w->check_callback(w->state);
+                WatcherCheckResult check = w->check_callback(w->state);
                 w->next_due = now + w->poll_interval_secs;
-                if (fired)
+
+                /* Only report a failing watcher once, not on every check,
+                 * until it recovers */
+                if (check == WATCHER_CHECK_EVENT ||
+                    (check == WATCHER_CHECK_ERROR && w->last_check != WATCHER_CHECK_ERROR))
                 {
-                    ThreadedQueuePush(event_queue, w);
+                    WatcherEvent *event = xmalloc(sizeof(WatcherEvent));
+                    event->watcher = w;
+                    event->check = check;
+                    ThreadedQueuePush(event_queue, event);
                     any_event = true;
                 }
+                w->last_check = check;
             }
 
             time_t until_due = (w->next_due > now) ? (w->next_due - now) : 0;
@@ -244,7 +262,7 @@ bool EventWatcherInitialize(int *fd)
         return false;
     }
 
-    event_queue = ThreadedQueueNew(16, NULL);
+    event_queue = ThreadedQueueNew(16, free);
 
     watcher_thread = StoppableThreadStart(WatcherThreadMain, NULL);
     if (watcher_thread == NULL)
@@ -264,18 +282,28 @@ bool EventWatcherInitialize(int *fd)
 
 /* Watchers are only destroyed by the main thread (WatcherRegistryClear()),
  * which is also the one handling events, and never while events are queued,
- * so the queued watchers can be used without holding watchers_mutex. Their
- * promiser and promise are never modified by the watcher thread. */
+ * so the watchers of queued events can be used without holding
+ * watchers_mutex. Their promiser and promise are never modified by the
+ * watcher thread. */
 static void HandleQueuedEvents(EvalContext *ctx, WatcherEventFn on_event)
 {
     assert(on_event != NULL);
 
     void *item;
     while (ThreadedQueuePop(event_queue, &item, 0))
     {
-        const Watcher *w = item;
-        Log(LOG_LEVEL_NOTICE, "Reactor watcher '%s' fired", w->promiser);
-        on_event(ctx, w->promise, w->promiser);
+        WatcherEvent *event = item;
+        const Watcher *w = event->watcher;
+        if (event->check == WATCHER_CHECK_ERROR)
+        {
+            Log(LOG_LEVEL_ERR, "Reactor watcher '%s' failed to check for its event", w->promiser);
+        }
+        else
+        {
+            Log(LOG_LEVEL_NOTICE, "Reactor watcher '%s' fired", w->promiser);
+        }
+        on_event(ctx, w->promise, w->promiser, event->check);
+        free(event);
     }
 }
 

cf-reactor/watcher.h

@@ -32,20 +32,31 @@ typedef enum
   EVENT_FILE_DELETED,
 } EventType;
 
-typedef bool (*WatcherCheckFn)(void *state);
+typedef enum
+{
+  WATCHER_CHECK_NO_EVENT,
+  WATCHER_CHECK_EVENT,
+  WATCHER_CHECK_ERROR,      /* unable to tell whether the event happened */
+} WatcherCheckResult;
+
+typedef WatcherCheckResult (*WatcherCheckFn)(void *state);
 typedef void (*WatcherStateDestroyFn)(void *state);
 
 /**
- * @brief Called on the main thread for every event of a registered watcher.
+ * @brief Called on the main thread for every event of a registered watcher,
+ *        and whenever a watcher starts failing to check for its event.
  *
  * @param pp the (unexpanded) events promise the watcher was registered for
  * @param promiser the expanded promiser the watcher was registered with,
  *                 selecting the iteration of the events promise
+ * @param check WATCHER_CHECK_EVENT if the event happened, or
+ *              WATCHER_CHECK_ERROR if the watcher failed to check for it
+ *              (only reported once until a check succeeds again)
  * @note Called without the watcher registry locked, but it must not call
  *       WatcherRegistryClear(), as the events of the watchers are being
  *       handled.
  */
-typedef void (*WatcherEventFn)(EvalContext *ctx, const Promise *pp, const char *promiser);
+typedef void (*WatcherEventFn)(EvalContext *ctx, const Promise *pp, const char *promiser, WatcherCheckResult check);
 
 void WatcherRegistryInitialize(void);
 void WatcherRegistryFinalize(void);