cozis/ToastyFS
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Add client trace lines and fix random client first-operation bug

Browse Source 
Add logging infrastructure to client.c mirroring the server's node_log
pattern, with trace lines for: init, async put/get/delete, begin
transfers, replay requests, all received message types (store ack, fetch
chunk response, redirect, reply, get blob response), disconnects, and
unexpected messages.

Add result/operation trace lines to random_client.c and fix a bug where
the random client never started its first operation (the condition
`result.type != TOASTYFS_RESULT_VOID` was always false on the first
tick since no operation was pending).

https://claude.ai/code/session_0184gHjra7fsmSPZ4kppaGhC
This commit is contained in:
Claude
2026-02-21 13:41:22 +00:00
parent ab2ee3fe3b
commit 6e60b41f1b
3 changed files with 104 additions and 3 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/client.c
+76
View File
@@ -14,6 +14,7 @@
#include "metadata.h" #include "metadata.h"
#include "server.h" #include "server.h"
#include <toastyfs.h> #include <toastyfs.h>
#include <stdio.h>
typedef enum { typedef enum {
STEP_IDLE, STEP_IDLE,
@@ -73,6 +74,48 @@ struct ToastyFS {
int put_data_len; int put_data_len;
}; };
// ---- Client logging infrastructure (mirrors server node_log) ----
#define TIME_FMT "%7.3fs"
#define TIME_VAL(t) ((double)(t) / 1000000000.0)
static const char *step_name(Step step)
{
switch (step) {
case STEP_IDLE: return "IDLE";
case STEP_STORE_CHUNK: return "STORE_CHUNK";
case STEP_COMMIT: return "COMMIT";
case STEP_DELETE: return "DELETE";
case STEP_GET: return "GET";
case STEP_FETCH_CHUNK: return "FETCH_CHUNK";
case STEP_GET_DONE: return "GET_DONE";
case STEP_PUT_DONE: return "PUT_DONE";
case STEP_DELETE_DONE: return "DELETE_DONE";
}
return "??";
}
static void client_log_impl(ToastyFS *tfs, const char *event, const char *detail)
{
Time now = get_current_time();
printf("[" TIME_FMT "] CLIENT %lu %-12s V%-3lu | %-20s %s\n",
TIME_VAL(now),
tfs->client_id,
step_name(tfs->step),
tfs->view_number,
event,
detail ? detail : "");
}
#define client_log(tfs, event, fmt, ...) do { \
char _detail[1024]; \
snprintf(_detail, sizeof(_detail), fmt, ##__VA_ARGS__); \
client_log_impl(tfs, event, _detail); \
} while (0)
#define client_log_simple(tfs, event) \
client_log_impl(tfs, event, NULL)
#warning "TODO: Replace compute_chunk_hash with a proper SHA256 implementation" #warning "TODO: Replace compute_chunk_hash with a proper SHA256 implementation"
static SHA256 compute_chunk_hash(const char *data, int size) static SHA256 compute_chunk_hash(const char *data, int size)
{ {
@@ -112,6 +155,7 @@ ToastyFS *toastyfs_init(uint64_t client_id, char **addrs, int num_addrs)
tfs->step = STEP_IDLE; tfs->step = STEP_IDLE;
tfs->put_data = NULL; tfs->put_data = NULL;
tfs->put_data_len = 0; tfs->put_data_len = 0;
client_log(tfs, "INIT", "id=%lu servers=%d", client_id, num_addrs);
return tfs; return tfs;
} }
@@ -224,6 +268,8 @@ static int begin_transfers(ToastyFS *tfs)
} }
} }
if (num > 0)
client_log(tfs, "BEGIN_TRANSFERS", "started=%d total=%d", num, tfs->num_transfers);
return num; return num;
} }
@@ -249,6 +295,7 @@ mark_waiting_transfers_for_hash_as_aborted(ToastyFS *tfs, SHA256 hash)
static void replay_request(ToastyFS *tfs) static void replay_request(ToastyFS *tfs)
{ {
tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error
client_log(tfs, "REPLAY", "step=%s view=%lu", step_name(tfs->step), tfs->view_number);
switch (tfs->step) { switch (tfs->step) {
case STEP_COMMIT: case STEP_COMMIT:
@@ -335,6 +382,7 @@ static int process_message(ToastyFS *tfs,
assert(transfer_idx > -1); assert(transfer_idx > -1);
if (resp.size == 0) { if (resp.size == 0) {
client_log(tfs, "RECV FETCH_RESP", "size=0 (not found)");
tfs->transfers[transfer_idx].state = TRANSFER_ABORTED; tfs->transfers[transfer_idx].state = TRANSFER_ABORTED;
break; break;
} }
@@ -350,15 +398,18 @@ static int process_message(ToastyFS *tfs,
tfs->transfers[transfer_idx].data = copy; tfs->transfers[transfer_idx].data = copy;
tfs->transfers[transfer_idx].size = resp.size; tfs->transfers[transfer_idx].size = resp.size;
mark_waiting_transfers_for_hash_as_aborted(tfs, resp.hash); mark_waiting_transfers_for_hash_as_aborted(tfs, resp.hash);
client_log(tfs, "RECV FETCH_RESP", "size=%u", resp.size);
if (begin_transfers(tfs) == 0) { if (begin_transfers(tfs) == 0) {
tfs->error = TOASTYFS_ERROR_VOID; tfs->error = TOASTYFS_ERROR_VOID;
tfs->step = STEP_GET_DONE; tfs->step = STEP_GET_DONE;
client_log_simple(tfs, "ALL CHUNKS FETCHED");
} else { } else {
tfs->step = STEP_FETCH_CHUNK; tfs->step = STEP_FETCH_CHUNK;
} }
} else { } else {
client_log(tfs, "RECV UNEXPECTED", "type=%d in FETCH_CHUNK", type);
tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE; tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE;
tfs->step = STEP_GET_DONE; tfs->step = STEP_GET_DONE;
} }
@@ -373,6 +424,8 @@ static int process_message(ToastyFS *tfs,
return -1; return -1;
memcpy(&ack, msg.ptr, sizeof(ack)); memcpy(&ack, msg.ptr, sizeof(ack));
client_log(tfs, "RECV STORE_ACK", "success=%d", ack.success);
if (ack.success) { if (ack.success) {
int transfer_idx = find_started_transfer_by_hash(tfs, ack.hash); int transfer_idx = find_started_transfer_by_hash(tfs, ack.hash);
@@ -407,17 +460,21 @@ static int process_message(ToastyFS *tfs,
send_message_to_server(tfs, leader_idx(tfs), &msg.base); send_message_to_server(tfs, leader_idx(tfs), &msg.base);
tfs->request_id++; tfs->request_id++;
tfs->step = STEP_COMMIT; tfs->step = STEP_COMMIT;
client_log(tfs, "SEND COMMIT_PUT", "key=%s chunks=%d req=%lu",
tfs->key, tfs->num_chunks, tfs->request_id);
} else { } else {
tfs->step = STEP_STORE_CHUNK; tfs->step = STEP_STORE_CHUNK;
} }
} else { } else {
client_log_simple(tfs, "STORE FAILED");
tfs->error = TOASTYFS_ERROR_TRANSFER_FAILED; tfs->error = TOASTYFS_ERROR_TRANSFER_FAILED;
tfs->step = STEP_PUT_DONE; tfs->step = STEP_PUT_DONE;
} }
} else { } else {
client_log(tfs, "RECV UNEXPECTED", "type=%d in STORE_CHUNK", type);
tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE; tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE;
tfs->step = STEP_PUT_DONE; tfs->step = STEP_PUT_DONE;
} }
@@ -432,6 +489,7 @@ static int process_message(ToastyFS *tfs,
return -1; return -1;
memcpy(&redirect, msg.ptr, sizeof(redirect)); memcpy(&redirect, msg.ptr, sizeof(redirect));
client_log(tfs, "RECV REDIRECT", "view=%lu", redirect.view_number);
if (redirect.view_number > tfs->view_number) { if (redirect.view_number > tfs->view_number) {
tfs->view_number = redirect.view_number; tfs->view_number = redirect.view_number;
replay_request(tfs); replay_request(tfs);
@@ -448,22 +506,26 @@ static int process_message(ToastyFS *tfs,
return 0; return 0;
if (reply.rejected) { if (reply.rejected) {
client_log_simple(tfs, "RECV REPLY REJECTED");
tfs->error = TOASTYFS_ERROR_REJECTED; tfs->error = TOASTYFS_ERROR_REJECTED;
tfs->step = STEP_PUT_DONE; tfs->step = STEP_PUT_DONE;
break; break;
} }
if (reply.result.type == META_RESULT_FULL) { if (reply.result.type == META_RESULT_FULL) {
client_log_simple(tfs, "RECV REPLY FULL");
tfs->error = TOASTYFS_ERROR_FULL; tfs->error = TOASTYFS_ERROR_FULL;
tfs->step = STEP_PUT_DONE; tfs->step = STEP_PUT_DONE;
break; break;
} }
assert(reply.result.type == META_RESULT_OK); assert(reply.result.type == META_RESULT_OK);
client_log_simple(tfs, "RECV REPLY OK");
tfs->error = TOASTYFS_ERROR_VOID; tfs->error = TOASTYFS_ERROR_VOID;
tfs->step = STEP_PUT_DONE; tfs->step = STEP_PUT_DONE;
} else { } else {
client_log(tfs, "RECV UNEXPECTED", "type=%d in COMMIT", type);
tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE; tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE;
tfs->step = STEP_PUT_DONE; tfs->step = STEP_PUT_DONE;
} }
@@ -478,6 +540,7 @@ static int process_message(ToastyFS *tfs,
return -1; return -1;
memcpy(&redirect, msg.ptr, sizeof(redirect)); memcpy(&redirect, msg.ptr, sizeof(redirect));
client_log(tfs, "RECV REDIRECT", "view=%lu", redirect.view_number);
if (redirect.view_number > tfs->view_number) { if (redirect.view_number > tfs->view_number) {
tfs->view_number = redirect.view_number; tfs->view_number = redirect.view_number;
replay_request(tfs); replay_request(tfs);
@@ -494,22 +557,26 @@ static int process_message(ToastyFS *tfs,
break; break;
if (reply.rejected) { if (reply.rejected) {
client_log_simple(tfs, "RECV REPLY REJECTED");
tfs->error = TOASTYFS_ERROR_REJECTED; tfs->error = TOASTYFS_ERROR_REJECTED;
tfs->step = STEP_DELETE_DONE; tfs->step = STEP_DELETE_DONE;
break; break;
} }
if (reply.result.type == META_RESULT_FULL) { if (reply.result.type == META_RESULT_FULL) {
client_log_simple(tfs, "RECV REPLY FULL");
tfs->error = TOASTYFS_ERROR_FULL; tfs->error = TOASTYFS_ERROR_FULL;
tfs->step = STEP_DELETE_DONE; tfs->step = STEP_DELETE_DONE;
break; break;
} }
assert(reply.result.type == META_RESULT_OK); assert(reply.result.type == META_RESULT_OK);
client_log_simple(tfs, "RECV REPLY OK");
tfs->error = TOASTYFS_ERROR_VOID; tfs->error = TOASTYFS_ERROR_VOID;
tfs->step = STEP_DELETE_DONE; tfs->step = STEP_DELETE_DONE;
} else { } else {
client_log(tfs, "RECV UNEXPECTED", "type=%d in DELETE", type);
tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE; tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE;
tfs->step = STEP_DELETE_DONE; tfs->step = STEP_DELETE_DONE;
} }
@@ -524,6 +591,7 @@ static int process_message(ToastyFS *tfs,
return -1; return -1;
memcpy(&redirect, msg.ptr, sizeof(redirect)); memcpy(&redirect, msg.ptr, sizeof(redirect));
client_log(tfs, "RECV REDIRECT", "view=%lu", redirect.view_number);
if (redirect.view_number > tfs->view_number) { if (redirect.view_number > tfs->view_number) {
tfs->view_number = redirect.view_number; tfs->view_number = redirect.view_number;
replay_request(tfs); replay_request(tfs);
@@ -536,6 +604,9 @@ static int process_message(ToastyFS *tfs,
return -1; return -1;
memcpy(&resp, msg.ptr, sizeof(resp)); memcpy(&resp, msg.ptr, sizeof(resp));
client_log(tfs, "RECV GET_BLOB_RESP", "found=%d chunks=%u size=%lu",
resp.found, resp.num_chunks, resp.size);
if (resp.found) { if (resp.found) {
tfs->num_transfers = 0; tfs->num_transfers = 0;
@@ -566,6 +637,7 @@ static int process_message(ToastyFS *tfs,
} }
} else { } else {
client_log(tfs, "RECV UNEXPECTED", "type=%d in GET", type);
tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE; tfs->error = TOASTYFS_ERROR_UNEXPECTED_MESSAGE;
tfs->step = STEP_GET_DONE; tfs->step = STEP_GET_DONE;
} }
@@ -587,6 +659,7 @@ void toastyfs_process_events(ToastyFS *tfs, void **ctxs, struct pollfd *pdata, i
if (events[i].type == EVENT_DISCONNECT) { if (events[i].type == EVENT_DISCONNECT) {
int conn_idx = events[i].conn_idx; int conn_idx = events[i].conn_idx;
client_log(tfs, "DISCONNECT", "conn=%d", conn_idx);
tcp_close(&tfs->tcp, conn_idx); tcp_close(&tfs->tcp, conn_idx);
continue; continue;
} }
@@ -701,6 +774,7 @@ int toastyfs_async_put(ToastyFS *tfs, char *key, int key_len,
tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error
tfs->step = STEP_STORE_CHUNK; tfs->step = STEP_STORE_CHUNK;
client_log(tfs, "ASYNC PUT", "key=%s size=%d chunks=%d", tfs->key, data_len, num_chunks);
if (begin_transfers(tfs) == 0) { if (begin_transfers(tfs) == 0) {
// Early completion // Early completion
@@ -735,6 +809,7 @@ int toastyfs_async_get(ToastyFS *tfs, char *key, int key_len)
tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error
tfs->step = STEP_GET; tfs->step = STEP_GET;
client_log(tfs, "ASYNC GET", "key=%s leader=%d", tfs->key, leader_idx(tfs));
send_message_to_server(tfs, leader_idx(tfs), &msg.base); send_message_to_server(tfs, leader_idx(tfs), &msg.base);
return 0; return 0;
} }
@@ -768,6 +843,7 @@ int toastyfs_async_delete(ToastyFS *tfs, char *key, int key_len)
tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error tfs->step_time = get_current_time(); // TODO: Handle INVALID_TIME error
tfs->step = STEP_DELETE; tfs->step = STEP_DELETE;
client_log(tfs, "ASYNC DELETE", "key=%s req=%lu leader=%d", tfs->key, tfs->request_id, leader_idx(tfs));
send_message_to_server(tfs, leader_idx(tfs), &msg.base); send_message_to_server(tfs, leader_idx(tfs), &msg.base);
return 0; return 0;
} }
src/random_client.c
+27 -3
View File
@@ -15,6 +15,20 @@
static uint64_t next_random_client_id = 100; static uint64_t next_random_client_id = 100;
static const char *error_name(ToastyFS_Error err)
{
switch (err) {
case TOASTYFS_ERROR_VOID: return "OK";
case TOASTYFS_ERROR_OUT_OF_MEMORY: return "OUT_OF_MEMORY";
case TOASTYFS_ERROR_UNEXPECTED_MESSAGE: return "UNEXPECTED_MSG";
case TOASTYFS_ERROR_REJECTED: return "REJECTED";
case TOASTYFS_ERROR_FULL: return "FULL";
case TOASTYFS_ERROR_NOT_FOUND: return "NOT_FOUND";
case TOASTYFS_ERROR_TRANSFER_FAILED: return "TRANSFER_FAILED";
}
return "??";
}
static uint64_t rng(void) static uint64_t rng(void)
{ {
#if defined(MAIN_SIMULATION) || defined(MAIN_TEST) #if defined(MAIN_SIMULATION) || defined(MAIN_TEST)
@@ -66,6 +80,7 @@ int random_client_init(void *state_, int argc, char **argv,
state->tfs = toastyfs_init(client_id, addrs, num_addrs); state->tfs = toastyfs_init(client_id, addrs, num_addrs);
if (state->tfs == NULL) if (state->tfs == NULL)
return -1; return -1;
state->started = false;
*timeout = 0; *timeout = 0;
if (pcap < TCP_POLL_CAPACITY) { if (pcap < TCP_POLL_CAPACITY) {
@@ -87,32 +102,41 @@ int random_client_tick(void *state_, void **ctxs,
case TOASTYFS_RESULT_VOID: case TOASTYFS_RESULT_VOID:
break; break;
case TOASTYFS_RESULT_PUT: case TOASTYFS_RESULT_PUT:
printf(" RANDOM_CLIENT :: PUT result=%s\n", error_name(result.error));
break; break;
case TOASTYFS_RESULT_GET: case TOASTYFS_RESULT_GET:
printf(" RANDOM_CLIENT :: GET result=%s size=%d\n", error_name(result.error), result.size);
free(result.data); free(result.data);
break; break;
case TOASTYFS_RESULT_DELETE: case TOASTYFS_RESULT_DELETE:
printf(" RANDOM_CLIENT :: DELETE result=%s\n", error_name(result.error));
break; break;
} }
// Start a new random operation if idle (previous result was consumed) // Start a new random operation if idle (previous result was consumed,
if (result.type != TOASTYFS_RESULT_VOID) { // or this is the first tick and no operation has been started yet)
if (result.type != TOASTYFS_RESULT_VOID || !state->started) {
state->started = true;
char key[64]; char key[64];
int key_len = snprintf(key, sizeof(key), "k%d", (int)(rng() % 64)); int key_len = snprintf(key, sizeof(key), "k%d", (int)(rng() % 64));
switch (choose_random_oper()) { RandomOper oper = choose_random_oper();
switch (oper) {
case OPER_PUT: case OPER_PUT:
{ {
char data[CHUNK_SIZE]; char data[CHUNK_SIZE];
for (int i = 0; i < CHUNK_SIZE; i++) for (int i = 0; i < CHUNK_SIZE; i++)
data[i] = rng() & 0xFF; data[i] = rng() & 0xFF;
printf(" RANDOM_CLIENT :: starting PUT key=%s size=%d\n", key, CHUNK_SIZE);
toastyfs_async_put(state->tfs, key, key_len, data, CHUNK_SIZE); toastyfs_async_put(state->tfs, key, key_len, data, CHUNK_SIZE);
} }
break; break;
case OPER_GET: case OPER_GET:
printf(" RANDOM_CLIENT :: starting GET key=%s\n", key);
toastyfs_async_get(state->tfs, key, key_len); toastyfs_async_get(state->tfs, key, key_len);
break; break;
case OPER_DELETE: case OPER_DELETE:
printf(" RANDOM_CLIENT :: starting DELETE key=%s\n", key);
toastyfs_async_delete(state->tfs, key, key_len); toastyfs_async_delete(state->tfs, key, key_len);
break; break;
} }
src/random_client.h
+1
View File
@@ -11,6 +11,7 @@
typedef struct { typedef struct {
ToastyFS *tfs; ToastyFS *tfs;
bool started;
} RandomClient; } RandomClient;
struct pollfd; struct pollfd;