From 1d1cd71a0d043397e2d61c9d983ced31ed19a0e4 Mon Sep 17 00:00:00 2001 From: Nick Anderson Date: Sat, 11 Jul 2026 14:10:17 -0500 Subject: [PATCH] Fixed duplicate log_* entries from action bodies (CFE-85) A single promise could produce multiple identical entries in the log_kept, log_repaired, or log_failed files configured via an action body. This happened because DoSummarizeTransaction is called once per evaluation pass and once per sub-attribute check (e.g. create then perms), each writing to the log file independently. Fix by recording a composite key (PromiseID + expanded promiser) in a StringSet on the EvalContext the first time a promise is logged, and skipping subsequent calls for the same key. PromiseID alone would falsely suppress a parameterized bundle called with different arguments (same source line, different expanded promiser); the expanded promiser alone would suppress distinct promises in different bundles targeting the same path. The composite key handles both cases. The dedup is gated on at least one log_* target being configured, so promises without action bodies pay no cost. Ticket: CFE-85 Changelog: Title --- libpromises/eval_context.c | 35 ++++++- .../acceptance/00_basics/03_bodies/cfe_85.cf | 70 +++++++++++++ tests/unit/eval_context_test.c | 99 +++++++++++++++++++ 3 files changed, 200 insertions(+), 4 deletions(-) create mode 100644 tests/acceptance/00_basics/03_bodies/cfe_85.cf diff --git a/libpromises/eval_context.c b/libpromises/eval_context.c index 4d25864eaf..cc36e7e898 100644 --- a/libpromises/eval_context.c +++ b/libpromises/eval_context.c @@ -162,6 +162,11 @@ struct EvalContext_ StringSet *dependency_handles; FuncCacheMap *function_cache; + /* Promisers whose log_* actions have already been written during this + * run. Used to avoid duplicate entries in the log files (see + * SummarizeTransaction / CFE-85). */ + StringSet *logged_promisers; + uid_t uid; uid_t gid; pid_t pid; @@ -1124,6 +1129,7 @@ EvalContext *EvalContextNew(void) ctx->promise_lock_cache = StringSetNew(); ctx->function_cache = FuncCacheMapNew(); + ctx->logged_promisers = StringSetNew(); EvalContextSetupMissionPortalLogHook(ctx); @@ -1178,6 +1184,7 @@ void EvalContextDestroy(EvalContext *ctx) StringSetDestroy(ctx->dependency_handles); StringSetDestroy(ctx->promise_lock_cache); + StringSetDestroy(ctx->logged_promisers); FuncCacheMapDestroy(ctx->function_cache); @@ -3170,20 +3177,40 @@ static void SummarizeTransaction(EvalContext *ctx, const TransactionContext *tc, } BufferDestroy(buffer); - // FIXME: This was overwriting a local copy, with no side effects. - // The intention was clearly to skip this function if called - // repeatedly. Try to introduce this change: - // tc.log_string = NULL; /* To avoid repetition */ } } static void DoSummarizeTransaction(EvalContext *ctx, PromiseResult status, const Promise *pp, const TransactionContext *tc) { + assert(ctx != NULL); + assert(tc != NULL); + if (!IsPromiseValuableForLogging(pp)) { return; } + /* CFE-85: a single promise is evaluated several times per run (per + * evaluation pass, per sub-attribute check such as create vs perms), each + * producing a log_* entry. Suppress duplicates by recording the promise's + * identity and skipping later calls; the first outcome wins. + * + * The key combines PromiseID (source location / handle) with the expanded + * promiser so that a parameterized bundle called with different arguments + * (e.g. install("vim") and install("curl")) is not falsely suppressed. */ + if (tc->log_repaired == NULL && tc->log_kept == NULL && tc->log_failed == NULL) + { + return; /* No log targets configured -- nothing to deduplicate. */ + } + + char key[CF_BUFSIZE]; + xsnprintf(key, sizeof(key), "%s:%s", PromiseID(pp), pp->promiser); + if (StringSetContains(ctx->logged_promisers, key)) + { + return; + } + StringSetAdd(ctx->logged_promisers, xstrdup(key)); + char *log_name = NULL; switch (status) diff --git a/tests/acceptance/00_basics/03_bodies/cfe_85.cf b/tests/acceptance/00_basics/03_bodies/cfe_85.cf new file mode 100644 index 0000000000..ab4f47d3de --- /dev/null +++ b/tests/acceptance/00_basics/03_bodies/cfe_85.cf @@ -0,0 +1,70 @@ +# Test that a single promise writes at most one entry to the log_kept / +# log_repaired / log_failed files set in an action body, instead of one entry +# per evaluation pass and per sub-attribute check (CFE-85). +body common control +{ + inputs => { "../../default.sub.cf" }; + bundlesequence => { default("$(this.promise_filename)") }; + version => "1.0"; +} + +bundle agent init +{ + vars: + "software" slist => { "$(G.testdir)/123", "$(G.testdir)/xyz" }; +} + +bundle agent test +{ + files: + "$(init.software)" + create => "true", + perms => m("644"), + action => logme; +} + +body action logme +{ + log_kept => "$(G.testdir)/private_keptlog.log"; + log_repaired => "$(G.testdir)/private_replog.log"; + log_failed => "$(G.testdir)/private_faillog.log"; + log_string => "$(this.promiser) promise status"; +} + +bundle agent check +{ + vars: + # Each promiser should be logged exactly once in total across the three + # log files. Two promisers therefore means exactly two lines in total. + # Without the fix (CFE-85) many duplicate lines are written. + "kept_lines" + int => countlinesmatching(".*", "$(G.testdir)/private_keptlog.log"); + + "repair_lines" + int => countlinesmatching(".*", "$(G.testdir)/private_replog.log"); + + "fail_lines" + int => countlinesmatching(".*", "$(G.testdir)/private_faillog.log"); + + "counts" slist => { "$(kept_lines)", "$(repair_lines)", "$(fail_lines)" }; + "total" real => sum("counts"); + + classes: + # Both promisers are created fresh (create => "true"), so each lands once + # in the repaired log and nowhere else. The fix (CFE-85) guarantees exactly + # one entry per promiser: repair_lines == 2 and total == 2 means neither + # missing nor duplicated. + "ok" + expression => strcmp("$(repair_lines)", "2"), + and => strcmp("$(total)", "2"); + + reports: + DEBUG:: + "kept=$(kept_lines) repaired=$(repair_lines) failed=$(fail_lines) total=$(total)"; + + ok:: + "$(this.promise_filename) Pass"; + + !ok:: + "$(this.promise_filename) FAIL: total log entries = $(total), expected exactly 2 (one per promiser)"; +} diff --git a/tests/unit/eval_context_test.c b/tests/unit/eval_context_test.c index 77234beda8..3b6556d836 100644 --- a/tests/unit/eval_context_test.c +++ b/tests/unit/eval_context_test.c @@ -1,9 +1,14 @@ #include #include +#include +#include #include /* xsnprintf */ +#include /* xstrdup */ +#include #include #include +#include /* unlink */ char CFWORKDIR[CF_BUFSIZE]; @@ -197,6 +202,99 @@ static void test_persistent_class_timer_policy(void) EvalContextDestroy(ctx); } +/* CFE-85: a single promise must produce at most one entry in its log_* + * file, even when cfPS() (and thus SummarizeTransaction) is invoked multiple + * times for that promise during a run (once per evaluation pass / sub-check). + * + * This test verifies three scenarios: + * 1. Same promise, same promiser, two cfPS calls -> deduped to one line. + * 2. Different promise (different file/line), same promiser -> each gets a line. + * 3. Same source promise (same PromiseID), different expanded promiser + * (simulates a parameterized bundle) -> each gets a line. */ +static void test_log_action_dedupe(void) +{ + char logpath[CF_BUFSIZE]; + xsnprintf(logpath, sizeof(logpath), "%s/cfe85_dedupe_test.log", CFWORKDIR); + + EvalContext *ctx = EvalContextNew(); + Policy *policy = PolicyNew(); + Bundle *bundle = PolicyAppendBundle(policy, "default", "bundle1", + "agent", NULL, NULL, + EVAL_ORDER_UNDEFINED); + bundle->source_path = xstrdup("/policy1.cf"); + BundleSection *section = BundleAppendSection(bundle, "files"); + Promise *promise = BundleSectionAppendPromise(section, "/tmp/cfe85_dedupe_test", + (Rval) { NULL, RVAL_TYPE_NOPROMISEE }, + "any", NULL); + promise->offset.line = 10; + + /* Minimal attributes: only the transaction log_* fields matter for + * ClassAuditLog -> DoSummarizeTransaction. The classes list is left + * NULL, which SetPromiseOutcomeClasses tolerates. */ + Attributes attr; + memset(&attr, 0, sizeof(attr)); + attr.transaction.log_string = xstrdup("logged"); + attr.transaction.log_repaired = xstrdup(logpath); + + /* First call simulates the first evaluation (e.g. repaired). */ + cfPS(ctx, LOG_LEVEL_VERBOSE, PROMISE_RESULT_CHANGE, promise, &attr, + "files promise '%s' repaired", promise->promiser); + + /* Second call simulates a later pass / sub-check for the same promise. + * Without the CFE-85 fix this would append a second duplicate line. */ + cfPS(ctx, LOG_LEVEL_VERBOSE, PROMISE_RESULT_CHANGE, promise, &attr, + "files promise '%s' repaired", promise->promiser); + + /* Scenario 2: a distinct promise (different file/line identity) targeting + * the SAME path must still get its own line. */ + Bundle *bundle2 = PolicyAppendBundle(policy, "default", "bundle2", + "agent", NULL, NULL, + EVAL_ORDER_UNDEFINED); + bundle2->source_path = xstrdup("/policy2.cf"); + BundleSection *section2 = BundleAppendSection(bundle2, "files"); + Promise *promise2 = BundleSectionAppendPromise(section2, "/tmp/cfe85_dedupe_test", + (Rval) { NULL, RVAL_TYPE_NOPROMISEE }, + "any", NULL); + promise2->offset.line = 20; + cfPS(ctx, LOG_LEVEL_VERBOSE, PROMISE_RESULT_CHANGE, promise2, &attr, + "files promise '%s' repaired", promise2->promiser); + + /* Scenario 3: same source location (same PromiseID) but different + * expanded promiser, simulating a parameterized bundle called twice + * with different arguments -- e.g. install("vim") then install("curl"). + * Must NOT be suppressed. */ + Promise *promise3 = BundleSectionAppendPromise(section, "/tmp/cfe85_other_path", + (Rval) { NULL, RVAL_TYPE_NOPROMISEE }, + "any", NULL); + promise3->offset.line = 10; /* same line as promise1 in same bundle */ + cfPS(ctx, LOG_LEVEL_VERBOSE, PROMISE_RESULT_CHANGE, promise3, &attr, + "files promise '%s' repaired", promise3->promiser); + + FILE *f = fopen(logpath, "r"); + assert_true(f != NULL); + int lines = 0; + char buf[1024]; + while (fgets(buf, sizeof(buf), f) != NULL) + { + if (buf[0] != '\0' && buf[0] != '\n') + { + lines++; + } + } + fclose(f); + unlink(logpath); + + /* Three entries: scenario 1 deduped from 2 calls to 1, scenario 2 adds 1 + * (different promise identity), scenario 3 adds 1 (same PromiseID but + * different expanded promiser). */ + assert_int_equal(lines, 3); + + free(attr.transaction.log_string); + free(attr.transaction.log_repaired); + PolicyDestroy(policy); + EvalContextDestroy(ctx); +} + int main() { PRINT_TEST_BANNER(); @@ -208,6 +306,7 @@ int main() unit_test(test_persistent_class_timer_policy), unit_test(test_changes_chroot), unit_test(test_eval_with_token_from_list), + unit_test(test_log_action_dedupe), }; int ret = run_tests(tests);