Delayed follow-up tasks can fire before their requested delay

[achamayou]

Describe the bug

JobBoard::tick() makes expired tasks runnable before publishing the new value of delayed.total_elapsed. A worker can run an expired task and schedule a follow-up in the interval between releasing delayed.tasks_mutex and storing the updated clock. The follow-up is then scheduled relative to the old clock.

A bounded two-actor scenario using the deterministic scheduler from #8238 exhaustively explored 759 schedules. In 178, a parent timer fired by tick(100ms) scheduled a child with a requested 10ms delay, but that child fired at logical time 101ms, rather than 110ms. The remaining 581 schedules fired the child at 110ms. These are schedule counts, not estimates of real-world frequency.

Relevant source:

• add_timed_task() lines 158-166 calculates the deadline from total_elapsed while holding delayed.tasks_mutex.
• tick() lines 169-214 publishes ready tasks at line 192, releases the mutex at line 212, and only then stores the new clock at line 214.

The clock is atomic, so this is a synchronization/ordering bug rather than an unsynchronized access to that field.

To Reproduce

Use the harness from #8238 at 344e89c59adac38087267bd9189b8e7b855bb328 over CCF ee34e7b2e0d3ae7f7a43a913d8ecfe35f7d74a9e. Link the following scenario into commit_concurrency_scheduled_test, which wraps the pthread operations of ccf::ds::Mutex, including those in the normally linked ccf_tasks library.

#include "commit_concurrency/scheduled/deterministic_scheduler.h"
#include "tasks/basic_task.h"
#include "tasks/job_board.h"

#define DOCTEST_CONFIG_NO_SHORT_MACRO_NAMES
#include <doctest/doctest.h>
#include <iostream>

using namespace std::chrono_literals;
using namespace ccf::kv::test;

struct DelayedFollowUp
{
  ccf::tasks::JobBoard board;
  size_t parent_calls = 0;
  size_t child_calls = 0;

  DelayedFollowUp()
  {
    board.add_delayed_task(
      ccf::tasks::make_basic_task([this]() {
        ++parent_calls;
        board.add_delayed_task(
          ccf::tasks::make_basic_task([this]() { ++child_calls; }), 10ms);
      }),
      100ms);
  }

  void run_one_if_ready()
  {
    // One consumer; do not enter the unmodelled condition-variable path.
    if (board.get_summary().pending_tasks != 0)
    {
      board.get_task()->do_task();
    }
  }
};

DOCTEST_TEST_CASE("A fired timer schedules its child against the new clock")
{
  std::unique_ptr<DelayedFollowUp> scenario;
  size_t early = 0;
  size_t on_time = 0;
  const auto explored = explore_all_interleavings(
    2,
    [&]() -> std::vector<std::function<void()>> {
      scenario = std::make_unique<DelayedFollowUp>();
      return {
        [&]() { scenario->board.tick(100ms); },
        [&]() { scenario->run_one_if_ready(); }};
    },
    [&](const DeterministicScheduler& scheduler) {
      if (scenario->parent_calls == 0)
      {
        scenario->run_one_if_ready();
      }
      DOCTEST_REQUIRE(scenario->parent_calls == 1);
      DOCTEST_REQUIRE(scenario->child_calls == 0);
      DOCTEST_REQUIRE(scenario->board.get_summary().pending_tasks == 0);

      scenario->board.tick(1ms);
      scenario->run_one_if_ready();
      if (scenario->child_calls != 0)
      {
        ++early;
      }
      else
      {
        ++on_time;
      }

      scenario->board.tick(9ms);
      scenario->run_one_if_ready();
      DOCTEST_REQUIRE(scenario->child_calls == 1);
      DOCTEST_REQUIRE(scenario->board.get_summary().pending_tasks == 0);
    },
    100000,
    {"ticker", "worker"});

  std::cout << "explored=" << explored << ", early=" << early
            << ", on_time=" << on_time << '\n';
  DOCTEST_CHECK(early == 0);
}

The recorded first counterexample in the investigation test has chooser indices:

0,0,0,0,0,0,1,1,1,1,1,1,1,1,1,0,0

Its causal ordering is:

1. Start with logical time 0 and a parent due at 100ms.
2. The ticker enters tick(100ms) and publishes the parent.
3. The ticker releases delayed.tasks_mutex, but is paused before total_elapsed.store(100ms).
4. The worker runs the parent and schedules its child with a delay of 10ms. add_timed_task() reads 0ms and records a deadline of 10ms.
5. The ticker resumes and publishes 100ms.
6. After both actors finish, tick(1ms) releases the child at 101ms.

Observed exhaustive result:

Delayed follow-up: explored=759, fired_at_101ms=178, fired_at_110ms=581
CHECK(early_schedules == 0): 178 == 0 [fails]

Expected behavior

The parent cannot run before the 100ms tick makes it ready. A 10ms follow-up requested by that parent must not become eligible at 101ms. Updating the logical clock and allowing concurrent deadline calculation must be ordered consistently.

Environment information

• CCF: ee34e7b2e0d3ae7f7a43a913d8ecfe35f7d74a9e.
• Harness: [WIP] Systematic testing: Test the full KV + History + Consensus stack, with deterministic and randomly-explored interleavings #8238, 344e89c59adac38087267bd9189b8e7b855bb328.
• Ubuntu 26.04 under WSL; Clang 21.1.8; CMake 4.2.3; Debug build; USE_SNMALLOC=OFF.
• Two explicitly enrolled actors: one ticker and one task consumer. No simultaneous tick() calls, background worker pool, native condition-variable waits, or try_lock() calls are required.

Additional context

This pattern has production users: NetworkIdentitySubsystem::fetch_first() lines 266-287 reschedules retries through TaskSchedulerImpl, which delegates to ccf::tasks::add_delayed_task(). Concurrent task scheduling is also explicitly covered by the existing task-system tests.

The reproduction establishes incorrect relative-delay semantics; it does not quantify operational impact or production frequency. Publishing the updated clock before releasing the delayed-task lock is a candidate correction, but no production fix is included here.