From 238e35b581539f40d66a6052a602b3fda8e170fd Mon Sep 17 00:00:00 2001 From: Francesco Cozzuto Date: Wed, 18 Feb 2026 18:45:44 +0100 Subject: [PATCH] Version 0.9 --- build.sh | 12 +- lib/file_system.c | 2 +- quakey/include/quakey.h | 13 + quakey/src/quakey.c | 484 +++++- raft/client.c | 92 +- raft/client.h | 10 + raft/client_table.c | 45 + raft/client_table.h | 28 + raft/invariant_checker.c | 351 +++++ raft/invariant_checker.h | 17 + raft/main.c | 52 +- raft/node.c | 1362 ++++++++--------- raft/node.h | 99 +- raft/wal.c | 87 +- raft/wal.h | 12 +- state_machine/kvstore.c | 118 ++ state_machine/kvstore.h | 51 + state_machine/state_machine.c | 25 - state_machine/state_machine.h | 26 - table.txt | 247 ++++ vsr/client.c | 188 ++- vsr/client.h | 12 + vsr/client_table.c | 4 +- vsr/client_table.h | 13 +- vsr/config.h | 2 + vsr/invariant_checker.c | 395 +++++ vsr/log.c | 18 + vsr/log.h | 7 +- vsr/main.c | 44 +- vsr/node.c | 2607 ++++++++++++++++----------------- vsr/node.h | 86 +- 31 files changed, 4256 insertions(+), 2253 deletions(-) create mode 100644 raft/client_table.c create mode 100644 raft/client_table.h create mode 100644 raft/invariant_checker.c create mode 100644 raft/invariant_checker.h create mode 100644 state_machine/kvstore.c create mode 100644 state_machine/kvstore.h delete mode 100644 state_machine/state_machine.c delete mode 100644 state_machine/state_machine.h create mode 100644 table.txt create mode 100644 vsr/invariant_checker.c diff --git a/build.sh b/build.sh index 0a1a46e..5b87308 100644 --- a/build.sh +++ b/build.sh @@ -1,6 +1,6 @@ -gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c vsr/node.c vsr/client.c vsr/main.c vsr/log.c vsr/client_table.c state_machine/state_machine.c quakey/src/mockfs.c quakey/src/quakey.c -o vsr_simulation -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SIMULATION -DFAULT_INJECTION -gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c vsr/node.c vsr/client.c vsr/main.c vsr/log.c vsr/client_table.c state_machine/state_machine.c -o vsr_server -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SERVER -gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c vsr/node.c vsr/client.c vsr/main.c vsr/log.c vsr/client_table.c state_machine/state_machine.c -o vsr_client -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_CLIENT -gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c raft/node.c raft/client.c raft/wal.c raft/main.c state_machine/state_machine.c quakey/src/mockfs.c quakey/src/quakey.c -o raft_simulation -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SIMULATION -DFAULT_INJECTION -DDISABLE_DISK_CORRUPTION -gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c raft/node.c raft/client.c raft/wal.c raft/main.c state_machine/state_machine.c -o raft_server -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SERVER -gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c raft/node.c raft/client.c raft/wal.c raft/main.c state_machine/state_machine.c -o raft_client -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_CLIENT \ No newline at end of file +gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c vsr/node.c vsr/client.c vsr/main.c vsr/log.c vsr/client_table.c vsr/invariant_checker.c state_machine/kvstore.c quakey/src/mockfs.c quakey/src/quakey.c -o vsr_simulation -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SIMULATION -DFAULT_INJECTION +gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c vsr/node.c vsr/client.c vsr/main.c vsr/log.c vsr/client_table.c state_machine/kvstore.c -o vsr_server -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SERVER +gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c vsr/node.c vsr/client.c vsr/main.c vsr/log.c vsr/client_table.c state_machine/kvstore.c -o vsr_client -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_CLIENT +gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c raft/node.c raft/client.c raft/wal.c raft/client_table.c raft/invariant_checker.c raft/main.c state_machine/kvstore.c quakey/src/mockfs.c quakey/src/quakey.c -o raft_simulation -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SIMULATION -DFAULT_INJECTION -DDISABLE_DISK_CORRUPTION -DDISABLE_SPURIOUS_IO_ERRORS +gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c raft/node.c raft/client.c raft/wal.c raft/client_table.c raft/main.c state_machine/kvstore.c -o raft_server -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_SERVER +gcc lib/basic.c lib/file_system.c lib/byte_queue.c lib/message.c lib/tcp.c raft/node.c raft/client.c raft/wal.c raft/client_table.c raft/main.c state_machine/kvstore.c -o raft_client -Iquakey/include -I. -Wall -Wextra -ggdb -O0 -DMAIN_CLIENT \ No newline at end of file diff --git a/lib/file_system.c b/lib/file_system.c index 8323eb0..5acea6f 100644 --- a/lib/file_system.c +++ b/lib/file_system.c @@ -36,7 +36,7 @@ int file_open(string path, Handle *fd) memcpy(zt, path.ptr, path.len); zt[path.len] = '\0'; - int ret = open(zt, O_RDWR | O_CREAT | O_APPEND, 0644); + int ret = open(zt, O_RDWR | O_CREAT, 0644); if (ret < 0) return -1; diff --git a/quakey/include/quakey.h b/quakey/include/quakey.h index 8978642..dc60515 100644 --- a/quakey/include/quakey.h +++ b/quakey/include/quakey.h @@ -26,6 +26,8 @@ #include #endif +#include + typedef struct {} Quakey; // Function pointers to a simulated program's code @@ -82,6 +84,9 @@ void *quakey_node_state(QuakeyNode node); // Schedule and executes one program until it would block, then returns int quakey_schedule_one(Quakey *quakey); +// Get the current simulated time in nanoseconds +QuakeyUInt64 quakey_current_time(Quakey *quakey); + // Generate a random u64 QuakeyUInt64 quakey_random(void); @@ -93,6 +98,12 @@ typedef struct { void quakey_signal(char *name); int quakey_get_signal(Quakey *quakey, QuakeySignal *signal); +// Limit the number of hosts that can be crashed at the same time. +// Set to 0 for no limit (default). +void quakey_set_max_crashes(Quakey *quakey, int max_crashes); + +void quakey_network_partitioning(Quakey *quakey, bool enable); + // Access spawned host information int quakey_num_hosts(Quakey *quakey); void *quakey_host_state(Quakey *quakey, int idx); // Returns NULL if host is dead @@ -135,6 +146,7 @@ int mock_clock_gettime(clockid_t clockid, struct timespec *tp); int mock_open(char *path, int flags, int mode); int mock_fcntl(int fd, int cmd, int flags); int mock_close(int fd); +int mock_access(const char *path, int mode); int mock_ftruncate(int fd, size_t new_size); int mock_fstat(int fd, struct stat *buf); int mock_read(int fd, char *dst, int len); @@ -183,6 +195,7 @@ void mock_free(void *ptr); #define open mock_open #define fcntl mock_fcntl #define close mock_close +#define access mock_access #define ftruncate mock_ftruncate #define CreateFileW mock_CreateFileW #define CloseHandle mock_CloseHandle diff --git a/quakey/src/quakey.c b/quakey/src/quakey.c index c8e3720..fd8d0c0 100644 --- a/quakey/src/quakey.c +++ b/quakey/src/quakey.c @@ -11,6 +11,10 @@ #define TODO __builtin_trap() +#define SIM_TRACE(sim, fmt, ...) \ + fprintf(stderr, "SIM: [%.3fs] " fmt "\n", \ + (double)(sim)->current_time / 1e9, ##__VA_ARGS__) + #ifdef NDEBUG #define UNREACHABLE {} #define ASSERT(X) {} @@ -317,6 +321,7 @@ typedef enum { EVENT_TYPE_DATA, EVENT_TYPE_WAKEUP, EVENT_TYPE_RESTART, + EVENT_TYPE_PARTITION, } TimeEventType; typedef struct { @@ -355,6 +360,17 @@ typedef struct { #define SIM_SIGNAL_LIMIT 8 +typedef struct { + Host *a; + Host *b; +} HostPair; + +typedef struct { + int count; + int capacity; + HostPair *pairs; +} HostPairList; + struct Sim { uint64_t seed; @@ -378,15 +394,30 @@ struct Sim { int num_signals; int head_signal; QuakeySignal signals[SIM_SIGNAL_LIMIT]; + + // Network partition simulation. The partition list holds pairs + // of hosts whose link is currently broken. The target_partition + // holds the desired end state. A periodic timer event gradually + // breaks or repairs links to converge toward the target. Once + // reached, a new random target is generated. + HostPairList partition; + HostPairList target_partition; + + // Maximum number of hosts that can be dead at the same time. + int max_crashes; + + bool network_partitioning; }; static void time_event_wakeup(Sim *sim, Nanos time, Host *host); static void time_event_connect(Sim *sim, Nanos time, Desc *desc); static void time_event_disconnect(Sim *sim, Nanos time, Desc *desc, b32 rst); -static void time_event_send_data(Sim *sim, Nanos time, Desc *desc); +static void time_event_send_data(Sim *sim, Nanos time, Desc *desc, int count); static void time_event_free(TimeEvent *event); static void time_event_restart(Sim *sim, Nanos time, Host *host); +static void time_event_partition(Sim *sim, Nanos time); static void remove_events_targeting_desc(Sim *sim, Desc *desc); +static b32 remove_wakeup_event(Sim *sim, Host *host); ///////////////////////////////////////////////////////////////// ///////////////////////////////////////////////////////////////// @@ -714,11 +745,6 @@ static b32 socket_queue_empty(SocketQueue *queue) return queue->used == 0; } -static b32 socket_queue_used(SocketQueue *queue) -{ - return queue->used; -} - ///////////////////////////////////////////////////////////////// // Accept Queue Code @@ -1003,9 +1029,10 @@ static void host_init(Host *host, Sim *sim, QuakeySpawn config, char *arg) TODO; } - if (host->poll_timeout > 0) + if (host->poll_timeout > 0) { + remove_wakeup_event(host->sim, host); time_event_wakeup(host->sim, host->sim->current_time + (Nanos)host->poll_timeout * 1000000ULL, host); - else if (host->poll_timeout == 0) + } else if (host->poll_timeout == 0) host->timedout = true; // Immediate timeout, don't create event at current_time } @@ -1035,8 +1062,11 @@ static void host_free(Host *host) } // Remove all events associated with a host (WAKEUP events and events -// whose source or destination descriptors belong to this host) -static void remove_events_for_host(Sim *sim, Host *host) +// whose source or destination descriptors belong to this host). +// If skip_restart is true, RESTART events are kept (used during +// restart failure to avoid removing the event currently being +// processed by process_events_at_current_time). +static void remove_events_for_host_ex(Sim *sim, Host *host, bool skip_restart) { int i = 0; while (i < sim->num_events) { @@ -1045,7 +1075,7 @@ static void remove_events_for_host(Sim *sim, Host *host) if (event->type == EVENT_TYPE_WAKEUP && event->host == host) remove = true; - if (event->type == EVENT_TYPE_RESTART && event->host == host) + if (!skip_restart && event->type == EVENT_TYPE_RESTART && event->host == host) remove = true; if (event->src_desc && event->src_desc->host == host) remove = true; @@ -1061,6 +1091,11 @@ static void remove_events_for_host(Sim *sim, Host *host) } } +static void remove_events_for_host(Sim *sim, Host *host) +{ + remove_events_for_host_ex(sim, host, false); +} + static int count_dead(Sim *sim) { int n = 0; @@ -1088,6 +1123,11 @@ static void host_crash(Host *host) // Remove all pending events for this host remove_events_for_host(sim, host); + // Let the application clean up (e.g. log the crash) + host___ = host; + host->free_func(host->state); + host___ = NULL; + // Free application state free(host->state); host->state = NULL; @@ -1098,7 +1138,6 @@ static void host_crash(Host *host) host->poll_count = 0; host->poll_timeout = -1; - printf("Quakey: Host crash (%d/%d dead)\n", count_dead(sim), sim->num_hosts); } // Restart a crashed host: re-initialize from saved config, @@ -1163,17 +1202,37 @@ static void host_restart(Host *host) ); host___ = NULL; if (ret < 0) { - // If the node fails to restart, mark it as dead again + // Clean up any descriptors created during the failed init + for (int i = 0; i < HOST_DESC_LIMIT; i++) { + if (host->desc[i].type != DESC_EMPTY) + desc_free(sim, &host->desc[i], true); + } + host->num_desc = 0; + // Skip removing RESTART events: this function is called from + // time_event_process (EVENT_TYPE_RESTART), so the current + // restart event is still in the array being iterated by + // process_events_at_current_time. Removing it here would cause + // the outer loop's swap-removal to discard an unrelated event. + remove_events_for_host_ex(sim, host, true); + free(host->state); + host->state = NULL; host->dead = true; + + // Schedule another restart attempt. Init can fail due to + // transient I/O errors from fault injection; permanently + // killing the host would be unrealistic since a real + // process supervisor would keep retrying. + Nanos restart_delay = 1000000000ULL + (sim_random(sim) % 9000000000ULL); + time_event_restart(sim, sim->current_time + restart_delay, host); return; } - if (host->poll_timeout > 0) + if (host->poll_timeout > 0) { + remove_wakeup_event(sim, host); time_event_wakeup(sim, sim->current_time + (Nanos)host->poll_timeout * 1000000ULL, host); - else if (host->poll_timeout == 0) + } else if (host->poll_timeout == 0) host->timedout = true; - printf("Quakey: Host restart (%d/%d dead)\n", count_dead(sim), sim->num_hosts); } static b32 host_is_linux(Host *host) @@ -1343,12 +1402,16 @@ static void host_update(Host *host) ); host___ = NULL; if (ret < 0) { - TODO; + host_crash(host); + Nanos restart_delay = 1000000000ULL + (sim_random(host->sim) % 9000000000ULL); + time_event_restart(host->sim, host->sim->current_time + restart_delay, host); + return; } - if (host->poll_timeout > 0) + if (host->poll_timeout > 0) { + remove_wakeup_event(host->sim, host); time_event_wakeup(host->sim, host->sim->current_time + (Nanos)host->poll_timeout * 1000000ULL, host); - else if (host->poll_timeout == 0) + } else if (host->poll_timeout == 0) host->timedout = true; // Immediate timeout, don't create event at current_time } @@ -1445,9 +1508,15 @@ static int host_create_pipe(Host *host, int *desc_idxs) return HOST_ERROR_FULL; Desc *desc_1 = &host->desc[desc_idx_1]; + // Mark the first slot as in-use before searching for the second, + // otherwise find_empty_desc_struct returns the same index twice. + desc_1->type = DESC_PIPE; + int desc_idx_2 = find_empty_desc_struct(host); - if (desc_idx_2 < 0) + if (desc_idx_2 < 0) { + desc_1->type = DESC_EMPTY; return HOST_ERROR_FULL; + } Desc *desc_2 = &host->desc[desc_idx_2]; desc_1->type = DESC_PIPE; @@ -1894,7 +1963,7 @@ static int send_inner(Desc *desc, char *src, int len) uint64_t rng = sim_random(sim); latency = 1000000 + (rng % 99000000); // between 1ms and 100ms #endif - time_event_send_data(desc->host->sim, desc->host->sim->current_time + latency, desc); + time_event_send_data(desc->host->sim, desc->host->sim->current_time + latency, desc, ret); return ret; } @@ -1916,7 +1985,7 @@ static int host_read(Host *host, int desc_idx, char *dst, int len) desc->type == DESC_PIPE) { num = recv_inner(desc, dst, len); } else if (desc->type == DESC_FILE) { -#ifdef FAULT_INJECTION +#if defined(FAULT_INJECTION) && !defined(DISABLE_SPURIOUS_IO_ERRORS) uint64_t roll = sim_random(host->sim) % 1000; if (roll == 0) return HOST_ERROR_IO; #endif @@ -1960,7 +2029,7 @@ static int host_write(Host *host, int desc_idx, char *src, int len) desc->type == DESC_PIPE) { num = send_inner(desc, src, len); } else if (desc->type == DESC_FILE) { -#ifdef FAULT_INJECTION +#if defined(FAULT_INJECTION) && !defined(DISABLE_SPURIOUS_IO_ERRORS) uint64_t roll = sim_random(host->sim) % 1000; if (roll == 0) return HOST_ERROR_IO; if (roll == 1) return HOST_ERROR_NOSPC; @@ -2000,9 +2069,11 @@ static int host_recv(Host *host, int desc_idx, char *dst, int len) Desc *desc = &host->desc[desc_idx]; #ifdef FAULT_INJECTION - Sim *sim = desc->host->sim; - uint64_t rng = sim_random(sim); - len = 1 + (rng % len); + if (len > 0) { + Sim *sim = desc->host->sim; + uint64_t rng = sim_random(sim); + len = 1 + (rng % len); + } #endif int num = 0; @@ -2024,9 +2095,11 @@ static int host_send(Host *host, int desc_idx, char *src, int len) Desc *desc = &host->desc[desc_idx]; #ifdef FAULT_INJECTION - Sim *sim = desc->host->sim; - uint64_t rng = sim_random(sim); - len = 1 + (rng % len); + if (len > 0) { + Sim *sim = desc->host->sim; + uint64_t rng = sim_random(sim); + len = 1 + (rng % len); + } #endif int num = 0; @@ -2132,7 +2205,7 @@ static int host_fsync(Host *host, int desc_idx) if (desc->type != DESC_FILE) return HOST_ERROR_BADIDX; -#ifdef FAULT_INJECTION +#if defined(FAULT_INJECTION) && !defined(DISABLE_SPURIOUS_IO_ERRORS) uint64_t roll = sim_random(host->sim) % 100; if (roll == 0) return HOST_ERROR_IO; @@ -2251,6 +2324,19 @@ static b32 remove_connect_event(Sim *sim, Desc *desc) return true; } +static b32 remove_wakeup_event(Sim *sim, Host *host) +{ + int i = 0; + while (i < sim->num_events && (sim->events[i].type != EVENT_TYPE_WAKEUP || sim->events[i].host != host)) + i++; + + if (i == sim->num_events) + return false; + + sim->events[i] = sim->events[--sim->num_events]; + return true; +} + // Remove all events that target a specific descriptor (DISCONNECT and DATA events) static void remove_events_targeting_desc(Sim *sim, Desc *desc) { @@ -2292,7 +2378,7 @@ static void time_event_disconnect(Sim *sim, Nanos time, Desc *desc, b32 rst) append_event(sim, event); } -static void time_event_send_data(Sim *sim, Nanos time, Desc *desc) +static void time_event_send_data(Sim *sim, Nanos time, Desc *desc, int count) { TimeEvent event = { .type = EVENT_TYPE_DATA, @@ -2300,7 +2386,7 @@ static void time_event_send_data(Sim *sim, Nanos time, Desc *desc) .host = NULL, .src_desc = NULL, .dst_desc = desc->peer, - .data_count = socket_queue_used(desc->output), + .data_count = count, .data_queue = socket_queue_ref(desc->output), .rst = false, }; @@ -2328,12 +2414,52 @@ static void time_event_restart(Sim *sim, Nanos time, Host *host) append_event(sim, event); } -static int sim_find_host(Sim *sim, Addr addr); +static void time_event_partition(Sim *sim, Nanos time) +{ + TimeEvent event = { + .type = EVENT_TYPE_PARTITION, + .time = time, + }; + append_event(sim, event); +} + +static int sim_find_host(Sim *sim, Addr addr); +static int change_target_partition(Sim *sim); +static bool break_or_repair_link(Sim *sim); +static bool hosts_are_partitioned(Sim *sim, Host *a, Host *b); + +static Nanos pick_partition_delay(Sim *sim, bool longer) +{ + Nanos min_delay = 1000000000; // 1s + Nanos max_delay = 10000000000; // 10s + if (longer) { + min_delay = 10000000000; + max_delay = 20000000000; + } + return min_delay + sim_random(sim) % (max_delay - min_delay); +} static b32 time_event_process(TimeEvent *event, Sim *sim) { b32 consumed = true; switch (event->type) { + case EVENT_TYPE_PARTITION: + { + // Try to move one step toward the target partition. + // If current already matches target, pick a new target. + if (!break_or_repair_link(sim)) { + if (sim->network_partitioning) { + if (change_target_partition(sim) < 0) { + TODO; + } + } + } + + // Reschedule for the next partition step + event->time = sim->current_time + pick_partition_delay(sim, true); + consumed = false; + } + break; case EVENT_TYPE_CONNECT: { Desc *src_desc = event->src_desc; @@ -2346,6 +2472,13 @@ static b32 time_event_process(TimeEvent *event, Sim *sim) } Host *peer_host = sim->hosts[idx]; + if (hosts_are_partitioned(sim, src_desc->host, peer_host)) { + //SIM_TRACE(sim, "PARTITION: blocked connection %s -> %s", + // src_desc->host->name, peer_host->name); + src_desc->connect_status = CONNECT_STATUS_NOHOST; + break; + } + Desc *peer = host_find_desc_bound_to(peer_host, src_desc->connect_addr, src_desc->connect_port); if (peer == NULL) { @@ -2410,6 +2543,242 @@ static b32 time_event_process(TimeEvent *event, Sim *sim) ///////////////////////////////////////////////////////////////// // Sim Code +static void +host_pair_list_init(HostPairList *list) +{ + list->count = 0; + list->capacity = 0; + list->pairs = NULL; +} + +static void +host_pair_list_free(HostPairList *list) +{ + free(list->pairs); +} + +static bool +host_pair_list_exists(HostPairList *list, Host *a, Host *b) +{ + for (int i = 0; i < list->count; i++) + if ((list->pairs[i].a == a && list->pairs[i].b == b) || + (list->pairs[i].a == b && list->pairs[i].b == a)) + return true; + return false; +} + +static int +host_pair_list_add(HostPairList *list, Host *a, Host *b) +{ + if (!host_pair_list_exists(list, a, b)) { + if (list->count == list->capacity) { + int n = 2 * list->count; + if (n < 8) n = 8; + void *p = realloc(list->pairs, n * sizeof(HostPair)); + if (p == NULL) + return -1; + list->capacity = n; + list->pairs = p; + } + list->pairs[list->count++] = (HostPair) { a, b }; + } + return 0; +} + +static void +host_pair_list_remove_at(HostPairList *list, int idx) +{ + list->pairs[idx] = list->pairs[--list->count]; +} + +// Generate a new random target partition by assigning hosts to +// random buckets. Hosts in the same bucket can communicate; hosts +// in different buckets have their link marked as broken. +static int change_target_partition(Sim *sim) +{ + HostPairList list; + host_pair_list_init(&list); + + #define MAX_BUCKETS 3 + #define MAX_NODES_PER_BUCKET 8 + + int num_buckets = 1 + sim_random(sim) % MAX_BUCKETS; + + Host *buckets[MAX_BUCKETS][MAX_NODES_PER_BUCKET]; + int bucket_sizes[MAX_BUCKETS]; + + for (int i = 0; i < num_buckets; i++) + bucket_sizes[i] = 0; + + // Randomly assign each host to a bucket + for (int i = 0; i < sim->num_hosts; i++) { + int bucket_index = sim_random(sim) % num_buckets; + buckets[bucket_index][bucket_sizes[bucket_index]++] = sim->hosts[i]; + } + + // Every cross-bucket pair is a broken link in the target + for (int i = 0; i < num_buckets; i++) { + for (int j = 0; j < bucket_sizes[i]; j++) { + for (int k = 0; k < num_buckets; k++) { + if (k == i) continue; + for (int g = 0; g < bucket_sizes[k]; g++) { + Host *a = buckets[i][j]; + Host *b = buckets[k][g]; + if (host_pair_list_add(&list, a, b) < 0) { + host_pair_list_free(&list); + return -1; + } + } + } + } + } + + host_pair_list_free(&sim->target_partition); + sim->target_partition = list; + //SIM_TRACE(sim, "PARTITION: new target partition with %d broken links (%d buckets)", + // list.count, num_buckets); + return 0; +} + +// Pick a random pair that exists in 'left' but not in 'right'. +// Returns the index into 'left', or -1 if no such pair exists. +static int pick_random_from_left_not_in_right(Sim *sim, + HostPairList *left, HostPairList *right) +{ + int *arr = malloc(left->count * sizeof(int)); + if (arr == NULL) { + TODO; // Allowing this to return error would make execution not deterministic + } + int num = 0; + + for (int i = 0; i < left->count; i++) { + HostPair pair = left->pairs[i]; + if (!host_pair_list_exists(right, pair.a, pair.b)) { + arr[num++] = i; + } + } + + int idx; + if (num == 0) { + idx = -1; + } else { + idx = arr[sim_random(sim) % num]; + } + + free(arr); + return idx; +} + +// Forcefully reset a connection socket and notify its peer. +// Removes any pending time events that reference either end. +static void reset_conn(Sim *sim, Desc *desc) +{ + assert(desc->type == DESC_SOCKET_C); + + if (desc->connect_status == CONNECT_STATUS_WAIT || + desc->connect_status == CONNECT_STATUS_DONE) { + + remove_events_targeting_desc(sim, desc); + + if (desc->peer) { + assert(desc->peer->type == DESC_SOCKET_C + || desc->peer->type == DESC_SOCKET_L); + + if (desc->peer->type == DESC_SOCKET_C) { + remove_events_targeting_desc(sim, desc->peer); + desc->peer->connect_status = CONNECT_STATUS_RESET; + desc->peer->peer = NULL; + } else { + accept_queue_remove(&desc->peer->accept_queue, desc); + } + desc->peer = NULL; + } + + desc->connect_status = CONNECT_STATUS_RESET; + } +} + +// Reset all active connections between two hosts (both directions) +static void drop_conns_between_hosts(Sim *sim, Host *host, Host *peer) +{ + for (int i = 0, j = 0; j < host->num_desc; i++) { + + Desc *desc = &host->desc[i]; + if (desc->type == DESC_EMPTY) + continue; + j++; + + if (desc->type == DESC_SOCKET_C && desc->peer && desc->peer->host == peer) + reset_conn(sim, desc); + } + + for (int i = 0, j = 0; j < peer->num_desc; i++) { + + Desc *desc = &peer->desc[i]; + if (desc->type == DESC_EMPTY) + continue; + j++; + + if (desc->type == DESC_SOCKET_C && desc->peer && desc->peer->host == host) + reset_conn(sim, desc); + } +} + +// Break a link that is in the target but not yet in current +static bool break_link(Sim *sim) +{ + int idx = pick_random_from_left_not_in_right(sim, + &sim->target_partition, &sim->partition); + if (idx < 0) + return false; + HostPair pair = sim->target_partition.pairs[idx]; + + host_pair_list_add(&sim->partition, pair.a, pair.b); + drop_conns_between_hosts(sim, pair.a, pair.b); + //SIM_TRACE(sim, "PARTITION: break link %s <-> %s (%d broken links)", + // pair.a->name, pair.b->name, sim->partition.count); + return true; +} + +// Repair a link that is broken in current but not in the target +static bool repair_link(Sim *sim) +{ + int idx = pick_random_from_left_not_in_right(sim, + &sim->partition, &sim->target_partition); + if (idx < 0) + return false; + + //HostPair pair = sim->partition.pairs[idx]; + host_pair_list_remove_at(&sim->partition, idx); + //SIM_TRACE(sim, "PARTITION: repair link %s <-> %s (%d broken links)", + // pair.a->name, pair.b->name, sim->partition.count); + return true; +} + +// Try to move one step toward the target: randomly attempt a +// break or repair first, falling back to the other on failure. +// Returns false when current already matches the target. +static bool break_or_repair_link(Sim *sim) +{ + if (sim_random(sim) & 1) { + if (break_link(sim)) + return true; + if (repair_link(sim)) + return true; + } else { + if (repair_link(sim)) + return true; + if (break_link(sim)) + return true; + } + return false; +} + +static bool hosts_are_partitioned(Sim *sim, Host *a, Host *b) +{ + return host_pair_list_exists(&sim->partition, a, b); +} + static void sim_init(Sim *sim, uint64_t seed) { sim->seed = seed; @@ -2422,10 +2791,27 @@ static void sim_init(Sim *sim, uint64_t seed) sim->events = NULL; sim->num_signals = 0; sim->head_signal = 0; + sim->max_crashes = 0; + sim->network_partitioning = true; + host_pair_list_init(&sim->partition); + host_pair_list_init(&sim->target_partition); + time_event_partition(sim, pick_partition_delay(sim, false)); +} + +static void sim_network_partitioning(Sim *sim, bool enable) +{ + sim->network_partitioning = enable; + if (!enable) { + host_pair_list_free(&sim->target_partition); + host_pair_list_init(&sim->target_partition); + } } static void sim_free(Sim *sim) { + host_pair_list_free(&sim->target_partition); + host_pair_list_free(&sim->partition); + for (int i = 0; i < sim->num_hosts; i++) host_free(sim->hosts[i]); free(sim->hosts); @@ -2503,6 +2889,9 @@ static void process_events_at_current_time(Sim *sim) } } } + + //if (sim->num_events > 10000) + // SIM_TRACE(sim, "WARNING: event queue large: %d events", sim->num_events); } static int find_first_ready_host(Sim *sim) @@ -2565,14 +2954,14 @@ static b32 sim_update(Sim *sim) if (sim->num_hosts > 1) { uint64_t rng = sim_random(sim); if ((rng % 10000) == 0) { - // Pick a random live host to crash + int live_count = 0; for (int i = 0; i < sim->num_hosts; i++) if (!sim->hosts[i]->dead) live_count++; + int dead_count = sim->num_hosts - live_count; - // Only crash if at least 2 hosts are alive (keep a majority) - if (live_count >= 2) { + if (dead_count < sim->max_crashes) { // Pick one of the live hosts at random int target = sim_random(sim) % live_count; int j = 0; @@ -2664,6 +3053,18 @@ void quakey_free(Quakey *quakey) } } +void quakey_set_max_crashes(Quakey *quakey, int max_crashes) +{ + Sim *sim = (Sim*) quakey; + sim->max_crashes = max_crashes; +} + +void quakey_network_partitioning(Quakey *quakey, bool enable) +{ + Sim *sim = (Sim*) quakey; + sim_network_partitioning(sim, enable); +} + QuakeyNode quakey_spawn(Quakey *quakey, QuakeySpawn config, char *arg) { return (QuakeyNode) sim_spawn((Sim*) quakey, config, arg); @@ -2680,6 +3081,12 @@ int quakey_schedule_one(Quakey *quakey) return sim_update((Sim*) quakey); } +QuakeyUInt64 quakey_current_time(Quakey *quakey) +{ + Sim *sim = (Sim*) quakey; + return sim->current_time; +} + QuakeyUInt64 quakey_random(void) { Host *host = host___; @@ -2823,6 +3230,11 @@ int mock_close(int fd) return 0; } +int mock_access(const char *path, int mode) +{ + assert(0); // TODO +} + static int convert_addr(void *addr, size_t addr_len, Addr *converted_addr, uint16_t *converted_port) { diff --git a/raft/client.c b/raft/client.c index 92211a1..c4cc9f1 100644 --- a/raft/client.c +++ b/raft/client.c @@ -9,13 +9,64 @@ #include "node.h" #include "client.h" -#define CLIENT_TRACE(fmt, ...) {} -//#define CLIENT_TRACE(fmt, ...) fprintf(stderr, "CLIENT: " fmt "\n", ##__VA_ARGS__); +//#define CLIENT_TRACE(fmt, ...) {} +#define CLIENT_TRACE(fmt, ...) fprintf(stderr, "CLIENT: " fmt "\n", ##__VA_ARGS__); #define CLIENT_REQUEST_TIMEOUT_SEC 3 +#define KEY_POOL_SIZE 128 static uint64_t next_client_id = 1; +static uint64_t client_random(void) +{ +#if defined(MAIN_SIMULATION) || defined(MAIN_TEST) + return quakey_random(); +#else + return (uint64_t)rand(); +#endif +} + +static KVStoreOper random_oper(void) +{ + KVStoreOper oper = {0}; + snprintf(oper.key, KVSTORE_KEY_SIZE, "k%d", (int)(client_random() % KEY_POOL_SIZE)); + + switch (client_random() % 3) { + case 0: + oper.type = KVSTORE_OPER_SET; + oper.val = client_random(); + break; + case 1: + oper.type = KVSTORE_OPER_GET; + break; + case 2: + oper.type = KVSTORE_OPER_DEL; + break; + } + return oper; +} + +static const char *oper_type_name(KVStoreOperType t) +{ + switch (t) { + case KVSTORE_OPER_NOOP: return "NOOP"; + case KVSTORE_OPER_SET: return "SET"; + case KVSTORE_OPER_GET: return "GET"; + case KVSTORE_OPER_DEL: return "DEL"; + } + return "???"; +} + +static const char *result_type_name(KVStoreResultType t) +{ + switch (t) { + case KVSTORE_RESULT_OK: return "OK"; + case KVSTORE_RESULT_FULL: return "FULL"; + case KVSTORE_RESULT_MISSING: return "MISSING"; + } + return "???"; +} + static int process_message(ClientState *state, int conn_idx, uint8_t type, ByteView msg) @@ -31,7 +82,12 @@ process_message(ClientState *state, if (redirect_message.leader_idx >= 0 && redirect_message.leader_idx < state->num_servers) { CLIENT_TRACE("Redirected to leader %d", redirect_message.leader_idx); state->current_leader = redirect_message.leader_idx; - // Retry immediately with the correct leader + // Retry immediately with the correct leader. + // A redirect means the server did not process the request, + // so mark as rejected (not timeout) for the linearizability + // checker: the outcome is unambiguous (no effect). + state->last_was_rejected = true; + state->last_was_timeout = false; state->pending = false; } return 0; @@ -48,8 +104,24 @@ process_message(ClientState *state, return -1; memcpy(&reply_message, msg.ptr, sizeof(reply_message)); - CLIENT_TRACE("Received reply for request %lu", (unsigned long)state->request_id); + // Ignore stale replies from previous requests. After a timeout + // the client moves to a new leader and sends a new request, but + // the old leader may still deliver a reply for the old request + // on the previous connection. Without this check the client + // would accept the stale result for the wrong operation. + if (reply_message.request_id != state->request_id) + return 0; + CLIENT_TRACE("REPLY: %s key=\"%.16s\" -> %s val=%lu (req_id=%lu)", + oper_type_name(state->last_oper.type), + state->last_oper.key, + result_type_name(reply_message.result.type), + (unsigned long)reply_message.result.val, + (unsigned long)state->request_id); + + state->last_result = reply_message.result; + state->last_was_timeout = false; + state->last_was_rejected = false; state->pending = false; return 0; } @@ -167,6 +239,8 @@ int client_tick(void *state_, void **ctxs, if (now >= request_deadline) { CLIENT_TRACE("Request %lu timed out, trying next server", (unsigned long)state->request_id); + state->last_was_timeout = true; + state->last_was_rejected = false; state->pending = false; state->current_leader = (state->current_leader + 1) % state->num_servers; } @@ -181,6 +255,7 @@ int client_tick(void *state_, void **ctxs, tcp_connect(&state->tcp, state->server_addrs[leader], leader, NULL); } else { state->request_id++; + state->last_oper = random_oper(); RequestMessage request_message = { .base = { @@ -188,11 +263,18 @@ int client_tick(void *state_, void **ctxs, .type = MESSAGE_TYPE_REQUEST, .length = sizeof(RequestMessage), }, - .oper = OPERATION_A, + .oper = state->last_oper, .client_id = state->client_id, .request_id = state->request_id, }; + CLIENT_TRACE("REQUEST: %s key=\"%.16s\" val=%lu (req_id=%lu, leader=%d)", + oper_type_name(state->last_oper.type), + state->last_oper.key, + (unsigned long)state->last_oper.val, + (unsigned long)state->request_id, + leader); + ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); if (output) byte_queue_write(output, &request_message, sizeof(request_message)); diff --git a/raft/client.h b/raft/client.h index 9f049b8..70981ba 100644 --- a/raft/client.h +++ b/raft/client.h @@ -4,6 +4,8 @@ #include #include +#include + #include "config.h" typedef struct { @@ -13,6 +15,14 @@ typedef struct { // True if we are waiting for a response bool pending; + // The operation sent in the current pending request (for logging) + KVStoreOper last_oper; + + // Linearizability checker support + KVStoreResult last_result; + bool last_was_timeout; + bool last_was_rejected; + Address server_addrs[NODE_LIMIT]; int num_servers; diff --git a/raft/client_table.c b/raft/client_table.c new file mode 100644 index 0000000..7248cbe --- /dev/null +++ b/raft/client_table.c @@ -0,0 +1,45 @@ +#if defined(MAIN_SIMULATION) || defined(MAIN_TEST) +#define QUAKEY_ENABLE_MOCKS +#endif + +#include + +#include "client_table.h" + +void client_table_init(ClientTable *ct) +{ + ct->count = 0; + ct->capacity = 0; + ct->entries = NULL; +} + +void client_table_free(ClientTable *ct) +{ + free(ct->entries); +} + +ClientTableEntry *client_table_find(ClientTable *ct, uint64_t client_id) +{ + for (int i = 0; i < ct->count; i++) + if (ct->entries[i].client_id == client_id) + return &ct->entries[i]; + return NULL; +} + +int client_table_add(ClientTable *ct, uint64_t client_id, uint64_t request_id, int conn_tag) +{ + if (ct->count == ct->capacity) { + int n = ct->capacity ? 2 * ct->capacity : 8; + void *p = realloc(ct->entries, n * sizeof(ClientTableEntry)); + if (p == NULL) return -1; + ct->capacity = n; + ct->entries = p; + } + ct->entries[ct->count++] = (ClientTableEntry) { + .client_id = client_id, + .last_request_id = request_id, + .pending = true, + .conn_tag = conn_tag, + }; + return 0; +} diff --git a/raft/client_table.h b/raft/client_table.h new file mode 100644 index 0000000..ee002be --- /dev/null +++ b/raft/client_table.h @@ -0,0 +1,28 @@ +#ifndef CLIENT_TABLE_INCLUDED +#define CLIENT_TABLE_INCLUDED + +#include +#include + +#include + +typedef struct { + uint64_t client_id; + uint64_t last_request_id; + KVStoreResult last_result; + bool pending; + int conn_tag; +} ClientTableEntry; + +typedef struct { + int count; + int capacity; + ClientTableEntry *entries; +} ClientTable; + +void client_table_init(ClientTable *ct); +void client_table_free(ClientTable *ct); +ClientTableEntry *client_table_find(ClientTable *ct, uint64_t client_id); +int client_table_add(ClientTable *ct, uint64_t client_id, uint64_t request_id, int conn_tag); + +#endif // CLIENT_TABLE_INCLUDED \ No newline at end of file diff --git a/raft/invariant_checker.c b/raft/invariant_checker.c new file mode 100644 index 0000000..ff1295c --- /dev/null +++ b/raft/invariant_checker.c @@ -0,0 +1,351 @@ +// Raft invariant checker with external shadow log tracking. +// +// This file runs in the main simulation loop outside Quakey-scheduled +// processes. It includes node.h for struct definitions, then restores +// real allocators since mock_malloc/realloc/free abort outside process +// context. + +#include "invariant_checker.h" + +#include +#include + +// Restore real allocators (see checker/linearizability.c for precedent). +// The header chain (invariant_checker.h -> node.h -> wal.h -> +// lib/file_system.h) defines QUAKEY_ENABLE_MOCKS and replaces +// malloc/realloc/free with mock versions. We need the real ones +// because this code runs outside any Quakey-scheduled process. +#undef malloc +#undef realloc +#undef free +#include +#include + +static int self_idx(NodeState *state) +{ + for (int i = 0; i < state->num_nodes; i++) + if (addr_eql(state->node_addrs[i], state->self_addr)) + return i; + UNREACHABLE; +} + +static int shadow_log_append(InvariantChecker *ic, KVStoreOper oper) +{ + if (ic->shadow_count == ic->shadow_capacity) { + int n = 2 * ic->shadow_capacity; + if (n < 8) + n = 8; + KVStoreOper *p = realloc(ic->shadow_log, n * sizeof(KVStoreOper)); + if (p == NULL) + return -1; + ic->shadow_log = p; + ic->shadow_capacity = n; + } + ic->shadow_log[ic->shadow_count++] = oper; + return 0; +} + +void invariant_checker_init(InvariantChecker *ic) +{ + ic->shadow_log = NULL; + ic->shadow_count = 0; + ic->shadow_capacity = 0; +} + +void invariant_checker_free(InvariantChecker *ic) +{ + fprintf(stderr, "INVARIANT CHECKER: shadow log tracked %d committed entries\n", + ic->shadow_count); + free(ic->shadow_log); +} + +void invariant_checker_run(InvariantChecker *ic, NodeState **nodes, int num_nodes) +{ + for (int i = 0; i < num_nodes; i++) { + NodeState *s = nodes[i]; + if (s == NULL) + continue; + + int log_count = wal_entry_count(&s->wal); + + // The commit index starts at -1 (nothing committed) and only + // increases. It must never go below -1. + if (s->commit_index < -1) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: commit_index (%d) < -1\n", + i, s->commit_index); + __builtin_trap(); + } + + // A node cannot have committed an entry beyond what exists + // in its log. With an empty log (count=0), commit_index + // must be -1. + if (s->commit_index >= log_count) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: commit_index (%d) >= log_count (%d)\n", + i, s->commit_index, log_count); + __builtin_trap(); + } + + // Entries are applied to the state machine in order, up to + // the commit index. The last applied index must never exceed + // the commit index. + if (s->last_applied > s->commit_index) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: last_applied (%d) > commit_index (%d)\n", + i, s->last_applied, s->commit_index); + __builtin_trap(); + } + + if (s->last_applied < -1) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: last_applied (%d) < -1\n", + i, s->last_applied); + __builtin_trap(); + } + + // voted_for is either -1 (no vote) or a valid node index. + if (s->term_and_vote.voted_for != -1 && (s->term_and_vote.voted_for < 0 || s->term_and_vote.voted_for >= s->num_nodes)) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: voted_for (%d) is not -1 " + "and not in [0, %d)\n", + i, s->term_and_vote.voted_for, s->num_nodes); + __builtin_trap(); + } + + // Leaders append entries with their current term, and terms + // only increase. Truncation preserves this property because + // replacement entries come from a leader whose log already + // satisfies non-decreasing terms. + for (int k = 1; k < log_count; k++) { + if (wal_peek_entry(&s->wal, k)->term < wal_peek_entry(&s->wal, k-1)->term) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: wal[%d].term (%lu) " + "< wal[%d].term (%lu) (non-monotonic)\n", + i, k, (unsigned long)wal_peek_entry(&s->wal, k)->term, + k-1, (unsigned long)wal_peek_entry(&s->wal, k-1)->term); + __builtin_trap(); + } + } + + // A leader must have voted for itself in the current term. + // A node becomes leader by winning an election, which requires + // voting for itself. The voted_for value is only reset when + // stepping down (which changes the role to FOLLOWER). + if (s->role == ROLE_LEADER) { + if (s->term_and_vote.voted_for != self_idx(s)) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: role is LEADER but " + "voted_for (%d) != self_idx (%d)\n", + i, s->term_and_vote.voted_for, self_idx(s)); + __builtin_trap(); + } + } + + // A candidate must have voted for itself in the current term. + // A node enters candidate state only through start_election(), + // which increments the term and sets voted_for to self_idx. + if (s->role == ROLE_CANDIDATE) { + if (s->term_and_vote.voted_for != self_idx(s)) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: role is CANDIDATE but " + "voted_for (%d) != self_idx (%d)\n", + i, s->term_and_vote.voted_for, self_idx(s)); + __builtin_trap(); + } + } + + // For a leader, match_indices[self] must equal the last log + // index. The leader always has its own entries matched. + if (s->role == ROLE_LEADER) { + int expected_match = log_count - 1; + if (s->match_indices[self_idx(s)] != expected_match) { + fprintf(stderr, "INVARIANT VIOLATED: node %d (LEADER): " + "match_indices[self] (%d) != last log index (%d)\n", + i, s->match_indices[self_idx(s)], expected_match); + __builtin_trap(); + } + } + + // For a leader, next_indices[k] must be >= match_indices[k] + 1 + // for all followers (k != self). The next index to send is + // always at least one past the highest known replicated index. + // The leader's own next_indices[self] is not maintained since + // the leader never sends entries to itself. + if (s->role == ROLE_LEADER) { + int si = self_idx(s); + for (int k = 0; k < s->num_nodes; k++) { + if (k == si) + continue; + if (s->next_indices[k] < s->match_indices[k] + 1) { + fprintf(stderr, "INVARIANT VIOLATED: node %d (LEADER): " + "next_indices[%d] (%d) < match_indices[%d] + 1 (%d)\n", + i, k, s->next_indices[k], k, s->match_indices[k] + 1); + __builtin_trap(); + } + } + } + } + + // Election Safety: at most one leader per term. + // Each term has at most one leader because a candidate needs + // a majority of votes, and each node votes at most once per term. + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL || nodes[i]->role != ROLE_LEADER) + continue; + for (int j = i + 1; j < num_nodes; j++) { + if (nodes[j] == NULL || nodes[j]->role != ROLE_LEADER) + continue; + if (nodes[i]->term_and_vote.term == nodes[j]->term_and_vote.term) { + fprintf(stderr, "INVARIANT VIOLATED: two leaders in term %lu: " + "node %d and node %d\n", + (unsigned long)nodes[i]->term_and_vote.term, i, j); + __builtin_trap(); + } + } + } + + // State Machine Safety (committed prefix agreement). + // For any two nodes, their logs must agree on all entries up to + // min(commit_index_i, commit_index_j). This is the core safety + // property: all committed operations are identical across replicas. + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) + continue; + for (int j = i + 1; j < num_nodes; j++) { + if (nodes[j] == NULL) + continue; + + int min_commit = nodes[i]->commit_index; + if (nodes[j]->commit_index < min_commit) + min_commit = nodes[j]->commit_index; + + for (int k = 0; k <= min_commit; k++) { + WALEntry *ei = wal_peek_entry(&nodes[i]->wal, k); + WALEntry *ej = wal_peek_entry(&nodes[j]->wal, k); + + if (memcmp(&ei->oper, &ej->oper, sizeof(KVStoreOper)) != 0) { + fprintf(stderr, "INVARIANT VIOLATED: committed log operation " + "mismatch at index %d between node %d and node %d\n", + k, i, j); + __builtin_trap(); + } + + if (ei->term != ej->term) { + fprintf(stderr, "INVARIANT VIOLATED: committed log term " + "mismatch at index %d between node %d (term %lu) " + "and node %d (term %lu)\n", + k, i, (unsigned long)ei->term, + j, (unsigned long)ej->term); + __builtin_trap(); + } + } + } + } + + //////////////////////////////////////////////////////////////////// + // Shadow log: external commit tracking + //////////////////////////////////////////////////////////////////// + + // Phase 1: Find the observed max commit index and a source node. + // + // In Raft, commit_index == -1 means nothing committed, 0 means the + // first entry is committed, etc. We track the number of committed + // entries as (commit_index + 1) so it aligns with shadow_count. + int observed_committed = 0; // number of committed entries observed + int source_node_idx = -1; + + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) + continue; + int node_committed = nodes[i]->commit_index + 1; + if (node_committed > observed_committed) { + observed_committed = node_committed; + source_node_idx = i; + } + } + + // Phase 2: Append newly committed entries to the shadow log. + if (source_node_idx >= 0 && observed_committed > ic->shadow_count) { + + NodeState *source = nodes[source_node_idx]; + assert(wal_entry_count(&source->wal) >= observed_committed); + + for (int k = ic->shadow_count; k < observed_committed; k++) { + + KVStoreOper *source_oper = &wal_peek_entry(&source->wal, k)->oper; + + // Cross-validate against other live nodes that have also + // committed this entry. + for (int j = 0; j < num_nodes; j++) { + if (j == source_node_idx) + continue; + if (nodes[j] == NULL) + continue; + if (nodes[j]->commit_index < k) + continue; + if (wal_entry_count(&nodes[j]->wal) <= k) + continue; + + if (memcmp(&wal_peek_entry(&nodes[j]->wal, k)->oper, source_oper, sizeof(KVStoreOper)) != 0) { + fprintf(stderr, "INVARIANT VIOLATED: committed entry mismatch at index %d " + "between source node %d and node %d during shadow log append\n", + k, source_node_idx, j); + __builtin_trap(); + } + } + + if (shadow_log_append(ic, *source_oper) < 0) { + fprintf(stderr, "INVARIANT CHECKER: shadow log allocation failed\n"); + __builtin_trap(); + } + } + } + + // Phase 3: Verify shadow log against the cluster. + + // Sub-check A: Committed entries must match the shadow log. + for (int k = 0; k < ic->shadow_count; k++) { + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) + continue; + if (wal_entry_count(&nodes[i]->wal) <= k) + continue; + if (nodes[i]->commit_index < k) + continue; + + if (memcmp(&wal_peek_entry(&nodes[i]->wal, k)->oper, &ic->shadow_log[k], sizeof(KVStoreOper)) != 0) { + char shadow_buf[128], node_buf[128]; + kvstore_snprint_oper(shadow_buf, sizeof(shadow_buf), ic->shadow_log[k]); + kvstore_snprint_oper(node_buf, sizeof(node_buf), wal_peek_entry(&nodes[i]->wal, k)->oper); + fprintf(stderr, "INVARIANT VIOLATED: shadow log mismatch at index %d on node %d\n" + " shadow: %s\n" + " node: %s\n", + k, i, shadow_buf, node_buf); + __builtin_trap(); + } + } + } + + // Sub-check B: When commit regresses, previously committed entries + // must still be held by a majority of the cluster. + if (observed_committed < ic->shadow_count) { + for (int k = observed_committed; k < ic->shadow_count; k++) { + int holders = 0; + int num_dead = 0; + + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) { + num_dead++; + continue; + } + if (wal_entry_count(&nodes[i]->wal) <= k) + continue; + if (memcmp(&wal_peek_entry(&nodes[i]->wal, k)->oper, &ic->shadow_log[k], sizeof(KVStoreOper)) == 0) + holders++; + } + + if (holders + num_dead <= num_nodes / 2) { + char oper_buf[128]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), ic->shadow_log[k]); + fprintf(stderr, "INVARIANT VIOLATED: previously committed entry at index %d " + "no longer held by majority (holders=%d, dead=%d, total=%d)\n" + " entry: %s\n", + k, holders, num_dead, num_nodes, oper_buf); + __builtin_trap(); + } + } + } +} diff --git a/raft/invariant_checker.h b/raft/invariant_checker.h new file mode 100644 index 0000000..2f430e9 --- /dev/null +++ b/raft/invariant_checker.h @@ -0,0 +1,17 @@ +#ifndef INVARIANT_CHECKER_INCLUDED +#define INVARIANT_CHECKER_INCLUDED + +#include "node.h" + +typedef struct { + // External shadow log of committed operations (unbounded, dynamically allocated) + KVStoreOper *shadow_log; + int shadow_count; + int shadow_capacity; +} InvariantChecker; + +void invariant_checker_init(InvariantChecker *ic); +void invariant_checker_free(InvariantChecker *ic); +void invariant_checker_run(InvariantChecker *ic, NodeState **nodes, int num_nodes); + +#endif // INVARIANT_CHECKER_INCLUDED \ No newline at end of file diff --git a/raft/main.c b/raft/main.c index 5a8bf64..1d04e56 100644 --- a/raft/main.c +++ b/raft/main.c @@ -8,6 +8,7 @@ #include "node.h" #include "client.h" +#include "invariant_checker.h" static volatile int simulation_running = 1; @@ -17,15 +18,32 @@ static void sigint_handler(int sig) simulation_running = 0; } -int main(void) +int main(int argc, char **argv) { signal(SIGINT, sigint_handler); + QuakeyUInt64 seed = 2; + QuakeyUInt64 time_limit_ns = 0; // 0 means no limit + + for (int i = 1; i < argc; i++) { + if (strcmp(argv[i], "--seed") == 0 && i + 1 < argc) { + seed = strtoull(argv[++i], NULL, 10); + } else if (strcmp(argv[i], "--time") == 0 && i + 1 < argc) { + time_limit_ns = strtoull(argv[++i], NULL, 10) * 1000000000ULL; + } + } + Quakey *quakey; - int ret = quakey_init(&quakey, 2); + int ret = quakey_init(&quakey, seed); if (ret < 0) return -1; + QuakeyNode cli_1; + QuakeyNode cli_2; + QuakeyNode node_1; + QuakeyNode node_2; + QuakeyNode node_3; + // Client 1 { QuakeySpawn config = { @@ -39,7 +57,7 @@ int main(void) .disk_size = 10<<20, .platform = QUAKEY_LINUX, }; - quakey_spawn(quakey, config, "cli --server 127.0.0.4:8080 --server 127.0.0.5:8080 --server 127.0.0.6:8080"); + cli_1 = quakey_spawn(quakey, config, "cli --server 127.0.0.4:8080 --server 127.0.0.5:8080 --server 127.0.0.6:8080"); } // Client 2 @@ -55,7 +73,7 @@ int main(void) .disk_size = 10<<20, .platform = QUAKEY_LINUX, }; - quakey_spawn(quakey, config, "cli --server 127.0.0.4:8080 --server 127.0.0.5:8080 --server 127.0.0.6:8080"); + cli_2 = quakey_spawn(quakey, config, "cli --server 127.0.0.4:8080 --server 127.0.0.5:8080 --server 127.0.0.6:8080"); } // Node 1 @@ -71,7 +89,7 @@ int main(void) .disk_size = 10<<20, .platform = QUAKEY_LINUX, }; - quakey_spawn(quakey, config, "nd --addr 127.0.0.4:8080 --peer 127.0.0.5:8080 --peer 127.0.0.6:8080"); + node_1 = quakey_spawn(quakey, config, "nd --addr 127.0.0.4:8080 --peer 127.0.0.5:8080 --peer 127.0.0.6:8080"); } // Node 2 @@ -87,7 +105,7 @@ int main(void) .disk_size = 10<<20, .platform = QUAKEY_LINUX, }; - quakey_spawn(quakey, config, "nd --peer 127.0.0.4:8080 --addr 127.0.0.5:8080 --peer 127.0.0.6:8080"); + node_2 = quakey_spawn(quakey, config, "nd --peer 127.0.0.4:8080 --addr 127.0.0.5:8080 --peer 127.0.0.6:8080"); } // Node 3 @@ -103,12 +121,30 @@ int main(void) .disk_size = 10<<20, .platform = QUAKEY_LINUX, }; - quakey_spawn(quakey, config, "nd --peer 127.0.0.4:8080 --peer 127.0.0.5:8080 --addr 127.0.0.6:8080"); + node_3 = quakey_spawn(quakey, config, "nd --peer 127.0.0.4:8080 --peer 127.0.0.5:8080 --addr 127.0.0.6:8080"); } - while (simulation_running) + // Limit crashes to 1 node at a time (within fault tolerance of f=1). + quakey_set_max_crashes(quakey, 1); + + quakey_network_partitioning(quakey, true); + + InvariantChecker invariant_checker; + invariant_checker_init(&invariant_checker); + + while (simulation_running && (time_limit_ns == 0 || quakey_current_time(quakey) < time_limit_ns)) { + quakey_schedule_one(quakey); + NodeState *arr[] = { + quakey_node_state(node_1), + quakey_node_state(node_2), + quakey_node_state(node_3), + }; + invariant_checker_run(&invariant_checker, arr, sizeof(arr)/sizeof(arr[0])); + } + + invariant_checker_free(&invariant_checker); quakey_free(quakey); return 0; } diff --git a/raft/node.c b/raft/node.c index 3117d9e..ddf9a59 100644 --- a/raft/node.c +++ b/raft/node.c @@ -3,16 +3,19 @@ #endif #include -#include #include #include "node.h" -//#define NODE_TRACE(fmt, ...) {} -#define NODE_TRACE(fmt, ...) fprintf(stderr, "NODE: " fmt "\n", ##__VA_ARGS__); +typedef enum { + HR_OK, + HR_INVALID_MESSAGE, + HR_OUT_OF_MEMORY, + HR_IO_FAILURE, +} HandlerResult; // Format time as seconds with 3 decimal places for trace output -#define TIME_FMT "%.3fs" +#define TIME_FMT "%7.3fs" #define TIME_VAL(t) ((double)(t) / 1000000000.0) static const char *message_type_name(uint8_t type) @@ -39,44 +42,6 @@ static const char *role_name(Role role) return "UNKNOWN"; } -static void client_table_init(ClientTable *ct) -{ - ct->count = 0; - ct->capacity = 0; - ct->entries = NULL; -} - -static void client_table_free(ClientTable *ct) -{ - free(ct->entries); -} - -static ClientTableEntry *client_table_find(ClientTable *ct, uint64_t client_id) -{ - for (int i = 0; i < ct->count; i++) - if (ct->entries[i].client_id == client_id) - return &ct->entries[i]; - return NULL; -} - -static int client_table_add(ClientTable *ct, uint64_t client_id, uint64_t request_id, int conn_tag) -{ - if (ct->count == ct->capacity) { - int n = ct->capacity ? 2 * ct->capacity : 8; - void *p = realloc(ct->entries, n * sizeof(ClientTableEntry)); - if (p == NULL) return -1; - ct->capacity = n; - ct->entries = p; - } - ct->entries[ct->count++] = (ClientTableEntry) { - .client_id = client_id, - .last_request_id = request_id, - .pending = true, - .conn_tag = conn_tag, - }; - return 0; -} - static int self_idx(NodeState *state) { for (int i = 0; i < state->num_nodes; i++) @@ -85,6 +50,47 @@ static int self_idx(NodeState *state) UNREACHABLE; } +static void node_log_impl(NodeState *state, const char *event, const char *detail) +{ + printf("[" TIME_FMT "] NODE %d (%s) | T%-3lu C%-3d L%-3d | %-20s %s\n", + TIME_VAL(state->now), + self_idx(state), + role_name(state->role), + (unsigned long)state->term_and_vote.term, + state->commit_index, + wal_entry_count(&state->wal), + event, + detail ? detail : ""); +} + +#define node_log(state, event, fmt, ...) do { \ + char _detail[256]; \ + snprintf(_detail, sizeof(_detail), fmt, ##__VA_ARGS__); \ + node_log_impl(state, event, _detail); \ +} while (0) + +#define node_log_simple(state, event) \ + node_log_impl(state, event, NULL) + +static int count_set(uint32_t word) +{ + int n = 0; + for (int i = 0; i < (int) sizeof(word) * 8; i++) + if (word & (1 << i)) + n++; + return n; +} + +static bool reached_quorum(NodeState *state, uint32_t votes) +{ + return count_set(votes) > state->num_nodes/2; +} + +static void add_vote(uint32_t *votes, int idx) +{ + *votes |= 1 << idx; +} + static uint64_t choose_election_timeout(void) { uint64_t base = PRIMARY_DEATH_TIMEOUT_SEC * 1000000000ULL; @@ -95,98 +101,140 @@ static uint64_t choose_election_timeout(void) #endif } +// Checksummed record format for the term_and_vote file: +// uint64_t term (8 bytes) +// int voted_for (4 bytes) +// uint32_t checksum (4 bytes) +// Total: 16 bytes per record. +#define TERM_AND_VOTE_RECORD_SIZE 16 + +static uint32_t term_vote_checksum(uint64_t term, int voted_for) +{ + // FNV-1a over the term and voted_for bytes + uint32_t h = 2166136261u; + const unsigned char *p; + + p = (const unsigned char *)&term; + for (int i = 0; i < (int)sizeof(term); i++) { + h ^= p[i]; + h *= 16777619u; + } + + p = (const unsigned char *)&voted_for; + for (int i = 0; i < (int)sizeof(voted_for); i++) { + h ^= p[i]; + h *= 16777619u; + } + + return h; +} + static int set_term_and_vote(NodeState *state, uint64_t term, int voted_for) { - state->term = term; - state->voted_for = voted_for; - if (file_set_offset(state->term_and_vote_handle, 0) < 0) + uint32_t cksum = term_vote_checksum(term, voted_for); + + if (file_set_offset(state->term_and_vote.handle, 0) < 0) return -1; - if (file_write_exact(state->term_and_vote_handle, (char*) &term, sizeof(term))) + if (file_write_exact(state->term_and_vote.handle, (char*) &term, sizeof(term))) return -1; - if (file_write_exact(state->term_and_vote_handle, (char*) &voted_for, sizeof(voted_for))) + + if (file_set_offset(state->term_and_vote.handle, 8) < 0) return -1; - if (file_sync(state->term_and_vote_handle) < 0) + if (file_write_exact(state->term_and_vote.handle, (char*) &voted_for, sizeof(voted_for))) return -1; + + if (file_set_offset(state->term_and_vote.handle, 12) < 0) + return -1; + if (file_write_exact(state->term_and_vote.handle, (char*) &cksum, sizeof(cksum))) + return -1; + + if (file_sync(state->term_and_vote.handle) < 0) + return -1; + + state->term_and_vote.term = term; + state->term_and_vote.voted_for = voted_for; return 0; } -static int send_to_peer_ex(NodeState *state, int peer_idx, MessageHeader *msg, void *extra, int extra_len) + +static void +send_to_peer_ex(NodeState *state, int peer_idx, MessageHeader *msg, + void *extra, int extra_len) { ByteQueue *output; int conn_idx = tcp_index_from_tag(&state->tcp, peer_idx); if (conn_idx < 0) { int ret = tcp_connect(&state->tcp, state->node_addrs[peer_idx], peer_idx, &output); if (ret < 0) - return -1; + return; } else { output = tcp_output_buffer(&state->tcp, conn_idx); - if (output == NULL) { - assert(0); - } + if (output == NULL) + return; } int header_len = msg->length - extra_len; byte_queue_write(output, msg, header_len); if (extra_len > 0) byte_queue_write(output, extra, extra_len); - return 0; } -static int broadcast_to_peers_ex(NodeState *state, MessageHeader *msg, void *extra, int extra_len) +static void +broadcast_to_peers_ex(NodeState *state, MessageHeader *msg, + void *extra, int extra_len) { for (int i = 0; i < state->num_nodes; i++) { if (i != self_idx(state)) - if (send_to_peer_ex(state, i, msg, extra, extra_len) < 0) - return -1; + send_to_peer_ex(state, i, msg, extra, extra_len); } - return 0; } -static int broadcast_to_peers(NodeState *state, MessageHeader *msg) +static void +broadcast_to_peers(NodeState *state, MessageHeader *msg) { - return broadcast_to_peers_ex(state, msg, NULL, 0); + broadcast_to_peers_ex(state, msg, NULL, 0); } -static void send_vote_response(NodeState *state, int conn_idx, bool value, int candidate_idx) +static HandlerResult +send_vote_response(NodeState *state, int conn_idx, bool value, int candidate_idx) { + // Persist the vote BEFORE sending the response. If persistence + // fails the node crashes, which is correct: we must never send + // a vote grant that isn't durably recorded, otherwise after + // restart the node could vote again in the same term, violating + // the "at most one vote per term" invariant. + if (value) { + if (set_term_and_vote(state, state->term_and_vote.term, candidate_idx) < 0) + return HR_IO_FAILURE; + + // Reset election timer when granting a vote (Raft Section 5.2) + state->heartbeat = state->now; + state->election_timeout = choose_election_timeout(); + } + VotedMessage voted_message = { .base = { .version = MESSAGE_VERSION, .type = MESSAGE_TYPE_VOTED, .length = sizeof(VotedMessage), }, - .term = state->term, + .sender_idx = self_idx(state), + .term = state->term_and_vote.term, .value = (value == true) ? 1 : 0, }; - { - Time t = get_current_time(); - int peer = tcp_get_tag(&state->tcp, conn_idx); - NODE_TRACE("[" TIME_FMT "] node %d (%s) -> node %d: VOTED term=%lu granted=%s", - TIME_VAL(t), self_idx(state), role_name(state->role), - peer, (unsigned long)state->term, value ? "yes" : "no"); - } + node_log(state, "SEND VOTED", "-> node %d term=%lu granted=%s", + tcp_get_tag(&state->tcp, conn_idx), + (unsigned long)state->term_and_vote.term, value ? "yes" : "no"); ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); assert(output); byte_queue_write(output, &voted_message, voted_message.base.length); - - if (value) { - - if (set_term_and_vote(state, state->term, candidate_idx) < 0) { - // I/O error persisting vote; proceed anyway - } - - // Reset election timer when granting a vote (Raft Section 5.2) - Time now = get_current_time(); - if (now == INVALID_TIME) - return; - state->watchdog = now; - state->election_timeout = choose_election_timeout(); - } + return HR_OK; } -static void send_appended_response(NodeState *state, int conn_idx, bool success, int match_index) +static HandlerResult +send_appended_response(NodeState *state, int conn_idx, bool success, int match_index) { AppendedMessage appended_message = { .base = { @@ -195,26 +243,22 @@ static void send_appended_response(NodeState *state, int conn_idx, bool success, .length = sizeof(AppendedMessage), }, .sender_idx = self_idx(state), - .term = state->term, + .term = state->term_and_vote.term, .success = success ? 1 : 0, .match_index = match_index, }; - { - Time t = get_current_time(); - int peer = tcp_get_tag(&state->tcp, conn_idx); - NODE_TRACE("[" TIME_FMT "] node %d (%s) -> node %d: APPENDED term=%lu success=%s match_index=%d", - TIME_VAL(t), self_idx(state), role_name(state->role), - peer, (unsigned long)state->term, success ? "yes" : "no", match_index); - } + node_log(state, "SEND APPENDED", "-> node %d term=%lu success=%s match_index=%d", + tcp_get_tag(&state->tcp, conn_idx), (unsigned long)state->term_and_vote.term, success ? "yes" : "no", match_index); ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); assert(output); byte_queue_write(output, &appended_message, appended_message.base.length); + return HR_OK; } -static void send_redirect(NodeState *state, int conn_idx) +static HandlerResult send_redirect(NodeState *state, int conn_idx) { RedirectMessage redirect_message = { .base = { @@ -225,45 +269,58 @@ static void send_redirect(NodeState *state, int conn_idx) .leader_idx = state->leader_idx, }; - { - Time t = get_current_time(); - int tag = tcp_get_tag(&state->tcp, conn_idx); - NODE_TRACE("[" TIME_FMT "] node %d (%s) -> conn %d: REDIRECT leader_idx=%d", - TIME_VAL(t), self_idx(state), role_name(state->role), - tag, state->leader_idx); - } + node_log(state, "SEND REDIRECT", "-> conn %d leader_idx=%d", + tcp_get_tag(&state->tcp, conn_idx), state->leader_idx); ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); assert(output); byte_queue_write(output, &redirect_message, redirect_message.base.length); + return HR_OK; } // Apply all committed but not-yet-applied entries to the state machine. -// If this node is the leader, also reply to waiting clients. +// Update the client table for ALL roles so that deduplication survives +// leader changes. If this node is the leader, also reply to waiting clients. static void apply_committed(NodeState *state) { while (state->last_applied < state->commit_index) { state->last_applied++; - { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (%s): applying log entry %d (term %lu)", - TIME_VAL(t), self_idx(state), role_name(state->role), - state->last_applied, - (unsigned long) wal_peek_entry(&state->wal, state->last_applied)->term); - } + WALEntry *wal_entry = wal_peek_entry(&state->wal, state->last_applied); - OperationResult result = state_machine_update(&state->state_machine, wal_peek_entry(&state->wal, state->last_applied)->oper); + node_log(state, "APPLY", "entry %d (term %lu)", + state->last_applied, (unsigned long)wal_entry->term); - if (state->role == ROLE_LEADER) { - - ClientTableEntry *entry = client_table_find(&state->client_table, wal_peek_entry(&state->wal, state->last_applied)->client_id); - if (entry && entry->pending) { + KVStoreResult result = kvstore_update(&state->kvstore, wal_entry->oper); + // Update the client table with the committed result for ALL roles. + // This ensures deduplication state survives leader changes: when a + // follower becomes leader, its client table already knows about + // committed operations and can reject duplicate requests. + if (wal_entry->client_id != 0) { + ClientTableEntry *entry = client_table_find(&state->client_table, wal_entry->client_id); + if (entry == NULL) { + client_table_add(&state->client_table, wal_entry->client_id, + wal_entry->request_id, -1); + entry = client_table_find(&state->client_table, wal_entry->client_id); + if (entry) { + entry->pending = false; + entry->last_result = result; + } + } else { + entry->last_request_id = wal_entry->request_id; entry->pending = false; entry->last_result = result; + } + } + + // Leader: reply to waiting clients + if (state->role == ROLE_LEADER && wal_entry->client_id != 0) { + + ClientTableEntry *entry = client_table_find(&state->client_table, wal_entry->client_id); + if (entry) { ReplyMessage reply_message = { .base = { @@ -272,13 +329,14 @@ static void apply_committed(NodeState *state) .length = sizeof(ReplyMessage), }, .result = result, + .request_id = entry->last_request_id, }; - int ci = tcp_index_from_tag(&state->tcp, entry->conn_tag); - if (ci >= 0) { + int ci = entry->conn_tag >= 0 + ? tcp_index_from_tag(&state->tcp, entry->conn_tag) + : -1; + if (ci > -1) { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER) -> client %lu: REPLY for log entry %d", - TIME_VAL(t), self_idx(state), + node_log(state, "SEND REPLY", "-> client %lu entry %d", (unsigned long)entry->client_id, state->last_applied); ByteQueue *output = tcp_output_buffer(&state->tcp, ci); @@ -290,55 +348,68 @@ static void apply_committed(NodeState *state) } } -static int handle_append_entries(NodeState *state, int conn_idx, - AppendEntriesMessage *append_entries_message, WALEntry *entries) +static HandlerResult +handle_append_entries(NodeState *state, int conn_idx, AppendEntriesMessage *message, + WALEntry *entries) { // Reset election timer - Time now = get_current_time(); - if (now == INVALID_TIME) - return -1; - state->watchdog = now; + state->heartbeat = state->now; state->election_timeout = choose_election_timeout(); - state->leader_idx = append_entries_message->leader_idx; + state->leader_idx = message->leader_idx; - int prev_log_index = append_entries_message->prev_log_index; - uint64_t prev_log_term = append_entries_message->prev_log_term; + int prev_log_index = message->prev_log_index; + uint64_t prev_log_term = message->prev_log_term; // Log consistency check: verify prev_log_index/prev_log_term if (prev_log_index >= 0) { if (prev_log_index >= wal_entry_count(&state->wal)) { // We don't have the entry at prev_log_index - send_appended_response(state, conn_idx, false, -1); - return 0; + return send_appended_response(state, conn_idx, false, -1); } if (wal_peek_entry(&state->wal, prev_log_index)->term != prev_log_term) { // Conflicting entry at prev_log_index - send_appended_response(state, conn_idx, false, -1); - return 0; + return send_appended_response(state, conn_idx, false, -1); } } + // Raft Section 5.3, rules 3 & 4: + // Only truncate if an existing entry conflicts with a new one + // (same index but different terms). Skip entries that already match. + // Unconditionally truncating here would be wrong because a delayed + // AppendEntries (with fewer entries) could arrive after a newer one + // that already extended the log further. Blindly truncating would + // discard those newer, valid entries, causing the follower to lose + // committed data and forcing the leader to re-replicate them. int insert_idx = prev_log_index+1; - if (insert_idx < wal_entry_count(&state->wal)) { - // TODO: What if we're truncating operations that were already applied to the state machine? - if (wal_truncate(&state->wal, insert_idx) < 0) { - send_appended_response(state, conn_idx, false, -1); - return 0; + int i = 0; + for (; i < message->entry_count; i++) { + int log_idx = insert_idx + i; + + if (log_idx >= wal_entry_count(&state->wal)) + break; // No more existing entries; append the rest + + WALEntry incoming; + memcpy(&incoming, &entries[i], sizeof(WALEntry)); + + if (wal_peek_entry(&state->wal, log_idx)->term != incoming.term) { + // Conflict: truncate from this point onward and append the rest + if (wal_truncate(&state->wal, log_idx) < 0) + return HR_IO_FAILURE; + break; } + // Entry matches; skip it } - for (int i = 0; i < append_entries_message->entry_count; i++) { + for (; i < message->entry_count; i++) { // Copy in case it's unaligned WALEntry entry; memcpy(&entry, &entries[i], sizeof(WALEntry)); - if (wal_append(&state->wal, &entry) < 0) { - send_appended_response(state, conn_idx, false, -1); - return 0; - } + if (wal_append(&state->wal, &entry) < 0) + return HR_IO_FAILURE; } // Now we need to advance the local commit index @@ -365,37 +436,30 @@ static int handle_append_entries(NodeState *state, int conn_idx, // gradually commit messages until it's up to date // with other nodes. - int leader_commit = append_entries_message->leader_commit; + int leader_commit = message->leader_commit; + int last_new_index = prev_log_index + message->entry_count; if (state->commit_index < leader_commit) - state->commit_index = MIN(leader_commit, wal_entry_count(&state->wal)-1); + state->commit_index = MIN(leader_commit, last_new_index); apply_committed(state); - send_appended_response(state, conn_idx, true, wal_entry_count(&state->wal)-1); - return 0; + return send_appended_response(state, conn_idx, true, wal_entry_count(&state->wal)-1); } -static void start_election(NodeState *state) +static HandlerResult start_election(NodeState *state) { - { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d: starting election for term %lu", - TIME_VAL(t), self_idx(state), (unsigned long)state->term); - } - state->role = ROLE_CANDIDATE; - state->votes_received = 1; // Vote for self + state->votes = 1 << self_idx(state); // Vote for self - if (set_term_and_vote(state, state->term+1, self_idx(state)) < 0) { - return; // I/O error; retry on next election timeout - } + if (set_term_and_vote(state, state->term_and_vote.term+1, self_idx(state)) < 0) + return HR_IO_FAILURE; - Time now = get_current_time(); - if (now != INVALID_TIME) { - state->watchdog = now; - state->election_timeout = choose_election_timeout(); - } + state->heartbeat = state->now; + state->election_timeout = choose_election_timeout(); + + node_log(state, "ELECTION", "starting for term %lu", + (unsigned long)state->term_and_vote.term); RequestVoteMessage request_vote_message = { .base = { @@ -403,36 +467,32 @@ static void start_election(NodeState *state) .type = MESSAGE_TYPE_REQUEST_VOTE, .length = sizeof(RequestVoteMessage), }, - .term = state->term, + .term = state->term_and_vote.term, .sender_idx = self_idx(state), .last_log_index = wal_entry_count(&state->wal)-1, .last_log_term = wal_last_term(&state->wal), }; - { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (%s) -> ALL: REQUEST_VOTE term=%lu last_log_index=%d last_log_term=%lu", - TIME_VAL(t), self_idx(state), role_name(state->role), - (unsigned long) state->term, wal_entry_count(&state->wal)-1, - (unsigned long) wal_last_term(&state->wal)); - } + node_log(state, "SEND REQUEST_VOTE", "-> ALL last_log_index=%d last_log_term=%lu", + wal_entry_count(&state->wal)-1, + (unsigned long) wal_last_term(&state->wal)); broadcast_to_peers(state, &request_vote_message.base); + return HR_OK; } // Common pattern: step down to follower when we see a higher term. -static void step_down(NodeState *state, uint64_t new_term) +static HandlerResult step_down(NodeState *state, uint64_t new_term) { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (%s): stepping down to FOLLOWER, term %lu -> %lu", - TIME_VAL(t), self_idx(state), role_name(state->role), - (unsigned long) state->term, (unsigned long) new_term); + node_log(state, "STEP DOWN", "term %lu -> %lu", + (unsigned long)state->term_and_vote.term, (unsigned long)new_term); state->role = ROLE_FOLLOWER; - if (set_term_and_vote(state, new_term, -1) < 0) { - // I/O error persisting term; in-memory state already updated - } + if (set_term_and_vote(state, new_term, -1) < 0) + return HR_IO_FAILURE; + + return HR_OK; } // Send AppendEntries to a specific follower, including @@ -454,7 +514,7 @@ static void send_append_entries_to_peer(NodeState *state, int peer_idx) .type = MESSAGE_TYPE_APPEND_ENTRIES, .length = sizeof(AppendEntriesMessage) + count * sizeof(WALEntry), }, - .term = state->term, + .term = state->term_and_vote.term, .leader_idx = self_idx(state), .prev_log_index = prev_index, .prev_log_term = prev_term, @@ -462,25 +522,16 @@ static void send_append_entries_to_peer(NodeState *state, int peer_idx) .entry_count = count, }; - { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (%s) -> node %d: APPEND_ENTRIES term=%lu prev_log_index=%d prev_log_term=%lu leader_commit=%d entries=%d", - TIME_VAL(t), self_idx(state), role_name(state->role), - peer_idx, (unsigned long)state->term, prev_index, (unsigned long)prev_term, - state->commit_index, count); - } + node_log(state, "SEND APPEND_ENTRIES", "-> node %d prev_idx=%d prev_term=%lu commit=%d entries=%d", + peer_idx, prev_index, (unsigned long)prev_term, + state->commit_index, count); WALEntry *entries = (count > 0) ? wal_peek_entry(&state->wal, next) : NULL; send_to_peer_ex(state, peer_idx, &append_entries_message.base, entries, count * sizeof(WALEntry)); } -static void become_leader(NodeState *state) +static HandlerResult become_leader(NodeState *state) { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d: became LEADER for term %lu (votes=%d/%d)", - TIME_VAL(t), self_idx(state), (unsigned long)state->term, - state->votes_received, state->num_nodes); - state->role = ROLE_LEADER; state->leader_idx = self_idx(state); @@ -494,15 +545,15 @@ static void become_leader(NodeState *state) // This ensures entries from previous terms can be committed, since // Section 5.4.2 only allows committing entries from the current term. WALEntry noop = { - .term = state->term, - .oper = OPERATION_NOOP, + .term = state->term_and_vote.term, + .oper = { .type = KVSTORE_OPER_NOOP }, .client_id = 0, }; - if (wal_append(&state->wal, &noop) < 0) { - // I/O error; step down and let another node become leader - state->role = ROLE_FOLLOWER; - return; - } + if (wal_append(&state->wal, &noop) < 0) + return HR_IO_FAILURE; // TODO: Restore previously set fields? + + node_log(state, "BECAME LEADER", "term=%lu votes=%d/%d", + (unsigned long)state->term_and_vote.term, count_set(state->votes), state->num_nodes); state->match_indices[self_idx(state)] = wal_entry_count(&state->wal)-1; @@ -512,10 +563,8 @@ static void become_leader(NodeState *state) send_append_entries_to_peer(state, i); } - Time now = get_current_time(); - if (now == INVALID_TIME) - return; - state->watchdog = now; + state->heartbeat = state->now; + return HR_OK; } // A candidate's log is "at least as up-to-date" if its last @@ -532,215 +581,143 @@ static bool remote_has_recent_state(NodeState *state, return peer_index >= wal_entry_count(&state->wal)-1; } -static int -process_message_as_follower(NodeState *state, - int conn_idx, uint8_t type, ByteView msg) +static HandlerResult +process_request_vote_for_folloer(NodeState *state, int conn_idx, ByteView msg) { - switch (type) { - case MESSAGE_TYPE_REQUEST_VOTE: - { - RequestVoteMessage request_vote_message; - if (msg.len != sizeof(request_vote_message)) - return -1; - memcpy(&request_vote_message, msg.ptr, sizeof(request_vote_message)); + RequestVoteMessage request_vote_message; + if (msg.len != sizeof(request_vote_message)) + return HR_INVALID_MESSAGE; + memcpy(&request_vote_message, msg.ptr, sizeof(request_vote_message)); - // If the request's term is old, the peer is stale - // and we let it know by replying with our own term - // number. - if (request_vote_message.term < state->term) { - send_vote_response(state, conn_idx, false, -1); - break; - } + // If the request's term is old, the peer is stale + // and we let it know by replying with our own term + // number. + if (request_vote_message.term < state->term_and_vote.term) + return send_vote_response(state, conn_idx, false, -1); - // If the request's term is newer, we are staled - // and need to move forward. Then, we can procede - // with evaluating the peer for a vote. - if (request_vote_message.term > state->term) { - if (set_term_and_vote(state, request_vote_message.term, -1) < 0) - break; // I/O error; ignore this request - } - - // Grant vote if we haven't voted yet (or already - // voted for this candidate) and the candidate's - // log is at least as recent as our own. - if (state->voted_for == -1 || state->voted_for == request_vote_message.sender_idx) { - if (remote_has_recent_state(state, - request_vote_message.last_log_index, - request_vote_message.last_log_term)) { - send_vote_response(state, conn_idx, true, request_vote_message.sender_idx); - break; - } - } - - send_vote_response(state, conn_idx, false, -1); - } - break; - case MESSAGE_TYPE_VOTED: - { - // Followers don't expect vote responses. Ignore. - } - break; - case MESSAGE_TYPE_APPEND_ENTRIES: - { - AppendEntriesMessage append_entries_message; - if (msg.len < (int)sizeof(append_entries_message)) - return -1; - memcpy(&append_entries_message, msg.ptr, sizeof(append_entries_message)); - - if (append_entries_message.term < state->term) { - // Stale leader - send_appended_response(state, conn_idx, false, -1); - break; - } - - if (append_entries_message.term > state->term) { - if (set_term_and_vote(state, append_entries_message.term, -1) < 0) - break; // I/O error; ignore this message - } - - return handle_append_entries(state, conn_idx, &append_entries_message, (WALEntry*) (msg.ptr + sizeof(AppendEntriesMessage))); - } - break; - case MESSAGE_TYPE_APPENDED: - { - // Followers don't expect append responses. Ignore. - } - break; - case MESSAGE_TYPE_REQUEST: - { - // Redirect client to the current leader. - // If no leader exists at this time, we tell the client. - send_redirect(state, conn_idx); - } - break; - case MESSAGE_TYPE_REPLY: - { - return -1; - } - break; - case MESSAGE_TYPE_REDIRECT: - { - return -1; - } - break; + // If the request's term is newer, we are staled + // and need to move forward. Then, we can procede + // with evaluating the peer for a vote. + if (request_vote_message.term > state->term_and_vote.term) { + if (set_term_and_vote(state, request_vote_message.term, -1) < 0) + return HR_IO_FAILURE; } - return 0; + // Grant vote if we haven't voted yet (or already + // voted for this candidate) and the candidate's + // log is at least as recent as our own. + if (state->term_and_vote.voted_for == -1 || state->term_and_vote.voted_for == request_vote_message.sender_idx) { + if (remote_has_recent_state(state, + request_vote_message.last_log_index, + request_vote_message.last_log_term)) + return send_vote_response(state, conn_idx, true, request_vote_message.sender_idx); + } + + return send_vote_response(state, conn_idx, false, -1); } -static int -process_message_as_candidate(NodeState *state, - int conn_idx, uint8_t type, ByteView msg) +static HandlerResult +process_append_entries_for_follower(NodeState *state, int conn_idx, ByteView msg) { - switch (type) { - case MESSAGE_TYPE_REQUEST_VOTE: - { - RequestVoteMessage request_vote_message; - if (msg.len != sizeof(request_vote_message)) - return -1; - memcpy(&request_vote_message, msg.ptr, sizeof(request_vote_message)); + AppendEntriesMessage message; + if (msg.len < (int)sizeof(message)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); - // If same term, we already voted for ourselves; deny - if (request_vote_message.term == state->term) { - send_vote_response(state, conn_idx, false, -1); - break; - } + // Stale leader? + if (message.term < state->term_and_vote.term) + return send_appended_response(state, conn_idx, false, -1); - // Stale candidate - if (request_vote_message.term < state->term) { - send_vote_response(state, conn_idx, false, -1); - break; - } - - // Higher term: step down and consider the vote - step_down(state, request_vote_message.term); - - if (remote_has_recent_state(state, - request_vote_message.last_log_index, - request_vote_message.last_log_term)) { - send_vote_response(state, conn_idx, true, request_vote_message.sender_idx); - } else { - send_vote_response(state, conn_idx, false, -1); - } - } - break; - case MESSAGE_TYPE_VOTED: - { - VotedMessage voted_message; - if (msg.len != sizeof(voted_message)) - return -1; - memcpy(&voted_message, msg.ptr, sizeof(voted_message)); - - // Local state is stale - if (voted_message.term > state->term) { - step_down(state, voted_message.term); - break; - } - - // Ignore votes from old terms - if (voted_message.term < state->term) - break; - - if (voted_message.value) { - { - Time t = get_current_time(); - int sender = tcp_get_tag(&state->tcp, conn_idx); - NODE_TRACE("[" TIME_FMT "] node %d (CANDIDATE): received vote from node %d (%d/%d votes for term %lu)", - TIME_VAL(t), self_idx(state), sender, - state->votes_received+1, state->num_nodes, - (unsigned long)state->term); - } - state->votes_received++; - if (state->votes_received > state->num_nodes/2) { - become_leader(state); - } - } - } - break; - case MESSAGE_TYPE_APPEND_ENTRIES: - { - AppendEntriesMessage append_entries_message; - if (msg.len < (int)sizeof(append_entries_message)) - return -1; - memcpy(&append_entries_message, msg.ptr, sizeof(append_entries_message)); - - if (append_entries_message.term < state->term) { - // Stale leader; reject - send_appended_response(state, conn_idx, false, -1); - break; - } - - // A valid leader exists for this or a higher term; step down - step_down(state, append_entries_message.term); - - return handle_append_entries(state, conn_idx, &append_entries_message, (WALEntry*) (msg.ptr + sizeof(AppendEntriesMessage))); - } - break; - case MESSAGE_TYPE_APPENDED: - { - // Candidates don't expect append responses. Ignore. - } - break; - case MESSAGE_TYPE_REQUEST: - { - // Redirect client to the current leader. - // If no leader exists at this time, we tell the client. - send_redirect(state, conn_idx); - } - break; - case MESSAGE_TYPE_REPLY: - { - return -1; - } - break; - case MESSAGE_TYPE_REDIRECT: - { - return -1; - } - break; + if (message.term > state->term_and_vote.term) { + if (set_term_and_vote(state, message.term, -1) < 0) + return HR_IO_FAILURE; } - return 0; + WALEntry *entries = (WALEntry*) (msg.ptr + sizeof(AppendEntriesMessage)); + return handle_append_entries(state, conn_idx, &message, entries); +} + +static HandlerResult +process_request_vote_for_candidate(NodeState *state, int conn_idx, ByteView msg) +{ + RequestVoteMessage request_vote_message; + if (msg.len != sizeof(request_vote_message)) + return HR_INVALID_MESSAGE; + memcpy(&request_vote_message, msg.ptr, sizeof(request_vote_message)); + + // If same term, we already voted for ourselves; deny + if (request_vote_message.term == state->term_and_vote.term) + return send_vote_response(state, conn_idx, false, -1); + + // Stale candidate + if (request_vote_message.term < state->term_and_vote.term) + return send_vote_response(state, conn_idx, false, -1); + + // Higher term: step down and consider the vote + HandlerResult hret = step_down(state, request_vote_message.term); + if (hret != HR_OK) + return hret; + + if (remote_has_recent_state(state, + request_vote_message.last_log_index, + request_vote_message.last_log_term)) + return send_vote_response(state, conn_idx, true, request_vote_message.sender_idx); + + return send_vote_response(state, conn_idx, false, -1); +} + +static HandlerResult +process_voted_for_candidate(NodeState *state, int conn_idx, ByteView msg) +{ + VotedMessage message; + if (msg.len != sizeof(message)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + // Local state is stale + if (message.term > state->term_and_vote.term) + return step_down(state, message.term); + + // Ignore votes from old terms + if (message.term < state->term_and_vote.term) + return HR_OK; + + if (message.value) { + + add_vote(&state->votes, message.sender_idx); + + node_log(state, "RECV VOTE", "from node %d (%d/%d for term %lu)", + tcp_get_tag(&state->tcp, conn_idx), count_set(state->votes), state->num_nodes, (unsigned long)state->term_and_vote.term); + + if (reached_quorum(state, state->votes)) { + HandlerResult hret = become_leader(state); + if (hret != HR_OK) + return hret; + } + } + + return HR_OK; +} + +static HandlerResult +process_append_entries_for_candidate(NodeState *state, int conn_idx, ByteView msg) +{ + AppendEntriesMessage append_entries_message; + if (msg.len < (int)sizeof(append_entries_message)) + return HR_INVALID_MESSAGE; + memcpy(&append_entries_message, msg.ptr, sizeof(append_entries_message)); + + // Stale leader? + if (append_entries_message.term < state->term_and_vote.term) + return send_appended_response(state, conn_idx, false, -1); + + // A valid leader exists for this or a higher term; step down + HandlerResult hret = step_down(state, append_entries_message.term); + if (hret != HR_OK) + return hret; + + WALEntry *entries = (WALEntry*) (msg.ptr + sizeof(AppendEntriesMessage)); + return handle_append_entries(state, conn_idx, &append_entries_message, entries); } // Leader: advance commit_index to the highest index replicated @@ -772,232 +749,330 @@ static void advance_commit_index(NodeState *state) assert(candidate < wal_entry_count(&state->wal)); - if (wal_peek_entry(&state->wal, candidate)->term == state->term) + if (wal_peek_entry(&state->wal, candidate)->term == state->term_and_vote.term) state->commit_index = candidate; } -static int -process_message_as_leader(NodeState *state, - int conn_idx, uint8_t type, ByteView msg) +static HandlerResult +process_request_vote_for_leader(NodeState *state, int conn_idx, ByteView msg) { - switch (type) { - case MESSAGE_TYPE_REQUEST_VOTE: - { - RequestVoteMessage request_vote_message; - if (msg.len != sizeof(request_vote_message)) - return -1; - memcpy(&request_vote_message, msg.ptr, sizeof(request_vote_message)); + RequestVoteMessage request_vote_message; + if (msg.len != sizeof(request_vote_message)) + return HR_INVALID_MESSAGE; + memcpy(&request_vote_message, msg.ptr, sizeof(request_vote_message)); - if (request_vote_message.term > state->term) { + if (request_vote_message.term > state->term_and_vote.term) { - step_down(state, request_vote_message.term); + HandlerResult hret = step_down(state, request_vote_message.term); + if (hret != HR_OK) + return hret; - if (remote_has_recent_state(state, - request_vote_message.last_log_index, - request_vote_message.last_log_term)) { - send_vote_response(state, conn_idx, true, request_vote_message.sender_idx); - } else { - send_vote_response(state, conn_idx, false, -1); - } + if (remote_has_recent_state(state, + request_vote_message.last_log_index, + request_vote_message.last_log_term)) + return send_vote_response(state, conn_idx, true, request_vote_message.sender_idx); - } else { - - // Our term is at least as high; reject - send_vote_response(state, conn_idx, false, -1); - } - } - break; - case MESSAGE_TYPE_VOTED: - { - // Already leader, ignore stray vote responses - } - break; - case MESSAGE_TYPE_APPEND_ENTRIES: - { - AppendEntriesMessage append_entries_message; - if (msg.len < (int)sizeof(append_entries_message)) - return -1; - memcpy(&append_entries_message, msg.ptr, sizeof(append_entries_message)); - - if (append_entries_message.term > state->term) { - // A leader with a higher term exists; step down - step_down(state, append_entries_message.term); - return handle_append_entries(state, conn_idx, &append_entries_message, (WALEntry*) (msg.ptr + sizeof(AppendEntriesMessage))); - } - - // Same or lower term: reject (two leaders in the same term is impossible) - send_appended_response(state, conn_idx, false, -1); - } - break; - case MESSAGE_TYPE_APPENDED: - { - AppendedMessage appended_message; - if (msg.len != sizeof(appended_message)) - return -1; - memcpy(&appended_message, msg.ptr, sizeof(appended_message)); - - // Our state is stale - if (appended_message.term > state->term) { - step_down(state, appended_message.term); - break; - } - - int follower_idx = appended_message.sender_idx; - assert(follower_idx > -1); - assert(follower_idx < state->num_nodes); - - if (appended_message.success) { - - state->match_indices[follower_idx] = appended_message.match_index; - state->next_indices[follower_idx] = appended_message.match_index + 1; - - int old_commit_index = state->commit_index; - - advance_commit_index(state); - - if (state->commit_index > old_commit_index) { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): commit_index advanced %d -> %d", - TIME_VAL(t), self_idx(state), old_commit_index, state->commit_index); - } - - apply_committed(state); - - } else { - - // Log inconsistency: decrement nextIndex and retry - - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): log inconsistency with node %d, decrementing next_index to %d", - TIME_VAL(t), self_idx(state), follower_idx, - state->next_indices[follower_idx] > 0 ? state->next_indices[follower_idx] - 1 : 0); - - state->next_indices[follower_idx] = MAX(0, state->next_indices[follower_idx]-1); - send_append_entries_to_peer(state, follower_idx); - } - } - break; - case MESSAGE_TYPE_REQUEST: - { - RequestMessage request_message; - if (msg.len != sizeof(request_message)) - return -1; - memcpy(&request_message, msg.ptr, sizeof(request_message)); - - // Assign a unique tag to this client connection so we can - // find it later even if the connection array is reordered. - int tag = tcp_get_tag(&state->tcp, conn_idx); - if (tag == -1) { - tag = state->next_client_tag++; - tcp_set_tag(&state->tcp, conn_idx, tag, true); - } - - // Client table deduplication (same pattern as VSR) - ClientTableEntry *entry = client_table_find(&state->client_table, request_message.client_id); - if (entry == NULL) { - if (client_table_add(&state->client_table, request_message.client_id, request_message.request_id, tag) < 0) - break; - } else { - if (entry->pending) - break; // Already processing a request for this client - - if (entry->last_request_id > request_message.request_id) - break; // Stale request - - if (entry->last_request_id == request_message.request_id) { - // Return cached result - ReplyMessage reply_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_REPLY, - .length = sizeof(ReplyMessage), - }, - .result = entry->last_result, - }; - ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); - if (output) - byte_queue_write(output, &reply_message, sizeof(reply_message)); - break; - } - - entry->last_request_id = request_message.request_id; - entry->pending = true; - entry->conn_tag = tag; - } - - WALEntry wal_entry = { - .term = state->term, - .client_id = request_message.client_id, - .oper = request_message.oper, - }; - if (wal_append(&state->wal, &wal_entry) < 0) - break; // I/O error; client will retry - - // Update own match index - state->match_indices[self_idx(state)] = wal_entry_count(&state->wal)-1; - - // Replicate to all followers - for (int i = 0; i < state->num_nodes; i++) { - if (i != self_idx(state)) - send_append_entries_to_peer(state, i); - } - } - break; - case MESSAGE_TYPE_REPLY: - { - return -1; - } - break; - case MESSAGE_TYPE_REDIRECT: - { - return -1; - } - break; + return send_vote_response(state, conn_idx, false, -1); } - return 0; + // Our term is at least as high; reject + return send_vote_response(state, conn_idx, false, -1); } -static int +static HandlerResult +process_append_entries_for_leader(NodeState *state, int conn_idx, ByteView msg) +{ + AppendEntriesMessage append_entries_message; + if (msg.len < (int)sizeof(append_entries_message)) + return HR_INVALID_MESSAGE; + memcpy(&append_entries_message, msg.ptr, sizeof(append_entries_message)); + + // Leader with a higher term exists? Step down + if (append_entries_message.term > state->term_and_vote.term) { + HandlerResult hret = step_down(state, append_entries_message.term); + if (hret != HR_OK) + return hret; + + WALEntry *entries = (WALEntry*) (msg.ptr + sizeof(AppendEntriesMessage)); + return handle_append_entries(state, conn_idx, &append_entries_message, entries); + } + + // Same or lower term: reject (two leaders in the same term is impossible) + return send_appended_response(state, conn_idx, false, -1); +} + +static HandlerResult +process_appended_for_leader(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + AppendedMessage appended_message; + if (msg.len != sizeof(appended_message)) + return HR_INVALID_MESSAGE; + memcpy(&appended_message, msg.ptr, sizeof(appended_message)); + + // Our state is stale + if (appended_message.term > state->term_and_vote.term) { + HandlerResult hret = step_down(state, appended_message.term); + if (hret != HR_OK) + return hret; + return HR_OK; + } + + int follower_idx = appended_message.sender_idx; + assert(follower_idx > -1); + assert(follower_idx < state->num_nodes); + + if (appended_message.success) { + + // Only advance monotonically: a stale success response (from + // an older AppendEntries) may carry a lower match_index than + // what we already know. Blindly overwriting would move + // next_index backward, causing the leader to re-send entries + // the follower already has and triggering spurious rejections + // that make next_index oscillate instead of converging. + if (appended_message.match_index > state->match_indices[follower_idx]) { + state->match_indices[follower_idx] = appended_message.match_index; + state->next_indices[follower_idx] = appended_message.match_index + 1; + } + + int old_commit_index = state->commit_index; + + advance_commit_index(state); + + if (state->commit_index > old_commit_index) + node_log(state, "COMMIT ADVANCE", "%d -> %d", old_commit_index, state->commit_index); + + apply_committed(state); + + } else { + + // Ignore stale rejections: only decrement if next_index + // hasn't already been advanced past this point by a success + if (appended_message.match_index == -1 && state->next_indices[follower_idx] > state->match_indices[follower_idx] + 1) { + + int new_next = MAX(state->match_indices[follower_idx] + 1, state->next_indices[follower_idx] - 1); + + node_log(state, "LOG INCONSISTENCY", "node %d next_index -> %d", follower_idx, new_next); + + state->next_indices[follower_idx] = new_next; + send_append_entries_to_peer(state, follower_idx); + } + } + + return HR_OK; +} + +static HandlerResult +process_request_for_leader(NodeState *state, int conn_idx, ByteView msg) +{ + RequestMessage request_message; + if (msg.len != sizeof(request_message)) + return HR_INVALID_MESSAGE; + memcpy(&request_message, msg.ptr, sizeof(request_message)); + + // Assign a unique tag to this client connection so we can + // find it later even if the connection array is reordered. + int tag = tcp_get_tag(&state->tcp, conn_idx); + if (tag == -1) { + tag = state->next_client_tag++; + tcp_set_tag(&state->tcp, conn_idx, tag, true); + } + + // Client table deduplication (same pattern as VSR) + ClientTableEntry *entry = client_table_find(&state->client_table, request_message.client_id); + if (entry == NULL) { + + if (client_table_add(&state->client_table, request_message.client_id, request_message.request_id, tag) < 0) + return HR_OK; + + } else { + + if (entry->pending) + return HR_OK; // Already processing a request for this client + + if (entry->last_request_id > request_message.request_id) + return HR_OK; // Stale request + + if (entry->last_request_id == request_message.request_id) { + // Return cached result + ReplyMessage reply_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_REPLY, + .length = sizeof(ReplyMessage), + }, + .result = entry->last_result, + .request_id = entry->last_request_id, + }; + ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); + if (output) + byte_queue_write(output, &reply_message, sizeof(reply_message)); + return HR_OK; + } + + entry->last_request_id = request_message.request_id; + entry->pending = true; + entry->conn_tag = tag; + } + + WALEntry wal_entry = { + .term = state->term_and_vote.term, + .client_id = request_message.client_id, + .request_id = request_message.request_id, + .oper = request_message.oper, + }; + + if (wal_append(&state->wal, &wal_entry) < 0) + return HR_IO_FAILURE; + + // Update own match index + state->match_indices[self_idx(state)] = wal_entry_count(&state->wal)-1; + + // Replicate to all followers + for (int i = 0; i < state->num_nodes; i++) { + if (i != self_idx(state)) + send_append_entries_to_peer(state, i); + } + + return HR_OK; +} + +static HandlerResult process_message(NodeState *state, int conn_idx, uint8_t type, ByteView msg) { - { - Time t = get_current_time(); - int sender = tcp_get_tag(&state->tcp, conn_idx); - NODE_TRACE("[" TIME_FMT "] node %d (%s) <- node/conn %d: recv %s (%d bytes)", - TIME_VAL(t), self_idx(state), role_name(state->role), - sender, message_type_name(type), (int)msg.len); - } + node_log(state, "RECV", "<- node/conn %d %s (%d bytes)", + tcp_get_tag(&state->tcp, conn_idx), + message_type_name(type), (int)msg.len); switch (state->role) { + case ROLE_LEADER: - return process_message_as_leader(state, conn_idx, type, msg); + switch (type) { + case MESSAGE_TYPE_REQUEST_VOTE: + return process_request_vote_for_leader(state, conn_idx, msg); + case MESSAGE_TYPE_APPEND_ENTRIES: + return process_append_entries_for_leader(state, conn_idx, msg); + case MESSAGE_TYPE_APPENDED: + return process_appended_for_leader(state, conn_idx, msg); + case MESSAGE_TYPE_REQUEST: + return process_request_for_leader(state, conn_idx, msg); + } + return HR_OK; + case ROLE_FOLLOWER: - return process_message_as_follower(state, conn_idx, type, msg); + switch (type) { + case MESSAGE_TYPE_REQUEST_VOTE: + return process_request_vote_for_folloer(state, conn_idx, msg); + case MESSAGE_TYPE_APPEND_ENTRIES: + return process_append_entries_for_follower(state, conn_idx, msg); + case MESSAGE_TYPE_REQUEST: + return send_redirect(state, conn_idx); + } + return HR_OK; + case ROLE_CANDIDATE: - return process_message_as_candidate(state, conn_idx, type, msg); + switch (type) { + case MESSAGE_TYPE_REQUEST_VOTE: + return process_request_vote_for_candidate(state, conn_idx, msg); + case MESSAGE_TYPE_VOTED: + return process_voted_for_candidate(state, conn_idx, msg); + case MESSAGE_TYPE_APPEND_ENTRIES: + return process_append_entries_for_candidate(state, conn_idx, msg); + case MESSAGE_TYPE_REQUEST: + return send_redirect(state, conn_idx); + } + return HR_OK; } + UNREACHABLE; } +static int term_and_vote_init(TermAndVote *term_and_vote, string file) +{ + // Do NOT use file_exists() here — it calls access() which is + // not mocked by quakey, so it checks the real filesystem instead + // of the mock. Instead, open the file (creates if new) and check + // its size, matching the pattern used by wal_init. + + Handle handle; + if (file_open(file, &handle) < 0) + return -1; + + size_t len; + if (file_size(handle, &len) < 0) { + file_close(handle); + return -1; + } + + uint64_t term; + int voted_for; + + if (len == 0) { + + term = 0; + voted_for = -1; + + } else { + + if (len != TERM_AND_VOTE_RECORD_SIZE) { + file_close(handle); + return -1; + } + + if (file_set_offset(handle, 0) < 0) { + file_close(handle); + return -1; + } + + if (file_read_exact(handle, (char*) &term, sizeof(term)) < 0) { + file_close(handle); + return -1; + } + + if (file_read_exact(handle, (char*) &voted_for, sizeof(voted_for)) < 0) { + file_close(handle); + return -1; + } + + uint32_t checksum; + if (file_read_exact(handle, (char*) &checksum, sizeof(checksum)) < 0) { + file_close(handle); + return -1; + } + + if (checksum != term_vote_checksum(term, voted_for)) { + file_close(handle); + return -1; + } + } + + term_and_vote->handle = handle; + term_and_vote->term = term; + term_and_vote->voted_for = voted_for; + return 0; +} + +static void term_and_vote_free(TermAndVote *term_and_vote) +{ + file_close(term_and_vote->handle); +} + int node_init(void *state_, int argc, char **argv, void **ctxs, struct pollfd *pdata, int pcap, int *pnum, int *timeout) { NodeState *state = state_; - string wal_file = S("raft.wal"); - string term_and_vote_file = S("term_and_vote.wal"); - Time now = get_current_time(); if (now == INVALID_TIME) { fprintf(stderr, "Node :: Couldn't get current time\n"); return -1; } - /////////////////////////////////////////////////////////////// - // Parse arguments + string wal_file = S("raft.wal"); + string term_and_vote_file = S("term_and_vote.wal"); bool self_addr_set = false; for (int i = 1; i < argc; i++) { @@ -1066,90 +1141,33 @@ int node_init(void *state_, int argc, char **argv, // globally refer to nodes by their index. addr_sort(state->node_addrs, state->num_nodes); - /////////////////////////////////////////////////////////////// - // Initialize term and vote - - bool existed = false; - if (file_exists(term_and_vote_file)) - existed = true; - - Handle term_and_vote_handle; - if (file_open(term_and_vote_file, &term_and_vote_handle) < 0) + if (term_and_vote_init(&state->term_and_vote, term_and_vote_file) < 0) return -1; - uint64_t term = 0; - int voted_for = -1; - if (existed) { - if (file_read_exact(term_and_vote_handle, (char*) &term, sizeof(term)) < 0) { - file_close(term_and_vote_handle); - return -1; - } - if (file_read_exact(term_and_vote_handle, (char*) &voted_for, sizeof(voted_for)) < 0) { - file_close(term_and_vote_handle); - return -1; - } - } + kvstore_init(&state->kvstore); - state->term_and_vote_handle = term_and_vote_handle; - state->term = term; - state->voted_for = voted_for; - - /////////////////////////////////////////////////////////////// - // Initialize WAL and state machine - - state_machine_init(&state->state_machine); - - if (wal_init(&state->wal, wal_file) < 0) { - printf("Couldn't initialize the WAL"); + if (wal_init(&state->wal, wal_file) < 0) return -1; - } - WALReplay wal_replay; - wal_replay_init(&wal_replay, &state->wal); - for (WALEntry *entry; (entry = wal_replay_next(&wal_replay)); ) { - state_machine_update(&state->state_machine, entry->oper); - } - wal_replay_free(&wal_replay); - - /////////////////////////////////////////////////////////////// - // Initialize volatile state - - // Current role of the node state->role = ROLE_FOLLOWER; - - // The time an AppendEntries was last sent or received - state->watchdog = now; - - // The index of the current leader + state->now = now; + state->heartbeat = now; state->leader_idx = -1; - - // Index of the last committed operation state->commit_index = -1; - - // Index of the last operation applied to the state machine state->last_applied = -1; - - // Number of votes received in the current term - state->votes_received = 0; - - // Nodes pick different election timeouts to reduce the risk - // of split votes + state->votes = 0; state->election_timeout = choose_election_timeout(); + state->commit_index = -1; + state->last_applied = -1; for (int i = 0; i < NODE_LIMIT; i++) { state->next_indices[i] = 0; state->match_indices[i] = -1; } - /////////////////////////////////////////////////////////////// - // Initialize client table - client_table_init(&state->client_table); state->next_client_tag = NODE_LIMIT; - /////////////////////////////////////////////////////////////// - // Initialize networking - if (tcp_context_init(&state->tcp) < 0) { fprintf(stderr, "Node :: Couldn't setup TCP context\n"); wal_free(&state->wal); @@ -1177,10 +1195,11 @@ int node_free(void *state_) { NodeState *state = state_; + term_and_vote_free(&state->term_and_vote); tcp_context_free(&state->tcp); client_table_free(&state->client_table); wal_free(&state->wal); - state_machine_free(&state->state_machine); + kvstore_free(&state->kvstore); return 0; } @@ -1192,6 +1211,8 @@ int node_tick(void *state_, void **ctxs, Time now = get_current_time(); if (now == INVALID_TIME) return -1; + if (now > state->now) + state->now = now; ///////////////////////////////////////////////////////////////// // Network events @@ -1217,11 +1238,15 @@ int node_tick(void *state_, void **ctxs, break; } - ret = process_message(state, conn_idx, msg_type, msg); - if (ret < 0) { + HandlerResult hret = process_message(state, conn_idx, msg_type, msg); + if (hret == HR_INVALID_MESSAGE) { tcp_close(&state->tcp, conn_idx); break; } + if (hret == HR_OUT_OF_MEMORY || hret == HR_IO_FAILURE) { + return -1; + } + assert(hret == HR_OK); tcp_consume_message(&state->tcp, conn_idx); } @@ -1233,25 +1258,28 @@ int node_tick(void *state_, void **ctxs, Time deadline = INVALID_TIME; if (state->role == ROLE_LEADER) { - Time watchdog_deadline = state->watchdog + HEARTBEAT_INTERVAL_SEC * 1000000000ULL; - if (now >= watchdog_deadline) { - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): heartbeat timeout, sending APPEND_ENTRIES to all peers", - TIME_VAL(now), self_idx(state)); + Time heartbeat_deadline = state->heartbeat + HEARTBEAT_INTERVAL_SEC * 1000000000ULL; + if (now >= heartbeat_deadline) { + node_log_simple(state, "HEARTBEAT"); for (int i = 0; i < state->num_nodes; i++) { if (i != self_idx(state)) send_append_entries_to_peer(state, i); } - state->watchdog = now; + state->heartbeat = now; + nearest_deadline(&deadline, now + HEARTBEAT_INTERVAL_SEC * 1000000000ULL); } else { - nearest_deadline(&deadline, watchdog_deadline); + nearest_deadline(&deadline, heartbeat_deadline); } } else { // Follower/Candidate: start election on leader timeout - Time death_deadline = state->watchdog + state->election_timeout; + Time death_deadline = state->heartbeat + state->election_timeout; if (now >= death_deadline) { - NODE_TRACE("[" TIME_FMT "] node %d (%s): election timeout expired, triggering election", - TIME_VAL(now), self_idx(state), role_name(state->role)); - start_election(state); + node_log_simple(state, "ELECTION TIMEOUT"); + HandlerResult hret = start_election(state); + if (hret != HR_OK) + return -1; + // start_election resets heartbeat and election_timeout + nearest_deadline(&deadline, state->heartbeat + state->election_timeout); } else { nearest_deadline(&deadline, death_deadline); } diff --git a/raft/node.h b/raft/node.h index 80853b1..75a25f7 100644 --- a/raft/node.h +++ b/raft/node.h @@ -7,6 +7,7 @@ #include "wal.h" #include "config.h" +#include "client_table.h" enum { MESSAGE_TYPE_REQUEST_VOTE, @@ -28,6 +29,7 @@ typedef struct { typedef struct { MessageHeader base; + int sender_idx; uint64_t term; uint8_t value; } VotedMessage; @@ -53,14 +55,15 @@ typedef struct { typedef struct { MessageHeader base; - Operation oper; + KVStoreOper oper; uint64_t client_id; uint64_t request_id; } RequestMessage; typedef struct { MessageHeader base; - OperationResult result; + KVStoreResult result; + uint64_t request_id; } ReplyMessage; typedef struct { @@ -68,20 +71,6 @@ typedef struct { int leader_idx; } RedirectMessage; -typedef struct { - uint64_t client_id; - uint64_t last_request_id; - OperationResult last_result; - bool pending; - int conn_tag; -} ClientTableEntry; - -typedef struct { - int count; - int capacity; - ClientTableEntry *entries; -} ClientTable; - typedef enum { ROLE_FOLLOWER, ROLE_CANDIDATE, @@ -90,46 +79,74 @@ typedef enum { typedef struct { - TCP tcp; - WAL wal; + // In-memory copy of the term and vote values. + // These must always be updated after the version + // stored on disk. + uint64_t term; + int voted_for; + // Handle to the file backing the term and vote + // values. + Handle handle; +} TermAndVote; + +typedef struct { + + // Networking subsystem + TCP tcp; + + // Static list of cluster nodes Address self_addr; Address node_addrs[NODE_LIMIT]; int num_nodes; + // Current loder of the node and the + // current leader. If no leader, -1. Role role; + int leader_idx; - uint64_t term; - int voted_for; - Handle term_and_vote_handle; + // Votes received when candidate. + // Each bit is associated to a node. The + // number of votes is obtained by counting + // set bits. This ensures nodes won't vote + // twice. + uint32_t votes; - // Index of the current leader - int leader_idx; + // Durable log subsystem + WAL wal; + + // Durable fixed-size data subsystem + TermAndVote term_and_vote; + + // Current election timeout. This value is relative + // and must be summed to the heartbeat in order to + // get the absolute election deadline. + uint64_t election_timeout; + + // This is the current value of the node. + // It is set at the start of each event + // handler call. + Time now; + + // If leader, this is the time when the last + // heartbeat was sent. If follower, this is + // the last time a heartbeat was received. + Time heartbeat; + + // The state machine to be replicated. + KVStore kvstore; + + // Table of client requests. This ensures request + // are applied in order. + ClientTable client_table; + int next_client_tag; int commit_index; int last_applied; - // When CANDIDATE - int votes_received; - - // When LEADER int next_indices[NODE_LIMIT]; int match_indices[NODE_LIMIT]; - // Relative timeout in nanoseconds - uint64_t election_timeout; - - // Last heartbeat time - uint64_t watchdog; - - // Keep track of client request order to enforce - // linearizability - ClientTable client_table; - int next_client_tag; - - // The state machine to be replicated - StateMachine state_machine; - } NodeState; struct pollfd; diff --git a/raft/wal.c b/raft/wal.c index 984211f..c5c3b68 100644 --- a/raft/wal.c +++ b/raft/wal.c @@ -4,10 +4,26 @@ #include #include +#include #include +#include #include "wal.h" +// FNV-1a checksum over all WALEntry fields except the checksum itself. +uint32_t wal_entry_checksum(WALEntry *entry) +{ + uint32_t h = 2166136261u; + const unsigned char *p = (const unsigned char *)entry; + // Hash all bytes up to (but not including) the checksum field + size_t len = offsetof(WALEntry, checksum); + for (size_t i = 0; i < len; i++) { + h ^= p[i]; + h *= 16777619u; + } + return h; +} + int wal_init(WAL *wal, string file) { Handle handle; @@ -21,25 +37,46 @@ int wal_init(WAL *wal, string file) return -1; } - if (size % sizeof(WALEntry) != 0) { + // Discard any partial trailing entry (crash during write). + int raw_count = size / sizeof(WALEntry); + size_t valid_size = raw_count * sizeof(WALEntry); + if (valid_size < size) { + file_truncate(handle, valid_size); + } + + WALEntry *entries = malloc(raw_count * sizeof(WALEntry)); + if (entries == NULL && raw_count > 0) { file_close(handle); return -1; } - int count = size / sizeof(WALEntry); + + if (file_set_offset(handle, 0) < 0) { + file_close(handle); + free(entries); + return -1; + } + + if (raw_count > 0 && file_read_exact(handle, (char*) entries, raw_count * sizeof(WALEntry)) < 0) { + file_close(handle); + free(entries); + return -1; + } + + // Verify checksums: truncate at the first corrupted entry. + // All entries from a corrupted one onward are discarded. + int count = raw_count; + for (int i = 0; i < raw_count; i++) { + if (entries[i].checksum != wal_entry_checksum(&entries[i])) { + count = i; + file_truncate(handle, count * sizeof(WALEntry)); + break; + } + } wal->count = count; - wal->capacity = count; - wal->entries = malloc(count * sizeof(WALEntry)); - if (wal->entries == NULL) { - file_close(handle); - return -1; - } - - if (file_read_exact(handle, (char*) wal->entries, count * sizeof(WALEntry)) < 0) { - file_close(handle); - return -1; - } - + wal->capacity = raw_count; // capacity >= count + wal->entries = entries; + wal->handle = handle; return 0; } @@ -61,12 +98,26 @@ int wal_append(WAL *wal, WALEntry *entry) wal->entries = p; } - // TODO: Should truncate file on partial writes - if (file_write_exact(wal->handle, (char*) entry, sizeof(*entry)) < 0) - return -1; + // Compute checksum before writing to disk + entry->checksum = wal_entry_checksum(entry); - if (file_sync(wal->handle) < 0) + if (file_write_exact(wal->handle, (char*) entry, sizeof(*entry)) < 0) { + // A partial write may have advanced the file offset. Truncate + // and rewind so the file stays consistent with the in-memory + // entry count. + file_truncate(wal->handle, wal->count * sizeof(WALEntry)); + file_set_offset(wal->handle, wal->count * sizeof(WALEntry)); return -1; + } + + if (file_sync(wal->handle) < 0) { + // The write succeeded but sync failed. Rewind the offset and + // truncate the phantom entry so the next append writes to the + // correct position. + file_truncate(wal->handle, wal->count * sizeof(WALEntry)); + file_set_offset(wal->handle, wal->count * sizeof(WALEntry)); + return -1; + } wal->entries[wal->count++] = *entry; return 0; diff --git a/raft/wal.h b/raft/wal.h index 498edfb..a506aff 100644 --- a/raft/wal.h +++ b/raft/wal.h @@ -3,14 +3,18 @@ #include -#include +#include typedef struct { - uint64_t term; - uint64_t client_id; - Operation oper; + uint64_t term; + uint64_t client_id; + uint64_t request_id; + KVStoreOper oper; + uint32_t checksum; } WALEntry; +uint32_t wal_entry_checksum(WALEntry *entry); + typedef struct { int count; int capacity; diff --git a/state_machine/kvstore.c b/state_machine/kvstore.c new file mode 100644 index 0000000..3e605f5 --- /dev/null +++ b/state_machine/kvstore.c @@ -0,0 +1,118 @@ +#if defined(MAIN_SIMULATION) || defined(MAIN_TEST) +#define QUAKEY_ENABLE_MOCKS +#endif + +#include +#include +#include + +#include "kvstore.h" + +void kvstore_init(KVStore *kvs) +{ + memset(kvs, 0, sizeof(*kvs)); +} + +void kvstore_free(KVStore *kvs) +{ + (void) kvs; +} + +static int find_entry(KVStore *kvs, char *key) +{ + for (int i = 0; i < kvs->count; i++) + if (!memcmp(kvs->entries[i].key, key, KVSTORE_KEY_SIZE)) + return i; + return -1; +} + +KVStoreResult kvstore_update(KVStore *kvs, KVStoreOper oper) +{ + KVStoreResult result; + switch (oper.type) { + case KVSTORE_OPER_NOOP: + result.type = KVSTORE_RESULT_OK; + result.val = 0; + break; + case KVSTORE_OPER_SET: + { + int i = find_entry(kvs, oper.key); + if (i < 0) { + if (kvs->count >= KVSTORE_ENTRY_LIMIT) { + result.type = KVSTORE_RESULT_FULL; + result.val = 0; + break; + } + i = kvs->count++; + memcpy(kvs->entries[i].key, oper.key, KVSTORE_KEY_SIZE); + } + kvs->entries[i].val = oper.val; + + result.type = KVSTORE_RESULT_OK; + result.val = 0; + } + break; + case KVSTORE_OPER_GET: + { + int i = find_entry(kvs, oper.key); + if (i < 0) { + result.type = KVSTORE_RESULT_MISSING; + result.val = 0; + } else { + result.type = KVSTORE_RESULT_OK; + result.val = kvs->entries[i].val; + } + } + break; + case KVSTORE_OPER_DEL: + { + int i = find_entry(kvs, oper.key); + if (i < 0) { + result.type = KVSTORE_RESULT_MISSING; + result.val = 0; + } else { + result.type = KVSTORE_RESULT_OK; + result.val = kvs->entries[i].val; + kvs->entries[i] = kvs->entries[--kvs->count]; + } + } + break; + default: + assert(0); + break; + } + + return result; +} + +void kvstore_dump_oper(KVStoreOper oper) +{ + switch (oper.type) { + case KVSTORE_OPER_NOOP: printf("NOOP"); break; + case KVSTORE_OPER_SET: printf("SET(%.16s, %lu)", oper.key, oper.val); break; + case KVSTORE_OPER_GET: printf("GET(%.16s)", oper.key); break; + case KVSTORE_OPER_DEL: printf("DEL(%.16s)", oper.key); break; + default: printf("???\n"); + } +} + +int kvstore_snprint_oper(char *buf, int size, KVStoreOper oper) +{ + switch (oper.type) { + case KVSTORE_OPER_NOOP: return snprintf(buf, size, "NOOP"); + case KVSTORE_OPER_SET: return snprintf(buf, size, "SET(%.16s, %lu)", oper.key, oper.val); + case KVSTORE_OPER_GET: return snprintf(buf, size, "GET(%.16s)", oper.key); + case KVSTORE_OPER_DEL: return snprintf(buf, size, "DEL(%.16s)", oper.key); + default: return snprintf(buf, size, "???"); + } +} + +int kvstore_snprint_result(char *buf, int size, KVStoreResult result) +{ + switch (result.type) { + case KVSTORE_RESULT_OK: return snprintf(buf, size, "OK(%lu)", result.val); + case KVSTORE_RESULT_FULL: return snprintf(buf, size, "FULL"); + case KVSTORE_RESULT_MISSING: return snprintf(buf, size, "MISSING"); + default: return snprintf(buf, size, "???"); + } +} diff --git a/state_machine/kvstore.h b/state_machine/kvstore.h new file mode 100644 index 0000000..db7051a --- /dev/null +++ b/state_machine/kvstore.h @@ -0,0 +1,51 @@ +#ifndef KVSTORE_INCLUDED +#define KVSTORE_INCLUDED + +#include + +#define KVSTORE_KEY_SIZE 16 +#define KVSTORE_ENTRY_LIMIT 64 + +typedef enum { + KVSTORE_OPER_NOOP, + KVSTORE_OPER_SET, + KVSTORE_OPER_GET, + KVSTORE_OPER_DEL, +} KVStoreOperType; + +typedef enum { + KVSTORE_RESULT_OK, + KVSTORE_RESULT_FULL, + KVSTORE_RESULT_MISSING, +} KVStoreResultType; + +typedef struct { + KVStoreOperType type; + char key[KVSTORE_KEY_SIZE]; + uint64_t val; +} KVStoreOper; + +typedef struct { + KVStoreResultType type; + uint64_t val; +} KVStoreResult; + +typedef struct { + char key[KVSTORE_KEY_SIZE]; + uint64_t val; +} KVEntry; + +typedef struct { + int count; + KVEntry entries[KVSTORE_ENTRY_LIMIT]; +} KVStore; + +void kvstore_init(KVStore *kvs); +void kvstore_free(KVStore *kvs); +KVStoreResult kvstore_update(KVStore *kvs, KVStoreOper oper); + +void kvstore_dump_oper(KVStoreOper oper); +int kvstore_snprint_oper(char *buf, int size, KVStoreOper oper); +int kvstore_snprint_result(char *buf, int size, KVStoreResult result); + +#endif // KVSTORE_INCLUDED diff --git a/state_machine/state_machine.c b/state_machine/state_machine.c deleted file mode 100644 index d7bb9e5..0000000 --- a/state_machine/state_machine.c +++ /dev/null @@ -1,25 +0,0 @@ -#if defined(MAIN_SIMULATION) || defined(MAIN_TEST) -#define QUAKEY_ENABLE_MOCKS -#endif - -#include -#include - -#include "state_machine.h" - -void state_machine_init(StateMachine *sm) -{ - (void)sm; -} - -void state_machine_free(StateMachine *sm) -{ - (void)sm; -} - -OperationResult state_machine_update(StateMachine *sm, Operation op) -{ - (void)sm; - (void)op; - return OPERATION_RESULT_X; -} diff --git a/state_machine/state_machine.h b/state_machine/state_machine.h deleted file mode 100644 index 959369f..0000000 --- a/state_machine/state_machine.h +++ /dev/null @@ -1,26 +0,0 @@ -#ifndef STATE_MACHINE_INCLUDED -#define STATE_MACHINE_INCLUDED - -typedef enum { - OPERATION_NOOP, - OPERATION_A, - OPERATION_B, - OPERATION_C, -} Operation; - -typedef enum { - OPERATION_RESULT_X, - OPERATION_RESULT_Y, - OPERATION_RESULT_Z, -} OperationResult; - -typedef struct { - -} StateMachine; - -void state_machine_init(StateMachine *sm); -void state_machine_free(StateMachine *sm); - -OperationResult state_machine_update(StateMachine *sm, Operation op); - -#endif // STATE_MACHINE_INCLUDED \ No newline at end of file diff --git a/table.txt b/table.txt new file mode 100644 index 0000000..5b27274 --- /dev/null +++ b/table.txt @@ -0,0 +1,247 @@ +Consensus Protocol Simulation Results +Simulated time: 1200s per run, seeds 1-100 +3 nodes, 2 clients, fault injection enabled, network partitioning enabled + +Column descriptions: + Seed - RNG seed used for the simulation run + Proto - Consensus protocol (VSR or Raft) + Invocations - Number of client requests initiated + OK - Requests that completed successfully with a response + Timeouts - Requests that timed out without a response + Rejected - Requests explicitly rejected (e.g. sent to a non-leader) + Checks - Linearizability checks performed by the checker + Steps - Total simulation scheduling steps (ticks across all hosts) + +Seed Proto Invocations OK Timeouts Rejected Checks Steps +----------------------------------------------------------------------- + 1 VSR 2244 2206 33 5 2244 105648 + 1 Raft 3276 1700 368 1206 3274 363190 + 2 VSR 2883 2839 39 5 2883 126828 + 2 Raft 3394 2761 285 346 3392 171163 + 3 VSR 592 497 94 1 592 42548 + 3 Raft 2789 2358 330 99 2787 150699 + 4 VSR 1274 1231 37 6 1274 78222 + 4 Raft 2068 1362 464 240 2066 88436 + 5 VSR 1405 1372 31 1 1404 75712 + 5 Raft 2304 1630 416 256 2302 131192 + 6 VSR 2025 1975 49 0 2024 169653 + 6 Raft 2182 1244 447 489 2180 378921 + 7 VSR 955 856 98 1 955 56039 + 7 Raft 3433 1609 311 1511 3431 297830 + 8 VSR 720 636 79 4 719 46945 + 8 Raft 2498 1759 436 301 2496 123015 + 9 VSR 859 780 77 2 859 56003 + 9 Raft 2778 1816 362 599 2777 225590 + 10 VSR 1486 1401 84 1 1486 95773 + 10 Raft 3114 2093 321 698 3112 341220 + 11 VSR 456 302 153 1 456 33396 + 11 Raft 3441 1209 375 1855 3439 345485 + 12 VSR 1220 1128 88 2 1218 66620 + 12 Raft 2555 1064 458 1031 2553 370909 + 13 VSR 863 753 108 1 862 52065 + 13 Raft 1965 1210 494 259 1963 162897 + 14 VSR 645 524 115 5 644 44976 + 14 Raft 2498 1918 399 179 2496 138682 + 15 VSR 690 638 50 1 689 48727 + 15 Raft 2541 1871 381 287 2539 200612 + 16 VSR 944 835 106 1 942 52517 + 16 Raft 2369 1451 466 450 2367 465559 + 17 VSR 647 564 80 2 646 40272 + 17 Raft 2446 1846 399 199 2444 124084 + 18 VSR 392 310 76 4 390 35414 + 18 Raft 1955 923 527 503 1953 218171 + 19 VSR 1165 1068 97 0 1165 60283 + 19 Raft 2987 1849 363 773 2985 230511 + 20 VSR 2229 2164 62 2 2228 108081 + 20 Raft 2996 1742 381 871 2994 450695 + 21 VSR 1390 1341 44 5 1390 78704 + 21 Raft 2441 1485 412 542 2439 120767 + 22 VSR 1844 1758 81 5 1844 96250 + 22 Raft 3561 1897 306 1356 3559 212082 + 23 VSR 1393 1335 55 3 1393 79177 + 23 Raft 2524 1496 434 593 2523 222489 + 24 VSR 971 951 18 0 969 56647 + 24 Raft 2177 1606 412 157 2175 177816 + 25 VSR 458 376 77 5 458 35323 + 25 Raft 2507 1898 374 233 2505 139076 + 26 VSR 1177 1117 60 0 1177 70344 + 26 Raft 2583 1978 365 238 2581 186689 + 27 VSR 1042 937 104 1 1042 70667 + 27 Raft 2794 2237 355 200 2792 171007 + 28 VSR 1118 1067 43 6 1116 67368 + 28 Raft 2790 1870 357 561 2788 257457 + 29 VSR 683 610 73 0 683 45166 + 29 Raft 2557 1439 408 708 2555 110388 + 30 VSR 1202 1134 63 3 1200 64864 + 30 Raft 3312 2297 316 697 3310 406253 + 31 VSR 1466 1399 65 2 1466 83025 + 31 Raft 2818 1612 377 827 2816 311506 + 32 VSR 1207 1161 41 5 1207 68520 + 32 Raft 2676 1141 416 1117 2674 255671 + 33 VSR 1219 1134 83 1 1218 65923 + 33 Raft 3260 2844 274 140 3258 191445 + 34 VSR 1255 1229 24 1 1254 71120 + 34 Raft 3311 1372 405 1532 3309 428477 + 35 VSR 1197 1142 50 4 1196 73779 + 35 Raft 2435 1793 418 222 2433 147736 + 36 VSR 1560 1500 55 4 1559 89849 + 36 Raft 2110 1186 515 407 2108 310505 + 37 VSR 1487 1424 58 4 1486 148383 + 37 Raft 3223 1407 335 1479 3221 242814 + 38 VSR 1397 1349 42 5 1396 76827 + 38 Raft 2466 1260 441 763 2464 352797 + 39 VSR 1304 1249 53 1 1303 78321 + 39 Raft 3027 2062 343 620 3025 334793 + 40 VSR 1299 1270 25 2 1297 72474 + 40 Raft 2183 1213 479 489 2181 229529 + 41 VSR 1091 1040 41 8 1089 65193 + 41 Raft 2856 2333 339 182 2854 162726 + 42 VSR 496 410 84 1 495 36493 + 42 Raft 2421 1797 400 222 2419 163015 + 43 VSR 658 562 92 2 656 46387 + 43 Raft 2834 2134 362 336 2832 161248 + 44 VSR 1372 1318 49 4 1371 75563 + 44 Raft 2654 2076 370 206 2652 262333 + 45 VSR 257 127 129 0 256 33593 + 45 Raft 3146 1319 366 1459 3144 395077 + 46 VSR 1515 1458 53 2 1513 105709 + 46 Raft 3320 1456 382 1480 3318 444523 + 47 VSR 1057 1017 39 0 1056 61117 + 47 Raft 2243 1351 467 423 2241 210836 + 48 VSR 1195 1140 51 3 1194 69487 + 48 Raft 2378 1708 422 246 2376 148188 + 49 VSR 950 876 71 2 949 55394 + 49 Raft 2984 2444 309 229 2982 153760 + 50 VSR 964 875 88 1 964 57668 + 50 Raft 2889 2295 344 248 2887 182648 + 51 VSR 1302 1250 49 1 1300 74028 + 51 Raft 2363 1734 415 212 2361 127568 + 52 VSR 1205 1111 91 2 1204 64727 + 52 Raft 2905 2380 303 221 2904 170346 + 53 VSR 869 744 124 0 868 95545 + 53 Raft 2203 964 444 794 2202 306208 + 54 VSR 408 333 72 3 408 36481 + 54 Raft 2113 1409 434 268 2111 103004 + 55 VSR 494 443 50 1 494 40161 + 55 Raft 2618 1937 375 305 2617 239299 + 56 VSR 1300 1231 66 2 1299 70686 + 56 Raft 3401 2723 282 394 3399 194017 + 57 VSR 238 145 93 0 238 34783 + 57 Raft 1941 1255 451 233 1939 90352 + 58 VSR 922 854 63 5 922 54772 + 58 Raft 2173 1303 448 420 2171 225395 + 59 VSR 1941 1853 84 3 1940 103258 + 59 Raft 2501 1237 420 842 2499 214547 + 60 VSR 1766 1645 114 5 1764 86384 + 60 Raft 2909 1062 437 1408 2907 446530 + 61 VSR 1630 1557 68 4 1629 76775 + 61 Raft 2956 2258 333 363 2954 199725 + 62 VSR 1077 1023 51 2 1076 107542 + 62 Raft 3418 1993 303 1120 3416 178317 + 63 VSR 2158 2107 47 3 2157 107086 + 63 Raft 2245 1039 473 731 2243 331394 + 64 VSR 1804 1743 53 7 1803 101345 + 64 Raft 2804 2152 325 325 2802 206594 + 65 VSR 934 825 106 1 932 77299 + 65 Raft 2279 1090 486 701 2277 266669 + 66 VSR 798 726 69 2 797 59313 + 66 Raft 2105 1135 444 524 2103 246688 + 67 VSR 965 874 91 0 965 71117 + 67 Raft 2268 1598 439 229 2266 103555 + 68 VSR 438 327 109 1 437 54528 + 68 Raft 2787 1755 395 635 2785 347905 + 69 VSR 922 869 52 1 922 61234 + 69 Raft 2588 1752 425 409 2586 218784 + 70 VSR 720 607 110 3 720 47228 + 70 Raft 2424 1495 414 513 2422 255104 + 71 VSR 1067 982 81 4 1067 62847 + 71 Raft 2207 1583 398 224 2205 165271 + 72 VSR 673 561 110 0 671 48927 + 72 Raft 2927 2052 348 525 2925 145377 + 73 VSR 1361 1270 88 2 1360 70464 + 73 Raft 2798 1976 353 467 2796 131273 + 74 VSR 1891 1842 43 5 1890 104058 + 74 Raft 2176 1640 405 129 2174 123942 + 75 VSR 970 879 91 0 970 86026 + 75 Raft 2456 879 491 1084 2454 380910 + 76 VSR 851 737 111 2 850 55131 + 76 Raft 3226 1945 343 936 3224 158287 + 77 VSR 610 474 133 2 609 40458 + 77 Raft 2492 1882 387 221 2490 134293 + 78 VSR 1269 1232 31 6 1269 69782 + 78 Raft 3411 1575 329 1506 3410 238137 + 79 VSR 921 859 62 0 921 55960 + 79 Raft 3008 2516 335 155 3006 176544 + 80 VSR 1271 1230 36 5 1271 77391 + 80 Raft 2605 1033 426 1144 2603 287940 + 81 VSR 835 708 124 2 834 52299 + 81 Raft 2582 1845 361 374 2580 140619 + 82 VSR 1024 913 109 1 1023 58016 + 82 Raft 2921 2264 330 325 2919 143004 + 83 VSR 922 802 120 0 922 51388 + 83 Raft 2600 1885 412 301 2598 129191 + 84 VSR 1533 1480 52 1 1533 79724 + 84 Raft 2344 1753 440 149 2342 129605 + 85 VSR 1650 1588 58 4 1650 88562 + 85 Raft 3366 1419 355 1590 3364 379641 + 86 VSR 884 763 118 1 882 49372 + 86 Raft 2736 1258 457 1019 2734 552128 + 87 VSR 1072 1003 68 0 1071 59323 + 87 Raft 1875 968 506 399 1873 253771 + 88 VSR 1493 1437 52 4 1493 92016 + 88 Raft 1902 1285 445 170 1900 109923 + 89 VSR 1294 1239 53 0 1292 69379 + 89 Raft 1922 1204 471 245 1920 91616 + 90 VSR 1215 1119 93 2 1214 67086 + 90 Raft 3440 2057 296 1085 3438 284840 + 91 VSR 2176 2142 28 6 2176 108769 + 91 Raft 2606 2025 358 221 2604 136452 + 92 VSR 594 550 42 0 592 43714 + 92 Raft 2563 1504 432 625 2561 370793 + 93 VSR 775 699 76 0 775 67757 + 93 Raft 1990 826 509 653 1988 320932 + 94 VSR 546 455 88 3 546 35972 + 94 Raft 2449 1686 399 362 2447 216855 + 95 VSR 420 326 94 0 420 33058 + 95 Raft 2506 1891 379 234 2504 141706 + 96 VSR 583 509 70 4 583 40050 + 96 Raft 2307 1263 473 569 2305 325134 + 97 VSR 1991 1965 21 3 1989 95473 + 97 Raft 2679 1360 397 920 2677 281323 + 98 VSR 1198 1123 73 2 1198 78181 + 98 Raft 2550 1467 467 614 2548 416874 + 99 VSR 954 884 67 3 954 72020 + 99 Raft 2051 1356 481 212 2049 102556 + 100 VSR 1426 1319 105 1 1425 76369 + 100 Raft 2817 1402 440 973 2815 474134 +----------------------------------------------------------------------- + +Summary Statistics + +VSR (100 completed runs, 0 violations): + Avg invocations: 1132.8 + Avg ok: 1057.4 + Avg timeouts: 72.3 + Avg rejected: 2.3 + Avg steps: 69089.2 + Total invocations: 113278 + Total ok: 105742 + Total timeouts: 7226 + Total rejected: 234 + OK rate: 93.3% + Timeout rate: 6.4% + Rejection rate: 0.2% + +Raft (100 completed runs, 0 violations): + Avg invocations: 2645.8 + Avg ok: 1664.9 + Avg timeouts: 397.6 + Avg rejected: 581.4 + Avg steps: 234875.8 + Total invocations: 264582 + Total ok: 166491 + Total timeouts: 39755 + Total rejected: 58142 + OK rate: 62.9% + Timeout rate: 15.0% + Rejection rate: 22.0% diff --git a/vsr/client.c b/vsr/client.c index 870f831..d589de0 100644 --- a/vsr/client.c +++ b/vsr/client.c @@ -6,18 +6,68 @@ #include #include -#include - #include "node.h" #include "client.h" //#define CLIENT_TRACE(fmt, ...) {} #define CLIENT_TRACE(fmt, ...) fprintf(stderr, "CLIENT: " fmt "\n", ##__VA_ARGS__); +#define KEY_POOL_SIZE 128 + +static uint64_t next_client_id = 1; + +static uint64_t client_random(void) +{ +#if defined(MAIN_SIMULATION) || defined(MAIN_TEST) + return quakey_random(); +#else + return (uint64_t)rand(); +#endif +} + +static KVStoreOper random_oper(void) +{ + KVStoreOper oper = {0}; + snprintf(oper.key, KVSTORE_KEY_SIZE, "k%d", (int)(client_random() % KEY_POOL_SIZE)); + + switch (client_random() % 3) { + case 0: + oper.type = KVSTORE_OPER_SET; + oper.val = client_random(); + break; + case 1: + oper.type = KVSTORE_OPER_GET; + break; + case 2: + oper.type = KVSTORE_OPER_DEL; + break; + } + return oper; +} + // Format time as seconds with 3 decimal places for trace output -#define TIME_FMT "%.3fs" +#define TIME_FMT "%7.3fs" #define TIME_VAL(t) ((double)(t) / 1000000000.0) +static void client_log_impl(ClientState *state, Time now, const char *event, const char *detail) +{ + printf("[" TIME_FMT "] CLIENT %lu | V%-3lu | %-20s %s\n", + TIME_VAL(now), + state->client_id, + state->view_number, + event, + detail ? detail : ""); +} + +#define client_log(state, now, event, fmt, ...) do { \ + char _detail[256]; \ + snprintf(_detail, sizeof(_detail), fmt, ##__VA_ARGS__); \ + client_log_impl(state, now, event, _detail); \ +} while (0) + +#define client_log_simple(state, now, event) \ + client_log_impl(state, now, event, NULL) + static int leader_idx(ClientState *state) { return state->view_number % state->num_servers; @@ -29,24 +79,61 @@ process_message(ClientState *state, { (void) conn_idx; + if (type == MESSAGE_TYPE_REDIRECT) { + RedirectMessage redirect_message; + if (msg.len != sizeof(RedirectMessage)) + return -1; + memcpy(&redirect_message, msg.ptr, sizeof(redirect_message)); + + if (redirect_message.view_number > state->view_number) { + Time now = get_current_time(); + client_log(state, now, "RECV REDIRECT", "view=%lu -> %lu leader=%d", + (unsigned long)state->view_number, + (unsigned long)redirect_message.view_number, + (int)(redirect_message.view_number % state->num_servers)); + state->view_number = redirect_message.view_number; + state->last_was_rejected = true; + state->last_was_timeout = false; + state->pending = false; + } + return 0; + } + if (!state->pending) return -1; if (type != MESSAGE_TYPE_REPLY) return -1; - ReplyMessage reply_message; + ReplyMessage message; if (msg.len != sizeof(ReplyMessage)) return -1; - memcpy(&reply_message, msg.ptr, sizeof(reply_message)); + memcpy(&message, msg.ptr, sizeof(message)); + + // Ignore stale replies from previous requests. After a timeout + // the client moves to a new view and sends a new request, but + // the old leader may still deliver a reply for the old request + // on the previous connection. Without this check the client + // would accept the stale result for the wrong operation. + if (message.request_id != state->request_id) + return 0; { Time now = get_current_time(); - CLIENT_TRACE("[" TIME_FMT "] received REPLY (rejected=%s)", - TIME_VAL(now), - reply_message.rejected ? "true" : "false"); + char oper_buf[64]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), state->last_oper); + if (message.rejected) { + client_log(state, now, "RECV REPLY", "key=%.16s %s -> REJECTED", state->last_oper.key, oper_buf); + } else { + char result_buf[64]; + kvstore_snprint_result(result_buf, sizeof(result_buf), message.result); + client_log(state, now, "RECV REPLY", "key=%.16s %s -> %s", state->last_oper.key, oper_buf, result_buf); + } } + state->last_result = message.result; + state->last_was_timeout = false; + state->last_was_rejected = message.rejected; state->pending = false; return 0; } @@ -92,35 +179,9 @@ int client_init(void *state_, int argc, char **argv, state->view_number = 0; state->request_id = 0; + state->reconnect_time = 0; - // Load or generate a persistent client_id from disk. - // This ensures the client_id survives process restarts. - { - string path = S("client_id"); - Handle fd; - bool loaded = false; - if (file_exists(path)) { - if (file_open(path, &fd) == 0) { - file_set_offset(fd, 0); - uint64_t saved_id; - if (file_read_exact(fd, (char*)&saved_id, sizeof(saved_id)) == (int)sizeof(saved_id)) { - state->client_id = saved_id; - loaded = true; - } - file_close(fd); - } - } - if (!loaded) { - Time now = get_current_time(); - state->client_id = (uint64_t)now; - if (file_open(path, &fd) == 0) { - file_set_offset(fd, 0); - file_write_exact(fd, (char*)&state->client_id, sizeof(state->client_id)); - file_sync(fd); - file_close(fd); - } - } - } + state->client_id = next_client_id++; // Connect to all known servers for (int i = 0; i < state->num_servers; i++) { @@ -133,8 +194,7 @@ int client_init(void *state_, int argc, char **argv, { Time now = get_current_time(); - CLIENT_TRACE("[" TIME_FMT "] initialized: num_servers=%d, leader_idx=%d", - TIME_VAL(now), state->num_servers, leader_idx(state)); + client_log(state, now, "INIT", "servers=%d leader=%d", state->num_servers, leader_idx(state)); } *timeout = 0; @@ -155,20 +215,24 @@ int client_tick(void *state_, void **ctxs, int num_events = tcp_translate_events(&state->tcp, events, ctxs, pdata, *pnum); for (int i = 0; i < num_events; i++) { + if (events[i].type == EVENT_DISCONNECT) { int conn_idx = events[i].conn_idx; int tag = tcp_get_tag(&state->tcp, conn_idx); if (tag == leader_idx(state) && state->pending) { Time now = get_current_time(); - CLIENT_TRACE("[" TIME_FMT "] lost connection to leader (node %d), resetting pending request", - TIME_VAL(now), leader_idx(state)); + client_log(state, now, "DISCONNECT", "key=%.16s lost leader (node %d)", state->last_oper.key, leader_idx(state)); + state->last_was_timeout = true; + state->last_was_rejected = false; state->pending = false; } tcp_close(&state->tcp, conn_idx); continue; } + if (events[i].type != EVENT_MESSAGE) continue; + int conn_idx = events[i].conn_idx; for (;;) { @@ -201,10 +265,16 @@ int client_tick(void *state_, void **ctxs, if (state->pending) { Time request_deadline = state->request_time + PRIMARY_DEATH_TIMEOUT_SEC * 1000000000ULL; if (request_deadline <= now) { - CLIENT_TRACE("[" TIME_FMT "] request to leader (node %d, view=%lu) timed out, trying next server", - TIME_VAL(now), leader_idx(state), - (unsigned long)state->view_number); + + { + char oper_buf[64]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), state->last_oper); + client_log(state, now, "TIMEOUT", "key=%.16s %s", state->last_oper.key, oper_buf); + } + state->view_number++; + state->last_was_timeout = true; + state->last_was_rejected = false; state->pending = false; } } @@ -213,15 +283,15 @@ int client_tick(void *state_, void **ctxs, int conn_idx = tcp_index_from_tag(&state->tcp, leader_idx(state)); if (conn_idx < 0) { - // Leader connection not available, try reconnecting - { - CLIENT_TRACE("[" TIME_FMT "] leader (node %d) not connected, reconnecting", - TIME_VAL(now), leader_idx(state)); + if (state->reconnect_time <= now) { + tcp_connect(&state->tcp, state->server_addrs[leader_idx(state)], leader_idx(state), NULL); + state->reconnect_time = now + HEARTBEAT_INTERVAL_SEC * 1000000000ULL; } - tcp_connect(&state->tcp, state->server_addrs[leader_idx(state)], leader_idx(state), NULL); } else { + // Now start a new operation state->request_id++; + state->last_oper = random_oper(); RequestMessage request_message = { .base = { @@ -229,7 +299,7 @@ int client_tick(void *state_, void **ctxs, .type = MESSAGE_TYPE_REQUEST, .length = sizeof(RequestMessage), }, - .oper = OPERATION_A, + .oper = state->last_oper, .client_id = state->client_id, .request_id = state->request_id, }; @@ -240,11 +310,9 @@ int client_tick(void *state_, void **ctxs, byte_queue_write(output, &request_message, request_message.base.length); { - CLIENT_TRACE("[" TIME_FMT "] sent REQUEST to leader (node %d, view=%lu, client_id=%lu, req_id=%lu)", - TIME_VAL(now), leader_idx(state), - (unsigned long)state->view_number, - (unsigned long)state->client_id, - (unsigned long)state->request_id); + char oper_buf[64]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), state->last_oper); + client_log(state, now, "SEND REQUEST", "key=%.16s %s", state->last_oper.key, oper_buf); } state->pending = true; @@ -252,10 +320,15 @@ int client_tick(void *state_, void **ctxs, } } - // Set timeout based on pending request deadline + // Set timeout based on pending request deadline or reconnection delay Time deadline = INVALID_TIME; if (state->pending) { nearest_deadline(&deadline, state->request_time + PRIMARY_DEATH_TIMEOUT_SEC * 1000000000ULL); + } else { + int conn_idx = tcp_index_from_tag(&state->tcp, leader_idx(state)); + if (conn_idx < 0 && state->reconnect_time > now) { + nearest_deadline(&deadline, state->reconnect_time); + } } *timeout = deadline_to_timeout(deadline, now); if (pcap < TCP_POLL_CAPACITY) @@ -268,6 +341,11 @@ int client_free(void *state_) { ClientState *state = state_; + { + Time now = get_current_time(); + client_log_simple(state, now, "CRASHED"); + } + tcp_context_free(&state->tcp); return 0; } diff --git a/vsr/client.h b/vsr/client.h index 40daccc..e6d6504 100644 --- a/vsr/client.h +++ b/vsr/client.h @@ -4,6 +4,8 @@ #include #include +#include + #include "config.h" typedef struct { @@ -14,6 +16,14 @@ typedef struct { bool pending; Time request_time; // When the current request was sent + // The operation sent in the current pending request (for logging) + KVStoreOper last_oper; + + // Linearizability checker support + KVStoreResult last_result; + bool last_was_timeout; + bool last_was_rejected; + Address server_addrs[NODE_LIMIT]; int num_servers; @@ -22,6 +32,8 @@ typedef struct { uint64_t client_id; uint64_t request_id; + Time reconnect_time; // Earliest time to retry connecting to leader + } ClientState; struct pollfd; diff --git a/vsr/client_table.c b/vsr/client_table.c index 1094734..0ac8415 100644 --- a/vsr/client_table.c +++ b/vsr/client_table.c @@ -28,7 +28,7 @@ ClientTableEntry *client_table_find(ClientTable *client_table, uint64_t client_i return NULL; } -int client_table_add(ClientTable *client_table, uint64_t client_id, uint64_t request_id, int conn_idx) +int client_table_add(ClientTable *client_table, uint64_t client_id, uint64_t request_id, int conn_tag) { if (client_table->count == client_table->capacity) { int n = 2 * client_table->capacity; @@ -44,7 +44,7 @@ int client_table_add(ClientTable *client_table, uint64_t client_id, uint64_t req .client_id = client_id, .last_request_id = request_id, .pending = true, - .conn_idx = conn_idx, + .conn_tag = conn_tag, }; return 0; } diff --git a/vsr/client_table.h b/vsr/client_table.h index 4c39f2b..20026d6 100644 --- a/vsr/client_table.h +++ b/vsr/client_table.h @@ -3,14 +3,17 @@ #include -#include +#include typedef struct { uint64_t client_id; uint64_t last_request_id; - OperationResult last_result; - bool pending; - int conn_idx; + KVStoreResult last_result; + bool pending; // Only meaningful on the leader that received + // the REQUEST. After a view change, a new leader + // may find stale entries with pending=false from + // a previous view when it was leader before. + int conn_tag; } ClientTableEntry; typedef struct { @@ -22,7 +25,7 @@ typedef struct { void client_table_init(ClientTable *client_table); void client_table_free(ClientTable *client_table); ClientTableEntry *client_table_find(ClientTable *client_table, uint64_t client_id); -int client_table_add(ClientTable *client_table, uint64_t client_id, uint64_t request_id, int conn_idx); +int client_table_add(ClientTable *client_table, uint64_t client_id, uint64_t request_id, int conn_tag); int client_table_insert(ClientTable *client_table, uint64_t client_id, uint64_t request_id); #endif // CLIENT_TABLE_INCLUDED \ No newline at end of file diff --git a/vsr/config.h b/vsr/config.h index 09d352c..f188dfb 100644 --- a/vsr/config.h +++ b/vsr/config.h @@ -5,7 +5,9 @@ #define FUTURE_LIMIT 32 #define HEARTBEAT_INTERVAL_SEC 1 #define PRIMARY_DEATH_TIMEOUT_SEC 5 +#define VIEW_CHANGE_TIMEOUT_SEC 10 #define RECOVERY_TIMEOUT_SEC 3 #define RECOVERY_ATTEMPT_LIMIT 10 +#define STATE_TRANSFER_TIMEOUT_SEC 2 #endif // CONFIG_INCLUDED \ No newline at end of file diff --git a/vsr/invariant_checker.c b/vsr/invariant_checker.c new file mode 100644 index 0000000..622add7 --- /dev/null +++ b/vsr/invariant_checker.c @@ -0,0 +1,395 @@ +// VSR invariant checker with external shadow log tracking. +// +// This file runs in the main simulation loop outside Quakey-scheduled +// processes. It includes node.h for struct definitions, then restores +// real allocators since mock_malloc/realloc/free abort outside process +// context. + +#include "node.h" + +#include + +// Restore real allocators (see checker/linearizability.c for precedent). +#undef malloc +#undef realloc +#undef free +#include + +// These helpers are static in node.c; duplicated here for the checker. + +static int self_idx(NodeState *state) +{ + for (int i = 0; i < state->num_nodes; i++) + if (addr_eql(state->node_addrs[i], state->self_addr)) + return i; + UNREACHABLE; +} + +static int leader_idx(NodeState *state) +{ + return state->view_number % state->num_nodes; +} + +static bool is_leader(NodeState *state) +{ + if (state->status == STATUS_RECOVERY) + return false; + return self_idx(state) == leader_idx(state); +} + +static int shadow_log_append(InvariantChecker *ic, KVStoreOper oper) +{ + if (ic->shadow_count == ic->shadow_capacity) { + int n = 2 * ic->shadow_capacity; + if (n < 8) + n = 8; + KVStoreOper *p = realloc(ic->shadow_log, n * sizeof(KVStoreOper)); + if (p == NULL) + return -1; + ic->shadow_log = p; + ic->shadow_capacity = n; + } + ic->shadow_log[ic->shadow_count++] = oper; + return 0; +} + +void invariant_checker_init(InvariantChecker *ic) +{ + ic->last_min_commit = -1; + ic->last_max_commit = -1; + for (int i = 0; i < NODE_LIMIT; i++) + ic->prev_status[i] = STATUS_NORMAL; + ic->shadow_log = NULL; + ic->shadow_count = 0; + ic->shadow_capacity = 0; +} + +void invariant_checker_free(InvariantChecker *ic) +{ + fprintf(stderr, "INVARIANT CHECKER: shadow log tracked %d committed entries\n", + ic->shadow_count); + free(ic->shadow_log); +} + +void invariant_checker_run(InvariantChecker *ic, NodeState **nodes, int num_nodes) +{ + int min_commit = -1; + int max_commit = -1; + + bool primary = false; + uint64_t primary_view_number = 0; + + bool min_commit_just_recovered = false; + + uint64_t max_view_number = 0; + for (int i = 0; i < num_nodes; i++) { + if (nodes[i]) + max_view_number = MAX(max_view_number, nodes[i]->view_number); + } + + for (int i = 0; i < num_nodes; i++) { + NodeState *n = nodes[i]; + if (n == NULL || n->status == STATUS_RECOVERY) + continue; + + if (min_commit < 0 || min_commit > n->commit_index) { + min_commit = n->commit_index; + min_commit_just_recovered = (ic->prev_status[i] == STATUS_RECOVERY); + } + + if (max_commit < 0 || max_commit < n->commit_index) { + max_commit = n->commit_index; + } + + if (is_leader(n) && n->view_number > primary_view_number) { + primary = true; + primary_view_number = n->view_number; + } + } + + // If the primary isn't up to date, it's not the + // real primary. + if (primary_view_number < max_view_number) + primary = false; + + if (min_commit < 0) { + assert(ic->last_min_commit == -1); + } else { + // The minimum number of committed entries should + // only increase, but there are some corner-cases + // when this is not true. + // When a node completes the recovery state, its + // log is technically outdated as it was sent some + // point in the past. If operations are committed + // while the recovery response is in transit over + // the network, the minimum number of committed + // entries will decrease. + if (!min_commit_just_recovered) { + assert(ic->last_min_commit <= min_commit); + } + } + + if (max_commit < 0) { + assert(ic->last_max_commit == -1); + } else { + // The maximum number of committed entries + // should only increase. The primary generally + // has more committed entries than replicas. If + // the primary dies, the maximum commit number + // of the live nodes may decrease. This is still + // okay since the new primary will commit up to + // that point as the view change completes. This + // implies that the maximum commit number should + // always increase unless there is no primary. + if (!primary) { + max_commit = ic->last_max_commit; + } else { + //assert(ic->last_max_commit <= max_commit); + } + } + + ic->last_min_commit = min_commit; + ic->last_max_commit = max_commit; + for (int i = 0; i < num_nodes; i++) { + if (nodes[i]) + ic->prev_status[i] = nodes[i]->status; + } + + for (int i = 0; i < num_nodes; i++) { + NodeState *s = nodes[i]; + if (s == NULL) + continue; + + // 1. commit_index <= log.count + // A node cannot have committed more entries than it has in its log. + if (s->commit_index > s->log.count) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: commit_index (%d) > log.count (%d)\n", + i, s->commit_index, s->log.count); + __builtin_trap(); + } + + // 2. commit_index >= 0 + if (s->commit_index < 0) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: commit_index (%d) < 0\n", + i, s->commit_index); + __builtin_trap(); + } + + // 4. Future buffer count is in valid range. + if (s->num_future < 0 || s->num_future > FUTURE_LIMIT) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: num_future (%d) out of range [0, %d]\n", + i, s->num_future, FUTURE_LIMIT); + __builtin_trap(); + } + + // 7. last_normal_view <= view_number + // The most recent view in which this node was in NORMAL status + // cannot exceed its current view number. + if (s->last_normal_view > s->view_number) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: last_normal_view (%lu) > view_number (%lu)\n", + i, (unsigned long)s->last_normal_view, (unsigned long)s->view_number); + __builtin_trap(); + } + + // 8. When status is NORMAL, last_normal_view must equal view_number. + // Every transition to NORMAL status sets last_normal_view = view_number. + // If they diverge while in NORMAL, a transition forgot to update it. + if (s->status == STATUS_NORMAL && s->last_normal_view != s->view_number) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: status is NORMAL but " + "last_normal_view (%lu) != view_number (%lu)\n", + i, (unsigned long)s->last_normal_view, (unsigned long)s->view_number); + __builtin_trap(); + } + + // 9. Log entry view numbers must not exceed the node's current view. + // Entries are created in the view they were proposed. No entry + // should carry a view number from the future. + for (int k = 0; k < s->log.count; k++) { + if ((uint64_t)s->log.entries[k].view_number > s->view_number) { + fprintf(stderr, "INVARIANT VIOLATED: node %d: log[%d].view_number (%d) " + "> view_number (%lu)\n", + i, k, s->log.entries[k].view_number, + (unsigned long)s->view_number); + __builtin_trap(); + } + } + + // 10. For a leader in NORMAL status, every uncommitted log entry + // must have the leader's own vote bit set. The leader always + // votes for its own entries. + if (s->status == STATUS_NORMAL && is_leader(s)) { + int idx = self_idx(s); + for (int k = s->commit_index; k < s->log.count; k++) { + if (!(s->log.entries[k].votes & (1 << idx))) { + fprintf(stderr, "INVARIANT VIOLATED: node %d (leader): " + "uncommitted log[%d] missing leader's own vote bit\n", + i, k); + __builtin_trap(); + } + } + } + } + + // Cross-node invariants + + // 5. At most one leader in normal status per view. + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL || nodes[i]->status != STATUS_NORMAL || !is_leader(nodes[i])) + continue; + for (int j = i + 1; j < num_nodes; j++) { + if (nodes[j] == NULL || nodes[j]->status != STATUS_NORMAL || !is_leader(nodes[j])) + continue; + if (nodes[i]->view_number == nodes[j]->view_number) { + fprintf(stderr, "INVARIANT VIOLATED: two normal leaders in view %lu: node %d and node %d\n", + (unsigned long)nodes[i]->view_number, i, j); + __builtin_trap(); + } + } + } + + // 6. Committed prefix agreement (State Machine Safety). + // For any two nodes, their logs must agree on all entries up to + // min(commit_index_i, commit_index_j). This is the core safety + // property of VSR: all committed operations are identical across + // replicas. + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) + continue; + for (int j = i + 1; j < num_nodes; j++) { + if (nodes[j] == NULL) + continue; + + int mc = nodes[i]->commit_index; + if (nodes[j]->commit_index < mc) + mc = nodes[j]->commit_index; + + for (int k = 0; k < mc; k++) { + if (memcmp(&nodes[i]->log.entries[k].oper, &nodes[j]->log.entries[k].oper, sizeof(KVStoreOper)) != 0) { + fprintf(stderr, "INVARIANT VIOLATED: committed log operation mismatch at index %d " + "between node %d and node %d\n", k, i, j); + __builtin_trap(); + } + } + } + } + + //////////////////////////////////////////////////////////////////// + // Shadow log: external commit tracking + //////////////////////////////////////////////////////////////////// + + // Phase 1: Find the observed max commit index and a source node. + int observed_max_commit = 0; + int source_node_idx = -1; + + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) + continue; + if (nodes[i]->status == STATUS_RECOVERY) + continue; + if (nodes[i]->commit_index > observed_max_commit) { + observed_max_commit = nodes[i]->commit_index; + source_node_idx = i; + } + } + + // Phase 2: Append newly committed entries to the shadow log. + if (source_node_idx >= 0 && observed_max_commit > ic->shadow_count) { + + NodeState *source = nodes[source_node_idx]; + assert(source->log.count >= observed_max_commit); + + for (int k = ic->shadow_count; k < observed_max_commit; k++) { + + KVStoreOper *source_oper = &source->log.entries[k].oper; + + // Cross-validate against other live non-recovering nodes + // that have also committed this entry. + for (int j = 0; j < num_nodes; j++) { + if (j == source_node_idx) + continue; + if (nodes[j] == NULL) + continue; + if (nodes[j]->status == STATUS_RECOVERY) + continue; + if (nodes[j]->commit_index <= k) + continue; + if (nodes[j]->log.count <= k) + continue; + + if (memcmp(&nodes[j]->log.entries[k].oper, source_oper, sizeof(KVStoreOper)) != 0) { + fprintf(stderr, "INVARIANT VIOLATED: committed entry mismatch at index %d " + "between source node %d and node %d during shadow log append\n", + k, source_node_idx, j); + __builtin_trap(); + } + } + + if (shadow_log_append(ic, *source_oper) < 0) { + fprintf(stderr, "INVARIANT CHECKER: shadow log allocation failed\n"); + __builtin_trap(); + } + } + } + + // Phase 3: Verify shadow log against the cluster. + + // Sub-check A: Committed entries must match the shadow log. + for (int k = 0; k < ic->shadow_count; k++) { + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) + continue; + if (nodes[i]->log.count <= k) + continue; + if (nodes[i]->commit_index <= k) + continue; + + if (memcmp(&nodes[i]->log.entries[k].oper, &ic->shadow_log[k], sizeof(KVStoreOper)) != 0) { + char shadow_buf[128], node_buf[128]; + kvstore_snprint_oper(shadow_buf, sizeof(shadow_buf), ic->shadow_log[k]); + kvstore_snprint_oper(node_buf, sizeof(node_buf), nodes[i]->log.entries[k].oper); + fprintf(stderr, "INVARIANT VIOLATED: shadow log mismatch at index %d on node %d\n" + " shadow: %s\n" + " node: %s\n", + k, i, shadow_buf, node_buf); + __builtin_trap(); + } + } + } + + // Sub-check B: When commit regresses, previously committed entries + // must still be held by a majority of the cluster. + // Recovering nodes are treated like dead nodes: they haven't + // restored their log yet and may still recover the entry through + // the recovery protocol. + if (observed_max_commit < ic->shadow_count) { + for (int k = observed_max_commit; k < ic->shadow_count; k++) { + int holders = 0; + int num_dead = 0; + + for (int i = 0; i < num_nodes; i++) { + if (nodes[i] == NULL) { + num_dead++; + continue; + } + if (nodes[i]->status == STATUS_RECOVERY) { + num_dead++; + continue; + } + if (nodes[i]->log.count <= k) + continue; + if (memcmp(&nodes[i]->log.entries[k].oper, &ic->shadow_log[k], sizeof(KVStoreOper)) == 0) + holders++; + } + + if (holders + num_dead <= num_nodes / 2) { + char oper_buf[128]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), ic->shadow_log[k]); + fprintf(stderr, "INVARIANT VIOLATED: previously committed entry at index %d " + "no longer held by majority (holders=%d, dead=%d, total=%d)\n" + " entry: %s\n", + k, holders, num_dead, num_nodes, oper_buf); + __builtin_trap(); + } + } + } +} diff --git a/vsr/log.c b/vsr/log.c index 276da6d..36f9aa2 100644 --- a/vsr/log.c +++ b/vsr/log.c @@ -13,11 +13,29 @@ void log_init(Log *log) log->entries = NULL; } +int log_init_from_network(Log *log, void *src, int num) +{ + log->count = num; + log->capacity = num; + log->entries = malloc(num * sizeof(LogEntry)); + if (log->entries == NULL) + return -1; + memcpy(log->entries, src, num * sizeof(LogEntry)); + return 0; +} + void log_free(Log *log) { free(log->entries); } +void log_move(Log *dst, Log *src) +{ + log_free(dst); + *dst = *src; + log_init(src); +} + int log_append(Log *log, LogEntry entry) { if (log->count == log->capacity) { diff --git a/vsr/log.h b/vsr/log.h index 23d0521..1fee700 100644 --- a/vsr/log.h +++ b/vsr/log.h @@ -1,15 +1,16 @@ #ifndef LOG_INCLUDED #define LOG_INCLUDED -#include +#include #include "config.h" typedef struct { - Operation oper; + KVStoreOper oper; uint32_t votes; int view_number; uint64_t client_id; + uint64_t request_id; } LogEntry; _Static_assert(NODE_LIMIT <= 32, ""); @@ -21,7 +22,9 @@ typedef struct { } Log; void log_init(Log *log); +int log_init_from_network(Log *log, void *src, int num); void log_free(Log *log); +void log_move(Log *dst, Log *src); int log_append(Log *log, LogEntry entry); #endif // LOG_INCLUDED \ No newline at end of file diff --git a/vsr/main.c b/vsr/main.c index c8ea3bd..374c28b 100644 --- a/vsr/main.c +++ b/vsr/main.c @@ -4,7 +4,7 @@ #include #include #include - +#include #include "node.h" #include "client.h" @@ -16,12 +16,23 @@ static void sigint_handler(int sig) simulation_running = 0; } -int main(void) +int main(int argc, char **argv) { signal(SIGINT, sigint_handler); + QuakeyUInt64 seed = 1; + QuakeyUInt64 time_limit_ns = 0; // 0 means no limit + + for (int i = 1; i < argc; i++) { + if (strcmp(argv[i], "--seed") == 0 && i + 1 < argc) { + seed = strtoull(argv[++i], NULL, 10); + } else if (strcmp(argv[i], "--time") == 0 && i + 1 < argc) { + time_limit_ns = strtoull(argv[++i], NULL, 10) * 1000000000ULL; + } + } + Quakey *quakey; - int ret = quakey_init(&quakey, 1); + int ret = quakey_init(&quakey, seed); if (ret < 0) return -1; @@ -111,7 +122,18 @@ int main(void) node_3 = quakey_spawn(quakey, config, "nd --peer 127.0.0.4:8080 --peer 127.0.0.5:8080 --addr 127.0.0.6:8080"); } - while (simulation_running) { + // Limit crashes to 1 node at a time (within fault tolerance of f=1). + // This is dynamically adjusted below: crashes are disabled while + // any node is still recovering. + quakey_set_max_crashes(quakey, 1); + + quakey_network_partitioning(quakey, true); + + InvariantChecker invariant_checker; + invariant_checker_init(&invariant_checker); + + while (simulation_running && (time_limit_ns == 0 || quakey_current_time(quakey) < time_limit_ns)) { + quakey_schedule_one(quakey); NodeState *arr[] = { @@ -119,9 +141,21 @@ int main(void) quakey_node_state(node_2), quakey_node_state(node_3), }; - check_vsr_invariants(arr, sizeof(arr)/sizeof(arr[0])); + invariant_checker_run(&invariant_checker, arr, sizeof(arr)/sizeof(arr[0])); + + // VR-Revisited Section 8.2: "a replica is considered failed + // until it has recovered its state." Disable crashes while + // any node is recovering to avoid exceeding f simultaneous + // failures (dead + recovering). + bool any_recovering = false; + for (int i = 0; i < 3; i++) { + if (arr[i] && arr[i]->status == STATUS_RECOVERY) + any_recovering = true; + } + quakey_set_max_crashes(quakey, any_recovering ? 0 : 1); } + invariant_checker_free(&invariant_checker); quakey_free(quakey); return 0; } diff --git a/vsr/node.c b/vsr/node.c index 0b19910..dac696e 100644 --- a/vsr/node.c +++ b/vsr/node.c @@ -8,39 +8,11 @@ #include "node.h" -//#define NODE_TRACE(fmt, ...) {} -#define NODE_TRACE(fmt, ...) fprintf(stderr, "NODE: " fmt "\n", ##__VA_ARGS__); - -// Format time as seconds with 3 decimal places for trace output -#define TIME_FMT "%.3fs" -#define TIME_VAL(t) ((double)(t) / 1000000000.0) - -static const char *message_type_name(uint8_t type) -{ - switch (type) { - case MESSAGE_TYPE_REQUEST: return "REQUEST"; - case MESSAGE_TYPE_REPLY: return "REPLY"; - case MESSAGE_TYPE_PREPARE: return "PREPARE"; - case MESSAGE_TYPE_PREPARE_OK: return "PREPARE_OK"; - case MESSAGE_TYPE_COMMIT: return "COMMIT"; - case MESSAGE_TYPE_BEGIN_VIEW_CHANGE: return "BEGIN_VIEW_CHANGE"; - case MESSAGE_TYPE_DO_VIEW_CHANGE: return "DO_VIEW_CHANGE"; - case MESSAGE_TYPE_BEGIN_VIEW: return "BEGIN_VIEW"; - case MESSAGE_TYPE_RECOVERY: return "RECOVERY"; - case MESSAGE_TYPE_RECOVERY_RESPONSE: return "RECOVERY_RESPONSE"; - default: return "UNKNOWN"; - } -} - -static const char *status_name(Status status) -{ - switch (status) { - case STATUS_NORMAL: return "NORMAL"; - case STATUS_CHANGE_VIEW: return "CHANGE_VIEW"; - case STATUS_RECOVERY: return "RECOVERY"; - } - return "UNKNOWN"; -} +typedef enum { + HR_OK, + HR_OUT_OF_MEMORY, + HR_INVALID_MESSAGE, +} HandlerResult; static int self_idx(NodeState *state) { @@ -57,1225 +29,1258 @@ static int leader_idx(NodeState *state) static bool is_leader(NodeState *state) { + if (state->status == STATUS_RECOVERY) + return false; return self_idx(state) == leader_idx(state); } -static int send_to_peer_ex(NodeState *state, int peer_idx, MessageHeader *msg, void *extra, int extra_len) +// ---- Logging infrastructure ---- + +#define TIME_FMT "%7.3fs" +#define TIME_VAL(t) ((double)(t) / 1000000000.0) + +static const char *status_name(Status s) +{ + switch (s) { + case STATUS_NORMAL: return "NR"; + case STATUS_CHANGE_VIEW: return "CV"; + case STATUS_RECOVERY: return "RC"; + } + return "??"; +} + +static void node_log_impl(NodeState *state, const char *event, const char *detail) +{ + printf("[" TIME_FMT "] NODE %d (%s) %s | V%-3lu C%-3d L%-3d | %-20s %s\n", + TIME_VAL(state->now), + self_idx(state), + is_leader(state) ? "PR" : "RE", + status_name(state->status), + state->view_number, + state->commit_index, + state->log.count, + event, + detail ? detail : ""); +} + +#define node_log(state, event, fmt, ...) do { \ + char _detail[256]; \ + snprintf(_detail, sizeof(_detail), fmt, ##__VA_ARGS__); \ + node_log_impl(state, event, _detail); \ +} while (0) + +#define node_log_simple(state, event) \ + node_log_impl(state, event, NULL) + +static int count_set(uint32_t word) +{ + int n = 0; + for (int i = 0; i < (int) sizeof(word) * 8; i++) + if (word & (1 << i)) + n++; + return n; +} + +static bool reached_quorum(NodeState *state, uint32_t votes) +{ + return count_set(votes) > state->num_nodes/2; +} + +static bool already_voted(uint32_t votes, int idx) +{ + uint32_t mask = 1 << idx; + return (votes & mask) == mask; +} + +static void add_vote(uint32_t *votes, int idx) +{ + *votes |= 1 << idx; +} + +static void send_to_peer_ex(NodeState *state, int peer_idx, MessageHeader *msg, void *extra, int extra_len) { ByteQueue *output; int conn_idx = tcp_index_from_tag(&state->tcp, peer_idx); if (conn_idx < 0) { int ret = tcp_connect(&state->tcp, state->node_addrs[peer_idx], peer_idx, &output); if (ret < 0) - return -1; + return; } else { output = tcp_output_buffer(&state->tcp, conn_idx); - if (output == NULL) { - assert(0); - } + if (output == NULL) + return; } byte_queue_write(output, msg, msg->length - extra_len); byte_queue_write(output, extra, extra_len); - return 0; } -static int send_to_peer(NodeState *state, int peer_idx, MessageHeader *msg) +static void send_to_peer(NodeState *state, int peer_idx, MessageHeader *msg) { - return send_to_peer_ex(state, peer_idx, msg, NULL, 0); + send_to_peer_ex(state, peer_idx, msg, NULL, 0); } -static int broadcast_to_peers_ex(NodeState *state, MessageHeader *msg, void *extra, int extra_len) +static void broadcast_to_peers_ex(NodeState *state, MessageHeader *msg, void *extra, int extra_len) { for (int i = 0; i < state->num_nodes; i++) { if (i != self_idx(state)) - if (send_to_peer_ex(state, i, msg, extra, extra_len) < 0) - return -1; + send_to_peer_ex(state, i, msg, extra, extra_len); } - return 0; } -static int broadcast_to_peers(NodeState *state, MessageHeader *msg) +static void broadcast_to_peers(NodeState *state, MessageHeader *msg) { - return broadcast_to_peers_ex(state, msg, NULL, 0); + broadcast_to_peers_ex(state, msg, NULL, 0); } -// TODO: test this function -static int count_set(uint32_t word) +static void begin_state_transfer(NodeState *state, int sender_idx) { - int n = 0; - for (int i = 0; i < sizeof(word) * 8; i++) - if (word & (1 << i)) - n++; - return n; + if (state->state_transfer_pending) + return; + state->state_transfer_pending = true; + + GetStateMessage message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_GET_STATE, + .length = sizeof(GetStateMessage), + }, + .view_number = state->view_number, + .op_number = state->log.count, + .sender_idx = self_idx(state), + }; + node_log(state, "SEND GET_STATE", "to=%d op=%d", sender_idx, state->log.count); + send_to_peer(state, sender_idx, &message.base); + + state->state_transfer_time = state->now; } -static int +static HandlerResult +process_request(NodeState *state, int conn_idx, ByteView msg) +{ + // Don't accept new requests during a view change. + // The leader must complete the view change first. + if (state->status != STATUS_NORMAL) + return HR_OK; + + RequestMessage request_message; + if (msg.len != sizeof(request_message)) + return HR_INVALID_MESSAGE; + memcpy(&request_message, msg.ptr, sizeof(request_message)); + + { + char oper_buf[64]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), request_message.oper); + node_log(state, "RECV REQUEST", "client=%lu req=%lu key=%.16s %s", + request_message.client_id, request_message.request_id, + request_message.oper.key, oper_buf); + } + + // Ensure a tag is associated to this connection + int conn_tag = tcp_get_tag(&state->tcp, conn_idx); + if (conn_tag == -1) { + conn_tag = state->next_client_tag++; + tcp_set_tag(&state->tcp, conn_idx, conn_tag, true); + } + + // We must first add or update the client table to + // invalidate the request ID. This makes it so any + // subsequent requests with the same ID are rejected + // while the first one is in progress. + // + // If the request ID is lower than the one stored in + // the table, the request is rejected. + // + // If the request ID is the same as the one in the table + // but no result was saved as the original one is still + // in progress, the request is rejected. + // + // If the request ID is the same and a result is available, + // it is returned immediately. + { + ClientTableEntry *entry = client_table_find(&state->client_table, request_message.client_id); + if (entry == NULL) { + + int ret = client_table_add( + &state->client_table, + request_message.client_id, + request_message.request_id, + conn_tag); + + if (ret < 0) { + + ReplyMessage reply_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_REPLY, + .length = sizeof(ReplyMessage), + }, + .rejected = true, + .request_id = request_message.request_id, + }; + + int conn_idx = tcp_index_from_tag(&state->tcp, conn_tag); + assert(conn_idx > -1); + + ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); + assert(output); + + node_log(state, "SEND REPLY", "client=%lu key=%.16s REJECTED (table full)", request_message.client_id, request_message.oper.key); + byte_queue_write(output, &reply_message, sizeof(reply_message)); + return HR_OK; + } + + } else { + + if (entry->pending) + return HR_OK; // Only one pending operation per client is allowed. Ignore the message. + + if (entry->last_request_id > request_message.request_id) + return HR_OK; // Request is old. Ignore. + + if (entry->last_request_id == request_message.request_id) { + + // This request was already processed and its value was cached. + // Respond with the cached value. + + ReplyMessage reply_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_REPLY, + .length = sizeof(ReplyMessage), + }, + .rejected = false, + .result = entry->last_result, + .request_id = request_message.request_id, + }; + + ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); + assert(output); + + { + char result_buf[64]; + kvstore_snprint_result(result_buf, sizeof(result_buf), entry->last_result); + node_log(state, "SEND REPLY", "client=%lu key=%.16s cached %s", request_message.client_id, request_message.oper.key, result_buf); + } + byte_queue_write(output, &reply_message, sizeof(reply_message)); + return HR_OK; + } + + entry->last_request_id = request_message.request_id; + entry->conn_tag = conn_tag; + entry->pending = true; + } + } + + LogEntry log_entry = { + .oper = request_message.oper, + .votes = 1 << self_idx(state), + .view_number = state->view_number, + .client_id = request_message.client_id, + .request_id = request_message.request_id, + }; + if (log_append(&state->log, log_entry) < 0) + return HR_OUT_OF_MEMORY; + + // We forwarded the message to all peers. As soon as + // we get enough PREPARE_OK responses, we'll commit + // and reply to the client. + PrepareMessage prepare_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_PREPARE, + .length = sizeof(PrepareMessage), + }, + .oper = request_message.oper, + .sender_idx = self_idx(state), + .log_index = state->log.count-1, + .commit_index = state->commit_index, + .view_number = state->view_number, + .client_id = request_message.client_id, + .request_id = request_message.request_id, + }; + { + char oper_buf[64]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), request_message.oper); + node_log(state, "SEND PREPARE", "to=* idx=%d key=%.16s %s", state->log.count-1, request_message.oper.key, oper_buf); + } + broadcast_to_peers(state, &prepare_message.base); + return HR_OK; +} + +static void reply_to_client(NodeState *state, uint64_t client_id, + uint64_t request_id, KVStoreOper *oper, KVStoreResult result) +{ + // After a view change, the new leader inherits log + // entries but not the client table's pending state. + // A client table entry may exist from a previous view + // (when this node was leader before) with pending=false. + // Only reply if this leader received the original REQUEST. + ClientTableEntry *table_entry = client_table_find(&state->client_table, client_id); + if (table_entry == NULL) + return; + + if (!table_entry->pending) + return; + + // Verify this reply is for the request the client is actually + // waiting for. After a view change, the new leader inherits + // uncommitted log entries from the old view carrying a stale + // request_id. If the client has since sent a newer request, + // we must not confuse the old result with the new request. + if (table_entry->last_request_id != request_id) + return; + + table_entry->pending = false; + table_entry->last_result = result; + + int conn_idx = tcp_index_from_tag(&state->tcp, table_entry->conn_tag); + if (conn_idx < 0) + return; + + ReplyMessage message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_REPLY, + .length = sizeof(ReplyMessage), + }, + .result = result, + .request_id = request_id, + }; + + { + char result_buf[64]; + kvstore_snprint_result(result_buf, sizeof(result_buf), result); + node_log(state, "SEND REPLY", "client=%lu req=%lu key=%.16s %s", + client_id, request_id, oper->key, result_buf); + } + + ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); + assert(output); + + byte_queue_write(output, &message, sizeof(message)); +} + +static void advance_commit_index(NodeState *state, int target_index, bool send_replies) +{ + target_index = MIN(target_index, state->log.count); + + while (state->commit_index < target_index) { + + LogEntry *entry = &state->log.entries[state->commit_index++]; + + KVStoreResult result = kvstore_update(&state->kvstore, entry->oper); + { + char oper_buf[64], result_buf[64]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), entry->oper); + kvstore_snprint_result(result_buf, sizeof(result_buf), result); + node_log(state, "APPLY", "idx=%d key=%.16s %s -> %s", state->commit_index-1, entry->oper.key, oper_buf, result_buf); + } + if (send_replies) { + reply_to_client(state, entry->client_id, entry->request_id, &entry->oper, result); + } + } +} + +// When the primary appends an entry to its log, it sends a +// PREPARE message to all backups. Backups add the entry to +// their own logs and reply with PREPARE_OK messages. When +// the primary receives a quorum of PREPARE_OKs, it commits +// the entry. +// +// In a reliable network and with no node crashes, we would +// expect entries to be committed linearly in the log. If +// log entries A and B are added to the log in that order, +// we expect A to reach PREPARE_OK messages before B. +// +// Unfortunately, we must assume messages will be lost (*). +// If that happens, instead of worrying about resending the +// PREPARE_OK for that entry, we rely on the fact that OK +// messages for future messages imply OK messages for the +// previous ones. The first message for which a quorum of +// OK messages is reached can work as an OK for all previous +// entries. +// +// For this reason, we allow "holes" in the log and if an +// entry reached quorum we advance the commit index to it. +// +// If the log index is lower than the log, it means we +// received an OK message that was not necessary anymore +// so we can ignore it. +// +// (*) This implementation uses TCP as a transport protocol, +// which means messages will be retransmitted if lost on +// the network. Nevertheless, if a node crashes while receiving +// a node or we crash before sending it, the message will +// be lost. +static HandlerResult +process_prepare_ok(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + PrepareOKMessage message; + if (msg.len != sizeof(message)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + node_log(state, "RECV PREPARE_OK", "from=%d idx=%d view=%lu", + message.sender_idx, message.log_index, message.view_number); + + if (message.view_number < state->view_number) + return HR_OK; // Drop + + if (message.view_number > state->view_number) { + // TODO: When can this happen? + state->view_number = message.view_number; + begin_state_transfer(state, message.sender_idx); + return HR_OK; + } + + assert(message.log_index > -1); + assert(message.log_index < state->log.count); + + if (message.log_index < state->commit_index) + return HR_OK; // Already processed + + LogEntry *entry = &state->log.entries[message.log_index]; + add_vote(&entry->votes, message.sender_idx); + if (reached_quorum(state, entry->votes)) { + node_log(state, "QUORUM", "idx=%d key=%.16s", message.log_index, entry->oper.key); + advance_commit_index(state, message.log_index+1, true); + } + return HR_OK; +} + +static bool +should_store_view_change_log(NodeState *state, DoViewChangeMessage message) +{ + if (message.old_view_number > state->view_change_old_view) + return true; + + if (message.old_view_number < state->view_change_old_view) + return false; + + if (message.op_number <= state->view_change_log.count) + return false; + + return true; +} + +static void +clear_view_change_fields(NodeState *state) +{ + state->view_change_begin_votes = 0; + state->view_change_apply_votes = 0; + state->view_change_old_view = 0; + state->view_change_commit = 0; + log_free(&state->view_change_log); + log_init(&state->view_change_log); +} + +static HandlerResult +complete_view_change_and_become_primary(NodeState *state) +{ + assert(state->commit_index <= state->view_change_commit); + + log_move(&state->log, &state->view_change_log); + + state->status = STATUS_NORMAL; + state->last_normal_view = state->view_number; + + // Apply committed entries that haven't been executed yet. + // The state machine has only been updated up to the old + // commit_index. The best log may contain additional + // committed entries (up to view_change_commit) + // that must be executed before we start processing new + // requests, otherwise the state machine will be stale. + advance_commit_index(state, state->view_change_commit, false); + + // Reset vote tracking for uncommitted entries. The log + // entries inherited from DO_VIEW_CHANGE have stale + // votes from the previous view. The new leader starts + // with its own vote for each entry. + for (int i = state->commit_index; i < state->log.count; i++) { + + LogEntry *entry = &state->log.entries[i]; + + entry->votes = 0; + add_vote(&entry->votes, self_idx(state)); + } + + node_log(state, "STATUS NORMAL", "became primary (view change complete)"); + + BeginViewMessage begin_view_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_BEGIN_VIEW, + .length = sizeof(BeginViewMessage) + state->log.count * sizeof(LogEntry), + }, + .view_number = state->view_number, + .commit_index = state->commit_index, + .op_number = state->log.count, + }; + node_log(state, "SEND BEGIN_VIEW", "to=* view=%lu log=%d commit=%d", + state->view_number, state->log.count, state->commit_index); + broadcast_to_peers_ex(state, &begin_view_message.base, state->log.entries, state->log.count * sizeof(LogEntry)); + + clear_view_change_fields(state); + return HR_OK; +} + +static HandlerResult +process_do_view_change(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + DoViewChangeMessage message; + if (msg.len < sizeof(message)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + node_log(state, "RECV DO_VIEW_CHANGE", "from=%d view=%lu old_view=%lu ops=%d commit=%d", + message.sender_idx, message.view_number, message.old_view_number, + message.op_number, message.commit_index); + + // Only process if we're still doing a view change. + // After completing a view change, status becomes NORMAL and + // we must not re-process stale DO_VIEW_CHANGE messages. + if (state->status != STATUS_CHANGE_VIEW) + return HR_OK; + + // Only process if the view matches what we're transitioning to + if (message.view_number != state->view_number) + return HR_OK; + + if (!already_voted(state->view_change_apply_votes, message.sender_idx)) { + + if (should_store_view_change_log(state, message)) { + + state->view_change_old_view = message.old_view_number; + + // Parse the variable-sized log from the message + int num_entries = (msg.len - sizeof(DoViewChangeMessage)) / sizeof(LogEntry); + if (num_entries != message.op_number) + return HR_INVALID_MESSAGE; // Message size mismatch + + log_free(&state->view_change_log); + if (log_init_from_network(&state->view_change_log, msg.ptr + sizeof(DoViewChangeMessage), num_entries) < 0) + return HR_OUT_OF_MEMORY; + } + + state->view_change_commit = MAX(state->view_change_commit, message.commit_index); + add_vote(&state->view_change_apply_votes, message.sender_idx); + } + + if (reached_quorum(state, state->view_change_apply_votes)) { + HandlerResult ret = complete_view_change_and_become_primary(state); + if (ret != HR_OK) + return ret; + } + + return HR_OK; +} + +static HandlerResult +process_recovery(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + RecoveryMessage recovery_message; + if (msg.len != sizeof(RecoveryMessage)) + return HR_INVALID_MESSAGE; + memcpy(&recovery_message, msg.ptr, sizeof(recovery_message)); + + node_log(state, "RECV RECOVERY", "from=%d nonce=%lu", recovery_message.sender_idx, recovery_message.nonce); + + if (state->status != STATUS_NORMAL) + return HR_OK; // Ignore message. + + node_log(state, "SEND RECOVERY_RESP", "to=%d view=%lu is_primary=%s", + recovery_message.sender_idx, state->view_number, is_leader(state) ? "yes" : "no"); + + RecoveryResponseMessage recovery_response_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_RECOVERY_RESPONSE, + .length = sizeof(RecoveryResponseMessage), + }, + .view_number = state->view_number, + .op_number = state->log.count-1, // TODO: What if the log is empty? + .nonce = recovery_message.nonce, + .commit_index = state->commit_index, + .sender_idx = self_idx(state), + }; + if (is_leader(state)) { + recovery_response_message.base.length += state->log.count * sizeof(LogEntry); + send_to_peer_ex(state, recovery_message.sender_idx, &recovery_response_message.base, + state->log.entries, state->log.count * sizeof(LogEntry)); + } else { + send_to_peer(state, recovery_message.sender_idx, &recovery_response_message.base); + } + return HR_OK; +} + +static HandlerResult +perform_log_transfer_for_view_change(NodeState *state) +{ + if (is_leader(state)) { + // We are the new leader: count our own vote directly + // since send_to_peer_ex skips self-sends. + + add_vote(&state->view_change_apply_votes, self_idx(state)); + + state->view_change_old_view = state->last_normal_view; + state->view_change_commit = state->commit_index; + + // TODO: This should use copy-on-write + if (log_init_from_network(&state->view_change_log, state->log.entries, state->log.count) < 0) + return HR_OUT_OF_MEMORY; + + } else { + DoViewChangeMessage do_view_change_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_DO_VIEW_CHANGE, + .length = sizeof(DoViewChangeMessage) + state->log.count * sizeof(LogEntry), + }, + .view_number = state->view_number, + .old_view_number = state->last_normal_view, + .op_number = state->log.count, + .commit_index = state->commit_index, + .sender_idx = self_idx(state), + }; + node_log(state, "SEND DO_VIEW_CHANGE", "to=%d view=%lu old_view=%lu log=%d commit=%d", + leader_idx(state), state->view_number, state->last_normal_view, + state->log.count, state->commit_index); + send_to_peer_ex(state, leader_idx(state), &do_view_change_message.base, state->log.entries, state->log.count * sizeof(LogEntry)); + } + + // Clear the future array since we're changing views + state->num_future = 0; + state->state_transfer_pending = false; + return HR_OK; +} + +static HandlerResult +process_begin_view_change(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + BeginViewChangeMessage message; + if (msg.len != sizeof(BeginViewChangeMessage)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + node_log(state, "RECV BEGIN_VIEW_CHG", "from=%d view=%lu", message.sender_idx, message.view_number); + + if (state->status == STATUS_RECOVERY) + return HR_OK; + + assert(state->status == STATUS_NORMAL + || state->status == STATUS_CHANGE_VIEW); + + // Ignore old messages + if (message.view_number < state->view_number) + return HR_OK; + + // BeginViewChange messages hold the view number of the view + // they are transitioning into. If this node is in NORMAL + // state and has the same view as the BeginViewChange message, + // it means the transition already happened and the message + // is stale. + if (state->status == STATUS_NORMAL) { + if (state->view_number == message.view_number) + return HR_OK; + } + + // If the peer's view number is larger, we need to transition + // to the view change state. + if (message.view_number > state->view_number) { + + // Send our own BeginViewChange to all peers + BeginViewChangeMessage message_2 = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_BEGIN_VIEW_CHANGE, + .length = sizeof(BeginViewChangeMessage), + }, + .view_number = message.view_number, + .sender_idx = self_idx(state), + }; + node_log(state, "SEND BEGIN_VIEW_CHG", "to=* view=%lu", message.view_number); + broadcast_to_peers(state, &message_2.base); + + clear_view_change_fields(state); + state->view_number = message.view_number; + node_log(state, "STATUS CHANGE_VIEW", "view=%lu", state->view_number); + state->status = STATUS_CHANGE_VIEW; + state->heartbeat = state->now; + } + + add_vote(&state->view_change_begin_votes, message.sender_idx); + add_vote(&state->view_change_begin_votes, self_idx(state)); + if (reached_quorum(state, state->view_change_begin_votes)) { + HandlerResult ret = perform_log_transfer_for_view_change(state); + if (ret != HR_OK) + return ret; + } + + return HR_OK; +} + +static HandlerResult +process_begin_view(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + BeginViewMessage message; + if (msg.len < sizeof(message)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + node_log(state, "RECV BEGIN_VIEW", "view=%lu commit=%d ops=%d", + message.view_number, message.commit_index, message.op_number); + + if (message.view_number < state->view_number) + return HR_OK; + + state->view_number = message.view_number; + + state->status = STATUS_NORMAL; + state->last_normal_view = state->view_number; + node_log(state, "STATUS NORMAL", "new view=%lu (follower)", state->view_number); + + // Replace the local log with the authoritative log from the primary + int num_entries = (msg.len - sizeof(BeginViewMessage)) / sizeof(LogEntry); + log_free(&state->log); + if (log_init_from_network(&state->log, msg.ptr + sizeof(BeginViewMessage), num_entries) < 0) + return HR_OUT_OF_MEMORY; + + state->num_future = 0; + state->state_transfer_pending = false; + + // If there are non-committed operations in the log, + // send a PREPAREOK to the new primary + if (state->log.count > message.commit_index) { + PrepareOKMessage ok_msg = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_PREPARE_OK, + .length = sizeof(PrepareOKMessage), + }, + .sender_idx = self_idx(state), + .log_index = state->log.count - 1, + .view_number = state->view_number, + }; + node_log(state, "SEND PREPARE_OK", "to=%d idx=%d key=%.16s", leader_idx(state), state->log.count - 1, + state->log.entries[state->log.count - 1].oper.key); + send_to_peer(state, leader_idx(state), &ok_msg.base); + } + + advance_commit_index(state, message.commit_index, false); + + clear_view_change_fields(state); + state->heartbeat = state->now; + return HR_OK; +} + +static HandlerResult +process_get_state(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + GetStateMessage get_state_message; + if (msg.len != sizeof(GetStateMessage)) + return HR_INVALID_MESSAGE; + memcpy(&get_state_message, msg.ptr, sizeof(get_state_message)); + + node_log(state, "RECV GET_STATE", "from=%d op=%d view=%lu", + get_state_message.sender_idx, get_state_message.op_number, get_state_message.view_number); + + if (state->status != STATUS_NORMAL) + return HR_OK; + + // Only respond if the requester is in the same view + if (get_state_message.view_number != state->view_number) + return HR_OK; + + // Compute the suffix of log entries the requester is missing + int start = get_state_message.op_number; + if (start < 0 || start >= state->log.count) + return HR_OK; // Nothing to send + + int num_entries = state->log.count - start; + + NewStateMessage new_state_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_NEW_STATE, + .length = sizeof(NewStateMessage) + num_entries * sizeof(LogEntry), + }, + .view_number = state->view_number, + .op_number = num_entries, + .commit_index = state->commit_index, + }; + node_log(state, "SEND NEW_STATE", "to=%d entries=%d commit=%d", + get_state_message.sender_idx, num_entries, state->commit_index); + send_to_peer_ex(state, get_state_message.sender_idx, &new_state_message.base, + state->log.entries + start, num_entries * sizeof(LogEntry)); + return HR_OK; +} + +static HandlerResult process_message_as_leader(NodeState *state, int conn_idx, uint8_t type, ByteView msg) { switch (type) { case MESSAGE_TYPE_REQUEST: - { - // Don't accept new requests during a view change. - // The leader must complete the view change first. - if (state->status != STATUS_NORMAL) - break; + return process_request(state, conn_idx, msg); - RequestMessage request_message; - - if (msg.len != sizeof(request_message)) - return -1; - memcpy(&request_message, msg.ptr, sizeof(request_message)); - - // We must first add or update the client table to - // invalidate the request ID. This makes it so any - // subsequent requests with the same ID are rejected - // while the first one is in progress. - // - // If the request ID is lower than the one stored in - // the table, the request is rejected. - // - // If the request ID is the same as the one in the table - // but no result was saved as the original one is still - // in progress, the request is rejected. - // - // If the request ID is the same and a result is available, - // it is returned immediately. - { - ClientTableEntry *entry = client_table_find(&state->client_table, request_message.client_id); - if (entry == NULL) { - - if (client_table_add(&state->client_table, request_message.client_id, request_message.request_id, conn_idx) < 0) { - ReplyMessage reply_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_REPLY, - .length = sizeof(ReplyMessage), - }, - .rejected = true, - }; - - ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); - assert(output); - - byte_queue_write(output, &reply_message, sizeof(reply_message)); - break; - } - - } else { - - if (entry->pending) - break; // Only one pending operation per client is allowed. Ignore the message. - - if (entry->last_request_id > request_message.request_id) - break; // Request is old. Ignore. - - if (entry->last_request_id == request_message.request_id) { - - // This request was already processed and its value was cached. - // Respond with the cached value. - - ReplyMessage reply_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_REPLY, - .length = sizeof(ReplyMessage), - }, - .rejected = false, - .result = entry->last_result, - }; - - ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); - assert(output); - - byte_queue_write(output, &reply_message, sizeof(reply_message)); - break; - } - - entry->last_request_id = request_message.request_id; - entry->pending = true; - } - } - - LogEntry log_entry = { - .oper = request_message.oper, - .votes = 1 << self_idx(state), - .view_number = state->view_number, - .client_id = request_message.client_id, - }; - if (log_append(&state->log, log_entry) < 0) { - assert(0); // TODO - } - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): REQUEST from client %lu (req_id=%lu), appended to log[%d], view=%lu", - TIME_VAL(now), self_idx(state), - (unsigned long)request_message.client_id, - (unsigned long)request_message.request_id, - state->log.count-1, (unsigned long)state->view_number); - } - - PrepareMessage prepare_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_PREPARE, - .length = sizeof(PrepareMessage), - }, - .oper = request_message.oper, - .sender_idx = self_idx(state), - .log_index = state->log.count-1, - .commit_index = state->commit_index, - .view_number = state->view_number, - }; - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER) -> ALL: PREPARE log_index=%d commit_index=%d view=%lu", - TIME_VAL(now), self_idx(state), - state->log.count-1, state->commit_index, - (unsigned long)state->view_number); - } - - if (broadcast_to_peers(state, &prepare_message.base) < 0) { - assert(0); - } - - // We forwarded the message to all peers. As soon as - // we get enough PREPARE_OK responses, we'll commit - // and reply to the client. - } - break; case MESSAGE_TYPE_PREPARE_OK: - { - PrepareOKMessage prepare_ok_message; + return process_prepare_ok(state, conn_idx, msg); - if (msg.len != sizeof(prepare_ok_message)) - return -1; - memcpy(&prepare_ok_message, msg.ptr, sizeof(prepare_ok_message)); - - if (prepare_ok_message.view_number != state->view_number) { - assert(0); - } - - // TODO: check log_index - int log_index = prepare_ok_message.log_index; - if (log_index < 0 || log_index >= state->log.count) { - assert(0); // TODO - } - - // When the primary appends an entry to its log, it sends a - // PREPARE message to all backups. Backups add the entry to - // their own logs and reply with PREPARE_OK messages. When - // the primary receives a quorum of PREPARE_OKs, it commits - // the entry. - // - // In a reliable network and with no node crashes, we would - // expect entries to be committed linearly in the log. If - // log entries A and B are added to the log in that order, - // we expect A to reach PREPARE_OK messages before B. - // - // Unfortunately, we must assume messages will be lost (*). - // If that happens, instead of worrying about resending the - // PREPARE_OK for that entry, we rely on the fact that OK - // messages for future messages imply OK messages for the - // previous ones. The first message for which a quorum of - // OK messages is reached can work as an OK for all previous - // entries. - // - // For this reason, we allow "holes" in the log and if an - // entry reached quorum we advance the commit index to it. - // - // If the log index is lower than the log, it means we - // received an OK message that was not necessary anymore - // so we can ignore it. - // - // (*) This implementation uses TCP as a transport protocol, - // which means messages will be retransmitted if lost on - // the network. Nevertheless, if a node crashes while receiving - // a node or we crash before sending it, the message will - // be lost. - - if (log_index < state->commit_index) - break; // Already processed - LogEntry *entry = &state->log.entries[log_index]; - - entry->votes |= 1 << prepare_ok_message.sender_idx; - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): PREPARE_OK from node %d for log[%d], prep_oks=%d/%d view=%lu", - TIME_VAL(now), self_idx(state), - prepare_ok_message.sender_idx, log_index, - count_set(entry->votes), state->num_nodes/2 + 1, - (unsigned long)prepare_ok_message.view_number); - } - - // Quorum reached for this log entry? - if (count_set(entry->votes) > state->num_nodes/2) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): quorum reached for log[%d], advancing commit_index %d -> %d", - TIME_VAL(now), self_idx(state), - log_index, state->commit_index, log_index + 1); - } - - // Okay, we can advance the commit index to here - while (state->commit_index <= log_index) { - - uint64_t client_id = state->log.entries[state->commit_index].client_id; - Operation oper = state->log.entries[state->commit_index].oper; - state->commit_index++; - - OperationResult result = state_machine_update(&state->state_machine, oper); - - ClientTableEntry *table_entry = client_table_find(&state->client_table, client_id); - if (table_entry) { - - assert(table_entry->pending); - table_entry->pending = false; - table_entry->last_result = result; - - ReplyMessage reply_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_REPLY, - .length = sizeof(ReplyMessage), - }, - .result = result, - }; - - ByteQueue *output = tcp_output_buffer(&state->tcp, table_entry->conn_idx); - assert(output); - - byte_queue_write(output, &reply_message, sizeof(reply_message)); - } - } - } - } - break; case MESSAGE_TYPE_DO_VIEW_CHANGE: - { - DoViewChangeMessage do_view_change_message; - if (msg.len < sizeof(do_view_change_message)) - return -1; - memcpy(&do_view_change_message, msg.ptr, sizeof(do_view_change_message)); + return process_do_view_change(state, conn_idx, msg); - // Parse the variable-sized log from the message - int num_entries = (msg.len - sizeof(DoViewChangeMessage)) / sizeof(LogEntry); - if (num_entries != do_view_change_message.op_number) - return -1; // Message size mismatch - - // Only process if the view matches what we're transitioning to - if (do_view_change_message.view_number != state->view_number) - break; - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d: DO_VIEW_CHANGE from node %d, view=%lu old_view=%lu op_number=%d commit_index=%d", - TIME_VAL(now), self_idx(state), - do_view_change_message.sender_idx, - (unsigned long)do_view_change_message.view_number, - (unsigned long)do_view_change_message.old_view_number, - do_view_change_message.op_number, - do_view_change_message.commit_index); - } - - // Track this vote - uint32_t vote_mask = 1 << do_view_change_message.sender_idx; - if ((state->do_view_change_votes & vote_mask) == 0) { - - state->do_view_change_votes |= vote_mask; - - // Check if this log is better than the one we have stored - // Best log: highest old_view_number, then highest op_number - bool is_better = (do_view_change_message.old_view_number > state->do_view_change_best_old_view) || - (do_view_change_message.old_view_number == state->do_view_change_best_old_view && - do_view_change_message.op_number > state->do_view_change_best_log.count); - - if (is_better) { - state->do_view_change_best_old_view = do_view_change_message.old_view_number; - - // Copy the log entries from the message - LogEntry *entries = malloc(num_entries * sizeof(LogEntry)); - if (entries == NULL) { - assert(0); - } - memcpy(entries, (uint8_t*)msg.ptr + sizeof(DoViewChangeMessage), num_entries * sizeof(LogEntry)); - - log_free(&state->do_view_change_best_log); - state->do_view_change_best_log.count = num_entries; - state->do_view_change_best_log.capacity = num_entries; - state->do_view_change_best_log.entries = entries; - } - - // Track the maximum commit index - if (do_view_change_message.commit_index > state->do_view_change_best_commit) { - state->do_view_change_best_commit = do_view_change_message.commit_index; - } - } - - // Count votes - int vote_count = 0; - for (int i = 0; i < state->num_nodes; i++) { - if (state->do_view_change_votes & (1 << i)) vote_count++; - } - - // Need f + 1 DoViewChange messages (including own) - if (vote_count >= state->num_nodes / 2 + 1) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d: view change complete, becoming LEADER for view %lu (votes=%d/%d)", - TIME_VAL(now), self_idx(state), - (unsigned long)state->view_number, - vote_count, state->num_nodes); - } - - // Use the best log we collected - log_free(&state->log); - state->log = state->do_view_change_best_log; - state->do_view_change_best_log = (Log){0}; // Clear to avoid double-free - - state->commit_index = state->do_view_change_best_commit; - state->status = STATUS_NORMAL; - - // Reset vote tracking for uncommitted entries. The log - // entries inherited from DO_VIEW_CHANGE have stale - // votes from the previous view. The new leader starts - // with its own vote for each entry. - for (int i = state->commit_index; i < state->log.count; i++) - state->log.entries[i].votes = 1 << self_idx(state); - - BeginViewMessage begin_view_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_BEGIN_VIEW, - .length = sizeof(BeginViewMessage) + state->log.count * sizeof(LogEntry), - }, - .view_number = state->view_number, - .commit_index = state->commit_index, - .op_number = state->log.count, - }; - - if (broadcast_to_peers_ex(state, &begin_view_message.base, state->log.entries, state->log.count * sizeof(LogEntry)) < 0) { - assert(0); - } - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER) -> ALL: BEGIN_VIEW view=%lu commit_index=%d log_count=%d", - TIME_VAL(now), self_idx(state), - (unsigned long)state->view_number, - state->commit_index, state->log.count); - } - - // Reset view change state for next time - state->do_view_change_votes = 0; - state->do_view_change_best_old_view = 0; - state->do_view_change_best_commit = 0; - } - } - break; case MESSAGE_TYPE_RECOVERY: - { - if (state->status != STATUS_NORMAL) - break; // Ignore message. + return process_recovery(state, conn_idx, msg); - RecoveryMessage recovery_message; - if (msg.len != sizeof(RecoveryMessage)) - return -1; - memcpy(&recovery_message, msg.ptr, sizeof(recovery_message)); - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): RECOVERY from node %d (nonce=%lu), sending RECOVERY_RESPONSE with log_count=%d", - TIME_VAL(now), self_idx(state), - recovery_message.sender_idx, - (unsigned long)recovery_message.nonce, - state->log.count); - } - - RecoveryResponseMessage recovery_response_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_RECOVERY_RESPONSE, - .length = sizeof(RecoveryResponseMessage) + state->log.count * sizeof(LogEntry), - }, - .view_number = state->view_number, - .op_number = state->log.count-1, // TODO: What if the log is empty? - .nonce = recovery_message.nonce, - .commit_index = state->commit_index, - .sender_idx = self_idx(state), - }; - - if (send_to_peer_ex(state, recovery_message.sender_idx, &recovery_response_message.base, state->log.entries, state->log.count * sizeof(LogEntry)) < 0) { - assert(0); - } - } - break; case MESSAGE_TYPE_BEGIN_VIEW_CHANGE: - { - if (state->status == STATUS_RECOVERY) break; + return process_begin_view_change(state, conn_idx, msg); - BeginViewChangeMessage begin_view_change_message; - if (msg.len != sizeof(BeginViewChangeMessage)) - return -1; - memcpy(&begin_view_change_message, msg.ptr, sizeof(begin_view_change_message)); - - if (begin_view_change_message.view_number > state->view_number) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): BEGIN_VIEW_CHANGE from node %d, transitioning view %lu -> %lu", - TIME_VAL(now), self_idx(state), - begin_view_change_message.sender_idx, - (unsigned long)state->view_number, - (unsigned long)begin_view_change_message.view_number); - } - - // Reset vote tracking when transitioning to a new view - state->begin_view_change_votes = 0; - state->view_number = begin_view_change_message.view_number; - state->status = STATUS_CHANGE_VIEW; - - // Send our own BeginViewChange to all peers - BeginViewChangeMessage own_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_BEGIN_VIEW_CHANGE, - .length = sizeof(BeginViewChangeMessage), - }, - .view_number = state->view_number, - .sender_idx = self_idx(state), - }; - - if (broadcast_to_peers(state, &own_message.base) < 0) { - assert(0); - } - // Count our own vote - state->begin_view_change_votes |= (1 << self_idx(state)); - } - - // Track this sender's vote (only if view matches) - if (begin_view_change_message.view_number == state->view_number) { - state->begin_view_change_votes |= (1 << begin_view_change_message.sender_idx); - } - - // Count votes - int vote_count = 0; - for (int i = 0; i < state->num_nodes; i++) { - if (state->begin_view_change_votes & (1 << i)) vote_count++; - } - - // Need f + 1 votes to send DoViewChange - if (vote_count >= state->num_nodes / 2 + 1) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): f+1 BEGIN_VIEW_CHANGE votes reached (%d/%d), sending DO_VIEW_CHANGE to node %d for view %lu", - TIME_VAL(now), self_idx(state), - vote_count, state->num_nodes, - (int)(state->view_number % state->num_nodes), - (unsigned long)state->view_number); - } - - DoViewChangeMessage do_view_change_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_DO_VIEW_CHANGE, - .length = sizeof(DoViewChangeMessage) + state->log.count * sizeof(LogEntry), - }, - .view_number = state->view_number, - .old_view_number = state->view_number - 1, // View before we started view change - .op_number = state->log.count, - .commit_index = state->commit_index, - .sender_idx = self_idx(state), - }; - if (leader_idx(state) == self_idx(state)) { - // We are the new leader: count our own vote directly - // since send_to_peer_ex skips self-sends. - state->do_view_change_votes |= (1 << self_idx(state)); - } else { - if (send_to_peer_ex(state, leader_idx(state), &do_view_change_message.base, state->log.entries, state->log.count * sizeof(LogEntry)) < 0) { - assert(0); - } - } - - // Clear the future array since we're changing views - state->num_future = 0; - } - } - break; case MESSAGE_TYPE_BEGIN_VIEW: - { - BeginViewMessage message; + return process_begin_view(state, conn_idx, msg); - if (msg.len < sizeof(message)) - return -1; - memcpy(&message, msg.ptr, sizeof(message)); - - // Only process messages containing a view-number - // that matches or advances the one we know. - if (message.view_number < state->view_number) - break; - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): BEGIN_VIEW received, stepping down and adopting view %lu (commit_index=%d, log_entries=%d)", - TIME_VAL(now), self_idx(state), - (unsigned long)message.view_number, - message.commit_index, message.op_number); - } - - // Update view and status - state->view_number = message.view_number; - state->status = STATUS_NORMAL; // Paper state: change status to normal - - // Replace the local log with the authoritative log from the primary - { - int num_entries = (msg.len - sizeof(BeginViewMessage)) / sizeof(LogEntry); - LogEntry *entries = malloc(num_entries * sizeof(LogEntry)); - if (entries == NULL) { - assert(0); - } - memcpy(entries, (uint8_t*)msg.ptr + sizeof(BeginViewMessage), num_entries * sizeof(LogEntry)); - - log_free(&state->log); - state->log.count = num_entries; - state->log.capacity = num_entries; - state->log.entries = entries; - } - - // Reset view change state - state->begin_view_change_votes = 0; - - // If there are non-committed operations in the log, - // send a PREPAREOK to the new primary - if (state->log.count > message.commit_index) { - PrepareOKMessage ok_msg = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_PREPARE_OK, - .length = sizeof(PrepareOKMessage), - }, - .sender_idx = self_idx(state), - .log_index = state->log.count - 1, - .view_number = state->view_number, - }; - if (send_to_peer(state, leader_idx(state), &ok_msg.base) < 0) { - assert(0); - } - } - - // Execute all operations known to be committed that haven't - // been executed previously - while (state->commit_index < message.commit_index && state->commit_index < state->log.count) { - state_machine_update(&state->state_machine, state->log.entries[state->commit_index].oper); - state->commit_index++; - } - - Time now = get_current_time(); - if (now == INVALID_TIME) { - assert(0); - } - state->last_heartbeat_time = now; - } - break; case MESSAGE_TYPE_RECOVERY_RESPONSE: - { - RecoveryResponseMessage message; - - if (msg.len < sizeof(message)) - return -1; - memcpy(&message, msg.ptr, sizeof(message)); - - // 1. Only process responses if we are actually in the recovering state - // 2. Ensure the nonce matches the one we sent to prevent accepting - // delayed responses from previous recovery attempts. - if (state->status != STATUS_RECOVERY || message.nonce != state->recovery_nonce) { - break; - } - - // Track this response - state->recovery_votes |= (1 << message.sender_idx); - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (RECOVERY): RECOVERY_RESPONSE from node %d, view=%lu op_number=%d commit_index=%d", - TIME_VAL(now), self_idx(state), - message.sender_idx, - (unsigned long)message.view_number, - message.op_number, message.commit_index); - } - - // Track the highest view number we've seen and who the primary is for it - if (message.view_number > state->max_view_seen) { - state->max_view_seen = message.view_number; - state->latest_primary_idx = (message.view_number % state->num_nodes); - } - - // Store the state from the primary if this message is from them - if (message.sender_idx == (int) (message.view_number % state->num_nodes)) { - // Copy the log from the variable-sized portion of the message - int num_entries = (msg.len - sizeof(RecoveryResponseMessage)) / sizeof(LogEntry); - LogEntry *entries = malloc(num_entries * sizeof(LogEntry)); - if (entries == NULL) { - assert(0); - } - memcpy(entries, (uint8_t*)msg.ptr + sizeof(RecoveryResponseMessage), num_entries * sizeof(LogEntry)); - - log_free(&state->potential_primary_log); - state->potential_primary_log.count = num_entries; - state->potential_primary_log.capacity = num_entries; - state->potential_primary_log.entries = entries; - - state->received_primary_state = true; - } - - // Check if we have f + 1 responses - int response_count = 0; - for (int i = 0; i < state->num_nodes; i++) { - if (state->recovery_votes & (1 << i)) response_count++; - } - - // The threshold f is derived from 2f + 1 = num_nodes - int f = (state->num_nodes - 1) / 2; - - if (response_count >= f + 1 && state->received_primary_state) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d: recovery complete (responses=%d, f+1=%d), adopting view %lu", - TIME_VAL(now), self_idx(state), - response_count, f + 1, - (unsigned long)state->max_view_seen); - } - - // Update state using information from the primary - state->view_number = state->max_view_seen; - - // Move the log (no need to copy since we're transferring ownership) - log_free(&state->log); - state->log = state->potential_primary_log; - state->potential_primary_log = (Log){0}; // Clear to avoid double-free - - state->commit_index = message.commit_index; - - // Change status to normal; the recovery protocol is complete - state->status = STATUS_NORMAL; - - // Update heartbeat to avoid immediate view change timeout - Time now = get_current_time(); - if (now == INVALID_TIME) { - assert(0); - } - state->last_heartbeat_time = now; - } - } + // Ignore message. break; + + case MESSAGE_TYPE_GET_STATE: + return process_get_state(state, conn_idx, msg); + default: break; } - return 0; + + return HR_OK; +} + +static HandlerResult +complete_recovery(NodeState *state) +{ + assert(state->commit_index <= state->recovery_commit); + + state->view_number = state->recovery_view; + log_move(&state->log, &state->recovery_log); + advance_commit_index(state, state->recovery_commit, false); + + state->status = STATUS_NORMAL; + state->last_normal_view = state->view_number; + node_log(state, "STATUS NORMAL", "recovery complete view=%lu commit=%d", + state->view_number, state->commit_index); + + // Reset stale votes + if (is_leader(state)) { + for (int i = state->commit_index; i < state->log.count; i++) { + LogEntry *entry = &state->log.entries[i]; + entry->votes = 0; + add_vote(&entry->votes, self_idx(state)); + } + } + + // Update heartbeat to avoid immediate view change timeout + state->heartbeat = state->now; + return HR_OK; +} + +static bool +received_recovery_primary(NodeState *state) +{ + assert(state->status == STATUS_RECOVERY); + + int primary_idx = state->recovery_view % state->num_nodes; + uint32_t primary_mask = 1 << primary_idx; + return (state->recovery_votes & primary_mask) != 0; +} + +static bool +sender_thinks_he_is_primary(NodeState *state, RecoveryResponseMessage message) +{ + return message.sender_idx == (int) (message.view_number % state->num_nodes); +} + +// When a node is trying to recover state, it expects +// a response from each replica and one from the primary +// containing the log. +// +// The recovering node is not aware of what the current +// view number is, and therefore doesn't know who is the +// primary. +// +// The only way a recovering node can infer whether a +// node is the primary or not, is by inferring it from +// the message itself. +// +// This function determines whether the message from a +// node contains a log and if it does, whether it should +// be stored. +// +// If no log was previously received, it is stored +// unconditionally. If a log is already stored, the +// newly received one is only stored if its view number +// is greater than the one associated to the stored +// log. +static bool +should_store_recovery_log(NodeState *state, RecoveryResponseMessage message) +{ + return sender_thinks_he_is_primary(state, message) + && (!received_recovery_primary(state) || state->recovery_log_view < message.view_number); +} + +static HandlerResult +process_recovery_response(NodeState *state, ByteView msg) +{ + RecoveryResponseMessage message; + if (msg.len < sizeof(message)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + node_log(state, "RECV RECOVERY_RESP", "from=%d view=%lu commit=%d nonce=%lu", + message.sender_idx, message.view_number, message.commit_index, message.nonce); + + // 1. Only process responses if we are actually in the recovering state [cite: 237] + // 2. Ensure the nonce matches the one we sent to prevent accepting + // delayed responses from previous recovery attempts[cite: 253]. + if (state->status != STATUS_RECOVERY) + return HR_OK; + + if (message.nonce != state->recovery_nonce) + return HR_OK; + + if (should_store_recovery_log(state, message)) { + log_free(&state->recovery_log); + if (log_init_from_network(&state->recovery_log, msg.ptr + sizeof(RecoveryResponseMessage), + (msg.len - sizeof(RecoveryResponseMessage)) / sizeof(LogEntry)) < 0) + return HR_OUT_OF_MEMORY; + + state->recovery_log_view = message.view_number; + state->recovery_commit = message.commit_index; + } + + add_vote(&state->recovery_votes, message.sender_idx); + state->recovery_view = MAX(state->recovery_view, message.view_number); + + if (reached_quorum(state, state->recovery_votes) && received_recovery_primary(state)) { + HandlerResult ret = complete_recovery(state); + if (ret != HR_OK) + return ret; + } + return HR_OK; } static int -process_message_as_replica(NodeState *state, - int conn_idx, uint8_t type, ByteView msg) +process_single_future_list_entry(NodeState *state) +{ + // Look for an entry with the current log index + int i = 0; + while (i < state->num_future && state->future[i].log_index != state->log.count) + i++; + + if (i == state->num_future) + return 0; // No entry + + LogEntry entry = { + .oper = state->future[i].oper, + .votes = 0, + .view_number = state->view_number, + .client_id = state->future[i].client_id, + .request_id = state->future[i].request_id, + }; + if (log_append(&state->log, entry) < 0) + return -1; + + PrepareOKMessage message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_PREPARE_OK, + .length = sizeof(PrepareOKMessage), + }, + .sender_idx = self_idx(state), + .log_index = state->log.count-1, + .view_number = state->view_number, + }; + send_to_peer(state, state->future[i].sender_idx, &message.base); + return 1; +} + +static void +remove_old_future_list_entries(NodeState *state) +{ + for (int i = 0; i < state->num_future; i++) { + if (state->future[i].log_index < state->log.count) { + state->future[i--] = state->future[--state->num_future]; + } + } +} + +static int process_future_list(NodeState *state) +{ + for (;;) { + int ret = process_single_future_list_entry(state); + if (ret != 1) + break; + } + remove_old_future_list_entries(state); + return 0; +} + +static HandlerResult +process_prepare(NodeState *state, ByteView msg) +{ + // A recovering node must not process PREPAREs. It doesn't have + // the full log yet and adopting a view from a PREPARE would set + // last_normal_view to a high value with an empty log, which can + // cause a subsequent view change to select this empty log over + // the correct one from other replicas. + if (state->status == STATUS_RECOVERY) + return HR_OK; + + PrepareMessage message; + if (msg.len != sizeof(message)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + { + char oper_buf[64]; + kvstore_snprint_oper(oper_buf, sizeof(oper_buf), message.oper); + node_log(state, "RECV PREPARE", "from=%d idx=%d commit=%d view=%lu key=%.16s %s", + message.sender_idx, message.log_index, message.commit_index, + message.view_number, message.oper.key, oper_buf); + } + + if (message.view_number < state->view_number) + return HR_OK; // Stale peer + + if (message.view_number > state->view_number) { + + // The new leader has started a view we haven't seen. + // Adopt the new view and process the PREPARE normally. + + state->view_number = message.view_number; + + state->status = STATUS_NORMAL; + state->last_normal_view = state->view_number; + + state->view_change_begin_votes = 0; + state->num_future = 0; + state->state_transfer_pending = false; + } + + // A replica that has entered CHANGE_VIEW must not process PREPAREs + // for the current view. It has already committed to the view change + // by broadcasting BEGIN_VIEW_CHANGE and must wait for the view + // change to complete via BEGIN_VIEW. Processing PREPAREs in this + // state would advance the log and commit_index without updating + // last_normal_view, causing a stale old_view_number in any + // subsequent DO_VIEW_CHANGE and potentially leading the new leader + // to select a shorter log over this replica's longer one. + if (state->status == STATUS_CHANGE_VIEW) + return HR_OK; + + if (message.log_index < state->log.count) + return HR_OK; // Message refers to an old entry. Ignore. + + if (message.log_index > state->log.count) { + + // The prepare message for a previous log entry was not received yet. + // Buffer this message to process it later (drop if buffer full) + if (state->num_future < FUTURE_LIMIT) { + state->future[state->num_future++] = message; + } + + // Request missing entries from the primary via State Transfer + begin_state_transfer(state, leader_idx(state)); + return HR_OK; + } + + LogEntry log_entry = { + .oper = message.oper, + .votes = 0, + .view_number = state->view_number, + .client_id = message.client_id, + .request_id = message.request_id, + }; + if (log_append(&state->log, log_entry) < 0) + return HR_OUT_OF_MEMORY; + + PrepareOKMessage ok_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_PREPARE_OK, + .length = sizeof(PrepareOKMessage), + }, + .sender_idx = self_idx(state), + .log_index = state->log.count-1, + .view_number = state->view_number, + }; + node_log(state, "SEND PREPARE_OK", "to=%d idx=%d key=%.16s", message.sender_idx, state->log.count-1, message.oper.key); + send_to_peer(state, message.sender_idx, &ok_message.base); + + process_future_list(state); + advance_commit_index(state, message.commit_index, false); + + state->heartbeat = state->now; + return HR_OK; +} + +static HandlerResult +process_commit(NodeState *state, int conn_idx, ByteView msg) { (void) conn_idx; + CommitMessage message; + if (msg.len != sizeof(CommitMessage)) + return HR_INVALID_MESSAGE; + memcpy(&message, msg.ptr, sizeof(message)); + + node_log(state, "RECV COMMIT", "commit=%d", message.commit_index); + + // In RECOVERY and VIEW_CHANGE we ignore COMMIT messages. + // It's important we don't reset the timer so that the + // recovery and view change mechanism can retry on timeout. + if (state->status != STATUS_NORMAL) + return HR_OK; + + advance_commit_index(state, message.commit_index, false); + state->heartbeat = state->now; + return HR_OK; +} + +static HandlerResult +process_new_state(NodeState *state, int conn_idx, ByteView msg) +{ + (void) conn_idx; + + NewStateMessage new_state_message; + if (msg.len < sizeof(NewStateMessage)) + return HR_INVALID_MESSAGE; + memcpy(&new_state_message, msg.ptr, sizeof(new_state_message)); + + node_log(state, "RECV NEW_STATE", "entries=%d commit=%d view=%lu", + new_state_message.op_number, new_state_message.commit_index, new_state_message.view_number); + + // Ignore if we're in a different view + if (new_state_message.view_number != state->view_number) + return HR_OK; + + int num_entries = (msg.len - sizeof(NewStateMessage)) / sizeof(LogEntry); + if (num_entries != new_state_message.op_number) + return HR_INVALID_MESSAGE; + + if (num_entries == 0) + return HR_OK; + + // Append received entries to our log + LogEntry *entries = (LogEntry *)((uint8_t *)msg.ptr + sizeof(NewStateMessage)); + for (int i = 0; i < num_entries; i++) { + + LogEntry entry = { + .oper = entries[i].oper, + .votes = 0, + .view_number = state->view_number, + .client_id = entries[i].client_id, + .request_id = entries[i].request_id, + }; + if (log_append(&state->log, entry) < 0) + return HR_OUT_OF_MEMORY; + + // Send PREPARE_OK for each appended entry + PrepareOKMessage prepare_ok_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_PREPARE_OK, + .length = sizeof(PrepareOKMessage), + }, + .sender_idx = self_idx(state), + .log_index = state->log.count - 1, + .view_number = state->view_number, + }; + node_log(state, "SEND PREPARE_OK", "to=%d idx=%d key=%.16s", leader_idx(state), state->log.count - 1, + state->log.entries[state->log.count - 1].oper.key); + send_to_peer(state, leader_idx(state), &prepare_ok_message.base); + } + + process_future_list(state); + advance_commit_index(state, new_state_message.commit_index, false); + + state->state_transfer_pending = false; + state->heartbeat = state->now; // TODO: Should only do this if the sender is the primary + return HR_OK; +} + +static HandlerResult +send_redirect(NodeState *state, int conn_idx) +{ + RedirectMessage redirect_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_REDIRECT, + .length = sizeof(RedirectMessage), + }, + .view_number = state->view_number, + }; + + node_log(state, "SEND REDIRECT", "-> conn %d view=%lu leader=%d", + tcp_get_tag(&state->tcp, conn_idx), + (unsigned long)state->view_number, leader_idx(state)); + + ByteQueue *output = tcp_output_buffer(&state->tcp, conn_idx); + assert(output); + + byte_queue_write(output, &redirect_message, redirect_message.base.length); + return HR_OK; +} + +static HandlerResult +process_message_as_replica(NodeState *state, + int conn_idx, uint8_t type, ByteView msg) +{ switch (type) { case MESSAGE_TYPE_REQUEST: - { - // Do nothing. Replicas ignore client requests. - } + if (state->status == STATUS_NORMAL) + return send_redirect(state, conn_idx); break; + case MESSAGE_TYPE_PREPARE: - { - PrepareMessage prepare_message; - if (msg.len != sizeof(prepare_message)) - return -1; - memcpy(&prepare_message, msg.ptr, sizeof(prepare_message)); + return process_prepare(state, msg); - // Stale peer - if (prepare_message.view_number < state->view_number) - break; - - if (prepare_message.view_number > state->view_number) { - // The new leader has started a view we haven't seen. - // Adopt the new view and process the PREPARE normally. - { - Time t = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA): adopting view %lu from PREPARE (was view %lu, status %s)", - TIME_VAL(t), self_idx(state), - (unsigned long)prepare_message.view_number, - (unsigned long)state->view_number, - status_name(state->status)); - } - state->view_number = prepare_message.view_number; - state->status = STATUS_NORMAL; - state->begin_view_change_votes = 0; - state->num_future = 0; - } - - if (prepare_message.log_index > state->log.count) { - // The prepare message for a previous log entry was not received yet. - // Buffer this message to process it later - if (state->num_future == FUTURE_LIMIT) { - assert(0); // TODO - } - state->future[state->num_future++] = prepare_message; - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA): PREPARE log_index=%d buffered (expected %d), num_future=%d", - TIME_VAL(now), self_idx(state), - prepare_message.log_index, state->log.count, - state->num_future); - } - - } else if (prepare_message.log_index < state->log.count) { - // Message refers to an old entry. Ignore. - } else { - - LogEntry log_entry = { - .oper = prepare_message.oper, - .votes = 0, - .view_number = state->view_number, - }; - - if (log_append(&state->log, log_entry) < 0) { - assert(0); // TODO - } - - PrepareOKMessage prepare_ok_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_PREPARE_OK, - .length = sizeof(PrepareOKMessage), - }, - .sender_idx = self_idx(state), - .log_index = state->log.count-1, - .view_number = state->view_number, - }; - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA) -> node %d: PREPARE_OK log_index=%d view=%lu", - TIME_VAL(now), self_idx(state), - prepare_message.sender_idx, - state->log.count-1, - (unsigned long)state->view_number); - } - - if (send_to_peer(state, prepare_message.sender_idx, &prepare_ok_message.base) < 0) { - assert(0); - } - - // Now try to process future log - bool processed_at_least_one; - do { - processed_at_least_one = false; - for (int i = 0; i < state->num_future; i++) { - - if (state->future[i].log_index < state->log.count) { - state->future[i--] = state->future[--state->num_future]; - continue; - } - - if (state->future[i].log_index == state->log.count) { - - LogEntry future_log_entry = { - .oper = state->future[i].oper, - .votes = 0, - .view_number = state->view_number, - }; - if (log_append(&state->log, future_log_entry) < 0) { - assert(0); // TODO - } - - PrepareOKMessage prepare_ok_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_PREPARE_OK, - .length = sizeof(PrepareOKMessage), - }, - .sender_idx = self_idx(state), - .log_index = state->log.count-1, - .view_number = state->view_number, - }; - if (send_to_peer(state, state->future[i].sender_idx, &prepare_ok_message.base) < 0) { - assert(0); - } - - processed_at_least_one = true; - break; - } - } - } while (processed_at_least_one); - - while (state->commit_index < prepare_message.commit_index && state->commit_index < state->log.count) { - state_machine_update(&state->state_machine, state->log.entries[state->commit_index].oper); - state->commit_index++; - } - - Time now = get_current_time(); - if (now == INVALID_TIME) { - assert(0); - } - state->last_heartbeat_time = now; - } - } - break; case MESSAGE_TYPE_COMMIT: - { - CommitMessage message; + return process_commit(state, conn_idx, msg); - if (msg.len != sizeof(CommitMessage)) - return -1; - memcpy(&message, msg.ptr, sizeof(message)); - - // Don't process heartbeats from a stale leader during - // a view change, as it would reset the retry timer and - // prevent the view change from completing. - if (state->status == STATUS_CHANGE_VIEW) - break; - - if (message.commit_index > state->commit_index) { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA): COMMIT advancing commit_index %d -> %d", - TIME_VAL(now), self_idx(state), - state->commit_index, message.commit_index); - } - - while (state->commit_index < message.commit_index && state->commit_index < state->log.count) { - state_machine_update(&state->state_machine, state->log.entries[state->commit_index].oper); - state->commit_index++; - } - - Time now = get_current_time(); - if (now == INVALID_TIME) { - assert(0); - } - state->last_heartbeat_time = now; - } - break; case MESSAGE_TYPE_BEGIN_VIEW_CHANGE: - { - if (state->status == STATUS_RECOVERY) break; + return process_begin_view_change(state, conn_idx, msg); - BeginViewChangeMessage begin_view_change_message; - if (msg.len != sizeof(BeginViewChangeMessage)) - return -1; - memcpy(&begin_view_change_message, msg.ptr, sizeof(begin_view_change_message)); - - if (begin_view_change_message.view_number > state->view_number) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA): BEGIN_VIEW_CHANGE from node %d, transitioning view %lu -> %lu", - TIME_VAL(now), self_idx(state), - begin_view_change_message.sender_idx, - (unsigned long)state->view_number, - (unsigned long)begin_view_change_message.view_number); - } - - // Reset vote tracking when transitioning to a new view - state->begin_view_change_votes = 0; - state->view_number = begin_view_change_message.view_number; - state->status = STATUS_CHANGE_VIEW; - - // Send our own BeginViewChange to all peers - BeginViewChangeMessage own_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_BEGIN_VIEW_CHANGE, - .length = sizeof(BeginViewChangeMessage), - }, - .view_number = state->view_number, - .sender_idx = self_idx(state), - }; - - if (broadcast_to_peers(state, &own_message.base) < 0) { - assert(0); - } - // Count our own vote - state->begin_view_change_votes |= (1 << self_idx(state)); - } - - // Track this sender's vote (only if view matches) - if (begin_view_change_message.view_number == state->view_number) { - state->begin_view_change_votes |= (1 << begin_view_change_message.sender_idx); - } - - // Count votes - int vote_count = 0; - for (int i = 0; i < state->num_nodes; i++) { - if (state->begin_view_change_votes & (1 << i)) vote_count++; - } - - // Need f + 1 votes to send DoViewChange - if (vote_count >= state->num_nodes / 2 + 1) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA): f+1 BEGIN_VIEW_CHANGE votes reached (%d/%d), sending DO_VIEW_CHANGE to node %d for view %lu", - TIME_VAL(now), self_idx(state), - vote_count, state->num_nodes, - (int)(state->view_number % state->num_nodes), - (unsigned long)state->view_number); - } - - DoViewChangeMessage do_view_change_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_DO_VIEW_CHANGE, - .length = sizeof(DoViewChangeMessage) + state->log.count * sizeof(LogEntry), - }, - .view_number = state->view_number, - .old_view_number = state->view_number - 1, // View before we started view change - .op_number = state->log.count, - .commit_index = state->commit_index, - .sender_idx = self_idx(state), - }; - if (leader_idx(state) == self_idx(state)) { - // We are the new leader: count our own vote directly - // since send_to_peer_ex skips self-sends. - state->do_view_change_votes |= (1 << self_idx(state)); - } else { - if (send_to_peer_ex(state, leader_idx(state), &do_view_change_message.base, state->log.entries, state->log.count * sizeof(LogEntry)) < 0) { - assert(0); - } - } - - // Clear the future array since we're changing views - state->num_future = 0; - } - } - break; case MESSAGE_TYPE_BEGIN_VIEW: - { - BeginViewMessage message; + return process_begin_view(state, conn_idx, msg); - if (msg.len < sizeof(message)) - return -1; - memcpy(&message, msg.ptr, sizeof(message)); - - // Replicas only process messages containing a view-number - // that matches or advances the one they know[cite: 738, 812]. - if (message.view_number < state->view_number) - break; - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA): BEGIN_VIEW received, adopting view %lu (commit_index=%d, log_entries=%d)", - TIME_VAL(now), self_idx(state), - (unsigned long)message.view_number, - message.commit_index, message.op_number); - } - - // Update view and status - state->view_number = message.view_number; - state->status = STATUS_NORMAL; // Paper state: change status to normal - - // Replace the local log with the authoritative log from the primary - { - int num_entries = (msg.len - sizeof(BeginViewMessage)) / sizeof(LogEntry); - LogEntry *entries = malloc(num_entries * sizeof(LogEntry)); - if (entries == NULL) { - assert(0); - } - memcpy(entries, (uint8_t*)msg.ptr + sizeof(BeginViewMessage), num_entries * sizeof(LogEntry)); - - log_free(&state->log); - state->log.count = num_entries; - state->log.capacity = num_entries; - state->log.entries = entries; - } - - // Reset view change state - state->begin_view_change_votes = 0; - - // If there are non-committed operations in the log, - // send a PREPAREOK to the new primary - if (state->log.count > message.commit_index) { - PrepareOKMessage ok_msg = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_PREPARE_OK, - .length = sizeof(PrepareOKMessage), - }, - .sender_idx = self_idx(state), - .log_index = state->log.count - 1, - .view_number = state->view_number, - }; - if (send_to_peer(state, leader_idx(state), &ok_msg.base) < 0) { - assert(0); - } - } - - // Execute all operations known to be committed that haven't - // been executed previously - while (state->commit_index < message.commit_index && state->commit_index < state->log.count) { - state_machine_update(&state->state_machine, state->log.entries[state->commit_index].oper); - state->commit_index++; - } - - Time now = get_current_time(); - if (now == INVALID_TIME) { - assert(0); - } - state->last_heartbeat_time = now; - } - break; case MESSAGE_TYPE_RECOVERY: - { - if (state->status != STATUS_NORMAL) - break; // Ignore message. + return process_recovery(state, conn_idx, msg); - RecoveryMessage recovery_message; - if (msg.len != sizeof(RecoveryMessage)) - return -1; - memcpy(&recovery_message, msg.ptr, sizeof(recovery_message)); - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA): RECOVERY from node %d (nonce=%lu), sending RECOVERY_RESPONSE", - TIME_VAL(now), self_idx(state), - recovery_message.sender_idx, - (unsigned long)recovery_message.nonce); - } - - RecoveryResponseMessage recovery_response_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_RECOVERY_RESPONSE, - .length = sizeof(RecoveryResponseMessage), - }, - .view_number = state->view_number, - .op_number = state->log.count-1, // TODO: What if the log is empty? - .nonce = recovery_message.nonce, - .commit_index = state->commit_index, - .sender_idx = self_idx(state), - }; - - if (send_to_peer(state, recovery_message.sender_idx, &recovery_response_message.base) < 0) { - assert(0); - } - } - break; case MESSAGE_TYPE_RECOVERY_RESPONSE: - { - RecoveryResponseMessage message; + return process_recovery_response(state, msg); - if (msg.len < sizeof(message)) - return -1; - memcpy(&message, msg.ptr, sizeof(message)); + case MESSAGE_TYPE_NEW_STATE: + return process_new_state(state, conn_idx, msg); - // 1. Only process responses if we are actually in the recovering state [cite: 237] - // 2. Ensure the nonce matches the one we sent to prevent accepting - // delayed responses from previous recovery attempts[cite: 253]. - if (state->status != STATUS_RECOVERY || message.nonce != state->recovery_nonce) { - break; - } - - // Track this response (e.g., in a bitmask or array) - state->recovery_votes |= (1 << message.sender_idx); - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (RECOVERY): RECOVERY_RESPONSE from node %d, view=%lu op_number=%d commit_index=%d", - TIME_VAL(now), self_idx(state), - message.sender_idx, - (unsigned long)message.view_number, - message.op_number, message.commit_index); - } - - // Track the highest view number we've seen and who the primary is for it - if (message.view_number > state->max_view_seen) { - state->max_view_seen = message.view_number; - state->latest_primary_idx = (message.view_number % state->num_nodes); - } - - // Store the state from the primary if this message is from them - if (message.sender_idx == (int) (message.view_number % state->num_nodes)) { - // Copy the log from the variable-sized portion of the message - int num_entries = (msg.len - sizeof(RecoveryResponseMessage)) / sizeof(LogEntry); - LogEntry *entries = malloc(num_entries * sizeof(LogEntry)); - if (entries == NULL) { - assert(0); - } - memcpy(entries, (uint8_t*)msg.ptr + sizeof(RecoveryResponseMessage), num_entries * sizeof(LogEntry)); - - log_free(&state->potential_primary_log); - state->potential_primary_log.count = num_entries; - state->potential_primary_log.capacity = num_entries; - state->potential_primary_log.entries = entries; - - state->received_primary_state = true; - } - - // Check if we have f + 1 responses - int response_count = 0; - for (int i = 0; i < state->num_nodes; i++) { - if (state->recovery_votes & (1 << i)) response_count++; - } - - // The threshold f is derived from 2f + 1 = num_nodes [cite: 66, 73] - int f = (state->num_nodes - 1) / 2; - - if (response_count >= f + 1 && state->received_primary_state) { - - { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d: recovery complete (responses=%d, f+1=%d), adopting view %lu", - TIME_VAL(now), self_idx(state), - response_count, f + 1, - (unsigned long)state->max_view_seen); - } - - // Update state using information from the primary - state->view_number = state->max_view_seen; - - // Move the log (no need to copy since we're transferring ownership) - log_free(&state->log); - state->log = state->potential_primary_log; - state->potential_primary_log = (Log){0}; // Clear to avoid double-free - - state->commit_index = message.commit_index; - - // Change status to normal; the recovery protocol is complete - state->status = STATUS_NORMAL; - - // Update heartbeat to avoid immediate view change timeout - Time now = get_current_time(); - if (now == INVALID_TIME) { - assert(0); - } - state->last_heartbeat_time = now; - } - } - break; default: break; } - return 0; + return HR_OK; } -static int +static HandlerResult process_message(NodeState *state, int conn_idx, uint8_t type, ByteView msg) { - Time now = get_current_time(); - NODE_TRACE("[" TIME_FMT "] node %d (%s, %s) <- conn %d: recv %s (%d bytes)", - TIME_VAL(now), self_idx(state), - is_leader(state) ? "LEADER" : "REPLICA", - status_name(state->status), - conn_idx, message_type_name(type), (int)msg.len); - // Tag incoming connections with the sender's node index so that // the connection can be used bidirectionally. Without this, when // node A connects to node B and sends a message, node B can't @@ -1320,6 +1325,12 @@ process_message(NodeState *state, sender_idx = m.sender_idx; } break; + case MESSAGE_TYPE_GET_STATE: + if (msg.len >= sizeof(GetStateMessage)) { + GetStateMessage m; memcpy(&m, msg.ptr, sizeof(m)); + sender_idx = m.sender_idx; + } + break; } if (sender_idx >= 0 && sender_idx < state->num_nodes) { int existing = tcp_index_from_tag(&state->tcp, sender_idx); @@ -1354,6 +1365,8 @@ int node_init(void *state_, int argc, char **argv, fprintf(stderr, "Node :: Couldn't get current time\n"); return -1; } + if (now > state->now) + state->now = now; state->num_nodes = 0; @@ -1409,24 +1422,26 @@ int node_init(void *state_, int argc, char **argv, Time deadline = INVALID_TIME; state->view_number = 0; - state->last_heartbeat_time = now; + state->last_normal_view = 0; + state->heartbeat = now; state->commit_index = 0; state->num_future = 0; + state->state_transfer_pending = false; + state->state_transfer_time = 0; // View change state - state->begin_view_change_votes = 0; - state->do_view_change_votes = 0; - state->do_view_change_best_old_view = 0; - state->do_view_change_best_commit = 0; - log_init(&state->do_view_change_best_log); + state->view_change_begin_votes = 0; + state->view_change_apply_votes = 0; + state->view_change_old_view = 0; + state->view_change_commit = 0; + log_init(&state->view_change_log); // Recovery state state->recovery_votes = 0; - state->max_view_seen = 0; - state->latest_primary_idx = 0; - state->received_primary_state = false; - state->recovery_attempt_count = 0; - log_init(&state->potential_primary_log); + state->recovery_commit = 0; + state->recovery_view = 0; + state->recovery_log_view = 0; + log_init(&state->recovery_log); // Detect whether this is a restart after a crash by checking for a // boot marker file on disk. The disk persists across crashes, so if @@ -1443,14 +1458,17 @@ int node_init(void *state_, int argc, char **argv, if (previously_crashed) { state->status = STATUS_RECOVERY; state->recovery_nonce = now; - state->recovery_start_time = now; + state->recovery_time = now; } else { state->status = STATUS_NORMAL; } + log_init(&state->log); // Initialize early so node_log can read log.count + node_log(state, "INIT", "nodes=%d%s", state->num_nodes, previously_crashed ? " (recovering)" : ""); client_table_init(&state->client_table); + state->next_client_tag = NODE_LIMIT; // Make sure they don't overlap with node indices - state_machine_init(&state->state_machine); + kvstore_init(&state->kvstore); if (tcp_context_init(&state->tcp) < 0) { fprintf(stderr, "Node :: Couldn't setup TCP context\n"); @@ -1464,8 +1482,6 @@ int node_init(void *state_, int argc, char **argv, return -1; } - log_init(&state->log); - // Write the boot marker to disk so that future restarts can detect // a previous crash. This must happen after TCP init so that the // marker is only written if the node successfully started. @@ -1476,6 +1492,7 @@ int node_init(void *state_, int argc, char **argv, } if (previously_crashed) { + node_log(state, "STATUS RECOVERY", "nonce=%lu (crash detected)", state->recovery_nonce); // Broadcast RECOVERY to all peers to learn the current view RecoveryMessage recovery_message = { .base = { @@ -1486,21 +1503,11 @@ int node_init(void *state_, int argc, char **argv, .sender_idx = self_idx(state), .nonce = state->recovery_nonce, }; - - if (broadcast_to_peers(state, &recovery_message.base) < 0) { - assert(0); // TODO - } - - nearest_deadline(&deadline, state->recovery_start_time + RECOVERY_TIMEOUT_SEC * 1000000000ULL); + node_log(state, "SEND RECOVERY", "to=* nonce=%lu", state->recovery_nonce); + broadcast_to_peers(state, &recovery_message.base); + nearest_deadline(&deadline, state->recovery_time + RECOVERY_TIMEOUT_SEC * 1000000000ULL); } - NODE_TRACE("[" TIME_FMT "] node %d initialized: %s, view=%lu, num_nodes=%d, status=%s", - TIME_VAL(now), self_idx(state), - is_leader(state) ? "LEADER" : "REPLICA", - (unsigned long)state->view_number, - state->num_nodes, - status_name(state->status)); - *timeout = deadline_to_timeout(deadline, now); if (pcap < TCP_POLL_CAPACITY) { fprintf(stderr, "Node :: Not enough poll() capacity (got %d, needed %d)\n", pcap, TCP_POLL_CAPACITY); @@ -1515,10 +1522,9 @@ int node_tick(void *state_, void **ctxs, { NodeState *state = state_; - Time now = get_current_time(); - if (now == INVALID_TIME) { - assert(0); // TODO - } + state->now = get_current_time(); + if (state->now == INVALID_TIME) + return -1; ///////////////////////////////////////////////////////////////// // NETWORK EVENTS @@ -1529,14 +1535,10 @@ int node_tick(void *state_, void **ctxs, for (int i = 0; i < num_events; i++) { - if (events[i].type == EVENT_DISCONNECT) { - tcp_close(&state->tcp, events[i].conn_idx); - continue; - } if (events[i].type != EVENT_MESSAGE) continue; - int conn_idx = events[i].conn_idx; + int conn_idx = events[i].conn_idx; for (;;) { ByteView msg; @@ -1549,11 +1551,14 @@ int node_tick(void *state_, void **ctxs, break; } - ret = process_message(state, conn_idx, msg_type, msg); - if (ret < 0) { + HandlerResult hret = process_message(state, conn_idx, msg_type, msg); + if (hret == HR_INVALID_MESSAGE) { tcp_close(&state->tcp, conn_idx); break; } + if (hret == HR_OUT_OF_MEMORY) + return -1; + assert(hret == HR_OK); tcp_consume_message(&state->tcp, conn_idx); } @@ -1570,41 +1575,31 @@ int node_tick(void *state_, void **ctxs, // Recovery handling runs regardless of leader/replica position, // since a recovering node must not act as leader until it learns // the current view from its peers. - Time recovery_deadline = state->recovery_start_time + RECOVERY_TIMEOUT_SEC * 1000000000ULL; - if (recovery_deadline <= now) { - - state->recovery_attempt_count++; - if (state->recovery_attempt_count >= RECOVERY_ATTEMPT_LIMIT) { - assert(0); // TODO - } else { - RecoveryMessage recovery_message = { - .base = { - .version = MESSAGE_VERSION, - .type = MESSAGE_TYPE_RECOVERY, - .length = sizeof(RecoveryMessage), - }, - .sender_idx = self_idx(state), - .nonce = state->recovery_nonce, - }; - - if (broadcast_to_peers(state, &recovery_message.base) < 0) { - assert(0); // TODO - } - - state->recovery_start_time = now; - } + Time recovery_deadline = state->recovery_time + RECOVERY_TIMEOUT_SEC * 1000000000ULL; + if (recovery_deadline <= state->now) { + node_log_simple(state, "TIMEOUT RECOVERY"); + RecoveryMessage recovery_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_RECOVERY, + .length = sizeof(RecoveryMessage), + }, + .sender_idx = self_idx(state), + .nonce = state->recovery_nonce, + }; + node_log(state, "SEND RECOVERY", "to=* nonce=%lu", state->recovery_nonce); + broadcast_to_peers(state, &recovery_message.base); + state->recovery_votes = 0; + state->recovery_log_view = 0; + state->recovery_time = state->now; } else { nearest_deadline(&deadline, recovery_deadline); } } else if (is_leader(state)) { - Time heartbeat_deadline = state->last_heartbeat_time + HEARTBEAT_INTERVAL_SEC * 1000000000ULL; - if (heartbeat_deadline <= now) { // TODO: check the time conversion here - - NODE_TRACE("[" TIME_FMT "] node %d (LEADER): heartbeat timeout, sending COMMIT to all peers (commit_index=%d)", - TIME_VAL(now), self_idx(state), state->commit_index); - + Time heartbeat_deadline = state->heartbeat + HEARTBEAT_INTERVAL_SEC * 1000000000ULL; + if (heartbeat_deadline <= state->now) { // TODO: check the time conversion here CommitMessage commit_message = { .base = { .version = MESSAGE_VERSION, @@ -1613,23 +1608,46 @@ int node_tick(void *state_, void **ctxs, }, .commit_index = state->commit_index, }; - if (broadcast_to_peers(state, &commit_message.base)) { - assert(0); // TODO - } - state->last_heartbeat_time = now; + node_log(state, "SEND COMMIT", "to=* commit=%d", state->commit_index); + broadcast_to_peers(state, &commit_message.base); + state->heartbeat = state->now; } else { nearest_deadline(&deadline, heartbeat_deadline); } } else { - Time death_deadline = state->last_heartbeat_time + PRIMARY_DEATH_TIMEOUT_SEC * 1000000000ULL; - if (death_deadline <= now) { + // State transfer retry: if we're waiting for missing log entries + // and the timeout has elapsed, re-send GET_STATE to the primary. + if (state->state_transfer_pending) { - NODE_TRACE("[" TIME_FMT "] node %d (REPLICA, %s): primary death timeout, initiating view change to view %lu", - TIME_VAL(now), self_idx(state), - status_name(state->status), - (unsigned long)(state->view_number + 1)); + Time st_deadline = state->state_transfer_time + STATE_TRANSFER_TIMEOUT_SEC * 1000000000ULL; + if (st_deadline <= state->now) { + node_log(state, "TIMEOUT STATE_TRANSFER", "op=%d", state->log.count); + GetStateMessage get_state_message = { + .base = { + .version = MESSAGE_VERSION, + .type = MESSAGE_TYPE_GET_STATE, + .length = sizeof(GetStateMessage), + }, + .view_number = state->view_number, + .op_number = state->log.count, + .sender_idx = self_idx(state), + }; + node_log(state, "SEND GET_STATE", "to=%d op=%d", leader_idx(state), state->log.count); + send_to_peer(state, leader_idx(state), &get_state_message.base); + state->state_transfer_time = state->now; + } else { + nearest_deadline(&deadline, st_deadline); + } + } + + int death_timeout = (state->status == STATUS_CHANGE_VIEW) + ? VIEW_CHANGE_TIMEOUT_SEC : PRIMARY_DEATH_TIMEOUT_SEC; + Time death_deadline = state->heartbeat + death_timeout * 1000000000ULL; + if (death_deadline <= state->now) { + + node_log_simple(state, "TIMEOUT PRIMARY_DEATH"); BeginViewChangeMessage begin_view_change_message = { .base = { @@ -1640,17 +1658,19 @@ int node_tick(void *state_, void **ctxs, .view_number = state->view_number + 1, .sender_idx = self_idx(state), }; - if (broadcast_to_peers(state, &begin_view_change_message.base)) { - assert(0); // TODO - } + node_log(state, "SEND BEGIN_VIEW_CHG", "to=* view=%lu", state->view_number + 1); + broadcast_to_peers(state, &begin_view_change_message.base); + state->status = STATUS_CHANGE_VIEW; - state->last_heartbeat_time = now; + node_log(state, "STATUS CHANGE_VIEW", "view=%lu", state->view_number + 1); + state->heartbeat = state->now; + } else { nearest_deadline(&deadline, death_deadline); } } - *timeout = deadline_to_timeout(deadline, now); + *timeout = deadline_to_timeout(deadline, state->now); if (pcap < TCP_POLL_CAPACITY) return -1; *pnum = tcp_register_events(&state->tcp, ctxs, pdata); @@ -1661,85 +1681,14 @@ int node_free(void *state_) { NodeState *state = state_; + node_log_simple(state, "CRASHED"); + log_free(&state->log); - log_free(&state->potential_primary_log); - log_free(&state->do_view_change_best_log); + log_free(&state->recovery_log); + log_free(&state->view_change_log); tcp_context_free(&state->tcp); client_table_free(&state->client_table); - state_machine_free(&state->state_machine); + kvstore_free(&state->kvstore); return 0; } -void check_vsr_invariants(NodeState **nodes, int num_nodes) -{ - for (int i = 0; i < num_nodes; i++) { - NodeState *s = nodes[i]; - if (s == NULL) - continue; - - // 1. commit_index <= log.count - // A node cannot have committed more entries than it has in its log. - if (s->commit_index > s->log.count) { - fprintf(stderr, "INVARIANT VIOLATED: node %d: commit_index (%d) > log.count (%d)\n", - i, s->commit_index, s->log.count); - __builtin_trap(); - } - - // 2. commit_index >= 0 - if (s->commit_index < 0) { - fprintf(stderr, "INVARIANT VIOLATED: node %d: commit_index (%d) < 0\n", - i, s->commit_index); - __builtin_trap(); - } - - // 4. Future buffer count is in valid range. - if (s->num_future < 0 || s->num_future > FUTURE_LIMIT) { - fprintf(stderr, "INVARIANT VIOLATED: node %d: num_future (%d) out of range [0, %d]\n", - i, s->num_future, FUTURE_LIMIT); - __builtin_trap(); - } - } - - // Cross-node invariants - - // 5. At most one leader in normal status per view. - for (int i = 0; i < num_nodes; i++) { - if (nodes[i] == NULL || nodes[i]->status != STATUS_NORMAL || !is_leader(nodes[i])) - continue; - for (int j = i + 1; j < num_nodes; j++) { - if (nodes[j] == NULL || nodes[j]->status != STATUS_NORMAL || !is_leader(nodes[j])) - continue; - if (nodes[i]->view_number == nodes[j]->view_number) { - fprintf(stderr, "INVARIANT VIOLATED: two normal leaders in view %lu: node %d and node %d\n", - (unsigned long)nodes[i]->view_number, i, j); - __builtin_trap(); - } - } - } - - // 6. Committed prefix agreement (State Machine Safety). - // For any two nodes, their logs must agree on all entries up to - // min(commit_index_i, commit_index_j). This is the core safety - // property of VSR: all committed operations are identical across - // replicas. - for (int i = 0; i < num_nodes; i++) { - if (nodes[i] == NULL) - continue; - for (int j = i + 1; j < num_nodes; j++) { - if (nodes[j] == NULL) - continue; - - int min_commit = nodes[i]->commit_index; - if (nodes[j]->commit_index < min_commit) - min_commit = nodes[j]->commit_index; - - for (int k = 0; k < min_commit; k++) { - if (memcmp(&nodes[i]->log.entries[k].oper, &nodes[j]->log.entries[k].oper, sizeof(Operation)) != 0) { - fprintf(stderr, "INVARIANT VIOLATED: committed log operation mismatch at index %d " - "between node %d and node %d\n", k, i, j); - __builtin_trap(); - } - } - } - } -} \ No newline at end of file diff --git a/vsr/node.h b/vsr/node.h index 14f8f36..228bbc5 100644 --- a/vsr/node.h +++ b/vsr/node.h @@ -5,7 +5,7 @@ #include #include -#include +#include #include "log.h" #include "config.h" @@ -28,22 +28,31 @@ enum { // Recovery Protocol MESSAGE_TYPE_RECOVERY, MESSAGE_TYPE_RECOVERY_RESPONSE, + + // State Transfer Protocol + MESSAGE_TYPE_GET_STATE, + MESSAGE_TYPE_NEW_STATE, + + // Client Redirect + MESSAGE_TYPE_REDIRECT, }; typedef struct { MessageHeader base; - Operation oper; + KVStoreOper oper; uint64_t client_id; uint64_t request_id; } RequestMessage; typedef struct { MessageHeader base; - Operation oper; + KVStoreOper oper; int sender_idx; int log_index; int commit_index; uint64_t view_number; + uint64_t client_id; + uint64_t request_id; } PrepareMessage; typedef struct { @@ -61,7 +70,8 @@ typedef struct { typedef struct { MessageHeader base; bool rejected; - OperationResult result; + KVStoreResult result; + uint64_t request_id; } ReplyMessage; typedef struct { @@ -103,6 +113,26 @@ typedef struct { int sender_idx; } RecoveryResponseMessage; +typedef struct { + MessageHeader base; + uint64_t view_number; + int op_number; // Requester's current log count + int sender_idx; +} GetStateMessage; + +typedef struct { + MessageHeader base; + uint64_t view_number; + int op_number; // Number of log entries that follow + int commit_index; + // Followed by: LogEntry log[op_number] +} NewStateMessage; + +typedef struct { + MessageHeader base; + uint64_t view_number; +} RedirectMessage; + typedef enum { STATUS_NORMAL, STATUS_CHANGE_VIEW, @@ -120,27 +150,28 @@ typedef struct { Status status; ClientTable client_table; + int next_client_tag; uint64_t view_number; + uint64_t last_normal_view; // Latest view where status was NORMAL // These fields are used in recovery mode uint32_t recovery_votes; uint64_t recovery_nonce; - uint64_t max_view_seen; - int latest_primary_idx; - bool received_primary_state; - Log potential_primary_log; - Time recovery_start_time; - int recovery_attempt_count; + uint64_t recovery_view; + Log recovery_log; + uint64_t recovery_log_view; + Time recovery_time; + int recovery_commit; /////////////////////////////////////////////////////////// // VIEW CHANGE - uint32_t begin_view_change_votes; // Bitmask of received BeginViewChange messages - uint32_t do_view_change_votes; // Bitmask of received DoViewChange messages - uint64_t do_view_change_best_old_view; // Best old_view_number seen in DoViewChange - int do_view_change_best_commit; // Best commit_index seen - Log do_view_change_best_log; // Best log seen + uint32_t view_change_begin_votes; + uint32_t view_change_apply_votes; + Log view_change_log; // Best log seen + uint64_t view_change_old_view; // Best old_view_number seen in DoViewChange + int view_change_commit; // Best commit_index seen /////////////////////////////////////////////////////////// @@ -152,11 +183,17 @@ typedef struct { PrepareMessage future[FUTURE_LIMIT]; int num_future; + bool state_transfer_pending; + Time state_transfer_time; + Log log; - Time last_heartbeat_time; + Time heartbeat; - StateMachine state_machine; + KVStore kvstore; + + // Set at each wakeup + Time now; } NodeState; @@ -171,6 +208,19 @@ int node_tick(void *state, void **ctxs, int node_free(void *state); -void check_vsr_invariants(NodeState **nodes, int num_nodes); +typedef struct { + int last_min_commit; + int last_max_commit; + Status prev_status[NODE_LIMIT]; + + // External shadow log of committed operations (unbounded, dynamically allocated) + KVStoreOper *shadow_log; + int shadow_count; + int shadow_capacity; +} InvariantChecker; + +void invariant_checker_init(InvariantChecker *ic); +void invariant_checker_free(InvariantChecker *ic); +void invariant_checker_run(InvariantChecker *ic, NodeState **nodes, int num_nodes); #endif // NODE_INCLUDED \ No newline at end of file