From fd731ceaaf3686a908f29435aef84b817b42b563 Mon Sep 17 00:00:00 2001 From: Cococry Date: Wed, 29 Jul 2026 09:39:23 +0200 Subject: [PATCH] feat: debug feature to write client identies/credentials to disk --- faithd/src/auth/device_link.c | 42 +++++++------ faithd/src/auth/handshake.c | 52 ++++++++------- faithd/src/client/client.c | 94 +++++++++++++++++++++++++--- faithd/src/codec/protocol.c | 59 +++++++++-------- faithd/src/commands/conversation.c | 26 ++++---- faithd/src/commands/dispatch.c | 22 +++---- faithd/src/core/crypto.c | 10 +-- faithd/src/delivery/event_inbox.c | 5 +- faithd/src/delivery/routing.c | 11 +++- faithd/src/server/client_io.c | 34 +++++----- faithd/src/server/client_lifecycle.c | 20 +++--- faithd/src/server/dispatch.c | 29 +++++---- faithd/src/server/server.c | 6 +- faithd/src/server/sess_registry.c | 15 +++-- faithd/src/test/client_test_suite.c | 18 +++--- faithd/src/transport/conn.c | 26 ++++---- faithd/src/transport/frame.c | 36 ++++++----- faithd/src/transport/tls.c | 14 +++-- 18 files changed, 316 insertions(+), 203 deletions(-) diff --git a/faithd/src/auth/device_link.c b/faithd/src/auth/device_link.c index d219c00..6ef78f0 100644 --- a/faithd/src/auth/device_link.c +++ b/faithd/src/auth/device_link.c @@ -14,6 +14,8 @@ #include "../logging/logging.h" #include "handshake.h" +#define _MODULE_NAME "auth/device_link" + static faith_status_code_t send_device_auth_response_failed(server_state_t *s, client_conn_t *cl) { if (!s || !cl || cl->closing) @@ -47,19 +49,19 @@ device_link_handle_device_response(server_state_t *s, client_conn_t *cl, if (!req || !req_cl) { nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Server got %s but there is no " + "[%s: client=%" PRIu64 " fd=%i] Server got %s but there is no " "device link request pending. Rejecting envelope.", - cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); return FAITH_ERR_INVALID; } if (response_envl->type != FAITH_ENVELOPE_DEVICE_AUTH_APPROVE && response_envl->type != FAITH_ENVELOPE_DEVICE_AUTH_DENY) { nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Invalid envelope type. Expected " + "[%s: client=%" PRIu64 " fd=%i] Invalid envelope type. Expected " "FAITH_ENVELOPE_DEVICE_AUTH_APPROVE or " "FAITH_ENVELOPE_DEVICE_AUTH_DENY, got %s", - cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); return FAITH_ERR_INVALID; } @@ -68,9 +70,9 @@ device_link_handle_device_response(server_state_t *s, client_conn_t *cl, response_envl->body_size != FAITH_ENVL_CTS_DEVICE_LINK_RESPONSE_BODY_SIZE) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server got invalid %s envelope contents.", - cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); _FH_CHECK_RETURN(send_device_auth_response_failed(s, cl)); @@ -85,9 +87,9 @@ device_link_handle_device_response(server_state_t *s, client_conn_t *cl, faith_id128_to_hex(cl->ident.device_id.bytes, device_id_hex)); nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Server got unauthorized %s" + "[%s: client=%" PRIu64 " fd=%i] Server got unauthorized %s" "from client. Client (auth_id=%s, device_id=%s) is not authorized.", - cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type), + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type), auth_id_hex, device_id_hex); /* Return UNAUTHORIZED without rejecting/closing the client connection that @@ -104,10 +106,10 @@ device_link_handle_device_response(server_state_t *s, client_conn_t *cl, faith_id128_to_hex(req->device_id_new.bytes, req_device_id_hex)); nob_log(INFO, - "[client=%" PRIu64 " fd=%i] Client that requested" + "[%s: client=%" PRIu64 " fd=%i] Client that requested" "their device (device_id=%s) to be linked to auth_id=%s has " "already been closed.", - cl->conn.id, cl->conn.fd, req_auth_id_hex, req_device_id_hex); + _MODULE_NAME, cl->conn.id, cl->conn.fd, req_auth_id_hex, req_device_id_hex); _FH_CHECK_RETURN(send_device_auth_response_failed(s, cl)); @@ -121,9 +123,9 @@ device_link_handle_device_response(server_state_t *s, client_conn_t *cl, if (!faith_device_id_equal(response.device_id_new, req->device_id_new)) { nob_log( ERROR, - "[client=%" PRIu64 " fd=%i] Server got %s but the sent" + "[%s: client=%" PRIu64 " fd=%i] Server got %s but the sent" "device_id does not match the device_id that requested the approval.", - cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); _FH_CHECK_RETURN(send_device_auth_response_failed(s, cl)); @@ -134,9 +136,9 @@ device_link_handle_device_response(server_state_t *s, client_conn_t *cl, if (faith_now_ms() > cl->pending_device_link_req->expires_at_ms) { nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Server got %s but the " + "[%s: client=%" PRIu64 " fd=%i] Server got %s but the " "link request has already expired.", - cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); /* Reject the requesting client conection if the request has expired but * keep the responding one open. */ @@ -211,12 +213,12 @@ device_link_handle_device_response(server_state_t *s, client_conn_t *cl, * correct behaviour.*/ if (!sess) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server got %s but client connection that " "sent the envelope does not have registered session data. " "However, the client connection IS authorized, so there is " "probably a deeper issue.", - cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(response_envl->type)); _FH_CHECK_RETURN(send_device_auth_response_failed(s, cl)); @@ -303,12 +305,12 @@ defer: { _FH_CHECK_RETURN(faith_id128_to_hex(device_id_new.bytes, device_id_hex)); nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Client connection" + "[%s: client=%" PRIu64 " fd=%i] Client connection" "(auth_id=%s, device_id=%s) failed authorization for device link " "request; Error %s. Device with device_id=%s will not be linked to " "auth_id=%s. " "Closing connection. ", - req_cl->conn.id, req_cl->conn.fd, auth_id_hex, device_id_hex, + _MODULE_NAME, req_cl->conn.id, req_cl->conn.fd, auth_id_hex, device_id_hex, faith_status_code_name(_fh_result), device_id_hex, auth_id_hex); /* Don't propagate status code */ @@ -339,9 +341,9 @@ device_link_new_device(server_state_t *s, client_conn_t *cl, nob_log( INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Handling newly joined device (device_id=%s) for auth_id=%s.", - cl->conn.id, cl->conn.fd, new_device_id_hex, cl_auth_id_hex); + _MODULE_NAME, cl->conn.id, cl->conn.fd, new_device_id_hex, cl_auth_id_hex); } if (!sess_registry_auth_id_registered(&s->rt, ¶ms->sender_auth_id)) { diff --git a/faithd/src/auth/handshake.c b/faithd/src/auth/handshake.c index f9b3a12..41ef4fb 100644 --- a/faithd/src/auth/handshake.c +++ b/faithd/src/auth/handshake.c @@ -9,6 +9,8 @@ #include "../delivery/events.h" +#define _MODULE_NAME "auth/handshake" + faith_status_code_t auth_handle_hello(server_state_t *s, client_conn_t *cl, const faith_envelope_t *hello_envl) { // HELLO { @@ -30,8 +32,9 @@ faith_status_code_t auth_handle_hello(server_state_t *s, client_conn_t *cl, if (cl->state != CLIENT_WAIT_FOR_HELLO) { nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Server got invalid HELLO from client.", - cl->conn.id, cl->conn.fd); + "[%s: client=%" PRIu64 + " fd=%i] Server got invalid HELLO from client.", + _MODULE_NAME, cl->conn.id, cl->conn.fd); return FAITH_ERR_BAD_ENVELOPE; } @@ -89,18 +92,18 @@ faith_status_code_t auth_handle_challenge_response( if (challenge_response_envl->type != FAITH_ENVELOPE_CHALLENGE_RESPONSE) { nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Invalid envelope type. Expected " + "[%s: client=%" PRIu64 " fd=%i] Invalid envelope type. Expected " "FAITH_ENVELOPE_CHALLENGE_RESPONSE, got %s", - cl->conn.id, cl->conn.fd, + _MODULE_NAME, cl->conn.id, cl->conn.fd, faith_envelope_name(challenge_response_envl->type)); return FAITH_ERR_INVALID; } if (cl->state != CLIENT_WAIT_FOR_CHALLENGE_RESPONSE) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server got invalid CHALLENGE_RESPONSE from client.", - cl->conn.id, cl->conn.fd); + _MODULE_NAME, cl->conn.id, cl->conn.fd); return FAITH_ERR_BAD_ENVELOPE; } @@ -109,18 +112,18 @@ faith_status_code_t auth_handle_challenge_response( if (!faith_client_id_equal(challenge_response_envl->sender_id, params->sender_auth_id)) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server got CHALLENGE_RESPONSE from invalid client.", - cl->conn.id, cl->conn.fd); + _MODULE_NAME, cl->conn.id, cl->conn.fd); return FAITH_ERR_INVALID; } if (!challenge_response_envl->body || challenge_response_envl->body_size != FAITH_ED25519_SIGNATURE_SIZE) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server got invalid CHALLENGE_RESPONSE envelope contents.", - cl->conn.id, cl->conn.fd); + _MODULE_NAME, cl->conn.id, cl->conn.fd); return FAITH_ERR_INVALID; } @@ -140,9 +143,10 @@ faith_status_code_t auth_handle_challenge_response( _FH_CHECK_RETURN( faith_id128_to_hex(params->device_id.bytes, device_id_hex)); nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Failed to get routing session (auth_id=%s, device_id=%s).", - cl->conn.id, cl->conn.fd, sender_auth_id_hex, device_id_hex); + _MODULE_NAME, cl->conn.id, cl->conn.fd, sender_auth_id_hex, + device_id_hex); return sess_rc; } @@ -171,10 +175,12 @@ faith_status_code_t auth_handle_challenge_response( _FH_CHECK_RETURN( faith_id128_to_hex(params->device_id.bytes, device_id_hex)); nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] Rejected requested routing session " + "[%s: client=%" PRIu64 + " fd=%i] Rejected requested routing session " "(auth_id=%s, device_id=%s). " "Invalid public key sent.", - cl->conn.id, cl->conn.fd, sender_auth_id_hex, device_id_hex); + _MODULE_NAME, cl->conn.id, cl->conn.fd, sender_auth_id_hex, + device_id_hex); return FAITH_ERR_UNAUTHORIZED; } @@ -222,9 +228,9 @@ faith_status_code_t auth_handle_challenge_response( sizeof(msg_buf), &sign_msg)); if (_fh_rc != FAITH_OK) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Failed to generate signing message buffer", - cl->conn.id, cl->conn.fd); + _MODULE_NAME, cl->conn.id, cl->conn.fd); return _fh_rc; } @@ -273,10 +279,11 @@ reject: { faith_id128_to_hex(params->sender_auth_id.bytes, sender_auth_id_hex)); _FH_CHECK_RETURN(faith_id128_to_hex(params->device_id.bytes, device_id_hex)); nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Client failed authorization for requested routing session " "(auth_id=%s, device_id=%s). ", - cl->conn.id, cl->conn.fd, sender_auth_id_hex, device_id_hex); + _MODULE_NAME, cl->conn.id, cl->conn.fd, sender_auth_id_hex, + device_id_hex); return FAITH_ERR_UNAUTHORIZED; } } @@ -306,9 +313,10 @@ faith_status_code_t auth_authorize_client( faith_id128_to_hex(cl->ident.device_id.bytes, cl_device_id_hex)); nob_log(INFO, - "[client=%" PRIu64 " fd=%i] Client passed authorization for " + "[%s: client=%" PRIu64 " fd=%i] Client passed authorization for " "requested routing session. (auth_id=%s, device_id=%s)", - cl->conn.id, cl->conn.fd, cl_auth_id_hex, cl_device_id_hex); + _MODULE_NAME, cl->conn.id, cl->conn.fd, cl_auth_id_hex, + cl_device_id_hex); return FAITH_OK; } @@ -345,9 +353,9 @@ auth_handshake_complete(server_state_t *s, client_conn_t *cl, faith_id128_to_hex(cl->ident.device_id.bytes, device_id_hex)); nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server accepted HELLO (auth id: %s, device id: %s)", - cl->conn.id, cl->conn.fd, auth_id_hex, device_id_hex); + _MODULE_NAME, cl->conn.id, cl->conn.fd, auth_id_hex, device_id_hex); return _fh_result; } diff --git a/faithd/src/client/client.c b/faithd/src/client/client.c index 2faef4f..ec0ae32 100644 --- a/faithd/src/client/client.c +++ b/faithd/src/client/client.c @@ -2,6 +2,7 @@ #include #include #include +#include #include #include #include @@ -985,6 +986,13 @@ client_dispatch_event(faith_client_t *client, faith_status_code_t _fh_result = FAITH_OK; + if (g_log_enable_tracing) { + nob_log(INFO, + "[client] Dispatching server event %s (sequence number: %" PRIu64 + ")...", + faith_event_codec_type_name(event->type), event->seq_num); + } + switch (event->type) { case FAITH_EVENT_CONVERSATION_CREATED: _FH_CHECK_RETURN(client_handle_event_conversation_created(client, event)); @@ -995,6 +1003,13 @@ client_dispatch_event(faith_client_t *client, client->ev_last_dispatched_seq = event->seq_num; + if (g_log_enable_tracing) { + nob_log(INFO, + "[client] Dispatched server event %s (sequence number: %" PRIu64 + ")", + faith_event_codec_type_name(event->type), event->seq_num); + } + return _fh_result; } @@ -1031,6 +1046,10 @@ client_buffer_event(faith_client_t *client, slot->event.data = data_copy; slot->occupied = true; + nob_log(INFO, + "[client] Buffered out-of-order event (sequence number: %" PRIu64 ")", + event->seq_num); + return FAITH_OK; } @@ -1047,6 +1066,12 @@ static faith_status_code_t client_drain_reorder_buffer(faith_client_t *client) { if (!slot->occupied || slot->event.seq_num != next_seq) return FAITH_OK; + nob_log( + INFO, + "[client] Dispatching buffered out-of-order event in sequence order " + "(original sequence number: %" PRIu64 ")", + slot->event.seq_num); + /* advances of the client */ _FH_CHECK_RETURN(client_dispatch_event(client, &slot->event)); @@ -1071,6 +1096,11 @@ client_process_event(faith_client_t *client, if (client->ev_last_dispatched_seq != UINT64_MAX && event->seq_num <= client->ev_last_dispatched_seq) { + nob_log(WARNING, + "[client] Saw duplicate or stale event (sequence number: %" PRIu64 + ", current sequence: %" PRIu64 ")", + event->seq_num, client->ev_last_dispatched_seq); + *o_saw_duplicate = true; return FAITH_OK; } @@ -1690,7 +1720,8 @@ static faith_status_code_t client_make_handshake(faith_client_t *client, _FH_CHECK_RETURN(read_frame_sync(client->ssl, &frame)); - nob_log(INFO, "[client] Got new server response."); + if (g_log_enable_tracing) + nob_log(INFO, "[client] Got new server response."); if (frame.msg_type != FAITH_MSG_ENVL) { nob_log(ERROR, @@ -1715,13 +1746,11 @@ static faith_status_code_t client_make_handshake(faith_client_t *client, faith_free_frame(&frame); - if (g_log_enable_tracing) - - /* ========================== */ - /* Read next frame */ - /* ========================== */ + /* ========================== */ + /* Read next frame */ + /* ========================== */ - _FH_CHECK_RETURN(read_frame_sync(client->ssl, &frame)); + _FH_CHECK_RETURN(read_frame_sync(client->ssl, &frame)); _FH_CHECK_DEFER( faith_decode_envelope(frame.payload, frame.payload_size, &envl)); @@ -1889,6 +1918,46 @@ faith_status_code_t faith_client_init_global(int log_enable_tracing) { return FAITH_OK; } +static int write_identity(const char *path, + const client_side_identity_t *ident) { + FILE *f = fopen(path, "wb"); + if (!f) + return 0; + + int ok = + fwrite(ident->auth_id.bytes, sizeof ident->auth_id.bytes, 1, f) == 1 && + fwrite(ident->device_id.bytes, sizeof ident->device_id.bytes, 1, f) == + 1 && + fwrite(ident->private_key, sizeof ident->private_key, 1, f) == 1 && + fwrite(ident->public_key, sizeof ident->public_key, 1, f) == 1; + + fclose(f); + return ok; +} + +static int read_identity(const char *path, client_side_identity_t *ident) { + FILE *f = fopen(path, "rb"); + if (!f) + return 0; + + int ok = + fread(ident->auth_id.bytes, sizeof ident->auth_id.bytes, 1, f) == 1 && + fread(ident->device_id.bytes, sizeof ident->device_id.bytes, 1, f) == 1 && + fread(ident->private_key, sizeof ident->private_key, 1, f) == 1 && + fread(ident->public_key, sizeof ident->public_key, 1, f) == 1; + + fclose(f); + + if (!ok) + return 0; + + ident->keypair = EVP_PKEY_new_raw_private_key( + EVP_PKEY_ED25519, NULL, ident->private_key, sizeof ident->private_key); + + return 1; +} + +#define READ_IDENT "ident/23a2b2bf0b4457c86ad6127da2a1ae85.bin" static faith_status_code_t client_new_identity(client_side_identity_t *o_ident) { if (!o_ident) @@ -1896,6 +1965,10 @@ client_new_identity(client_side_identity_t *o_ident) { /* Generate 128 bit random device & auth identities */ +#ifdef READ_IDENT + char buf[33]; + read_identity(READ_IDENT, o_ident); +#else _FH_CHECK_RETURN(faith_random_bytes(o_ident->auth_id.bytes, sizeof(o_ident->auth_id.bytes))); @@ -1917,6 +1990,13 @@ client_new_identity(client_side_identity_t *o_ident) { auth_id_hex, device_id_hex); } + char buf[33]; + _FH_CHECK_RETURN(faith_id128_to_hex(o_ident->auth_id.bytes, buf)); + char filepath[PATH_MAX]; + snprintf(filepath, sizeof(filepath), "ident/%s.bin", buf); + write_identity(filepath, o_ident); +#endif + return FAITH_OK; } diff --git a/faithd/src/codec/protocol.c b/faithd/src/codec/protocol.c index 7fe31d2..b737bf8 100644 --- a/faithd/src/codec/protocol.c +++ b/faithd/src/codec/protocol.c @@ -7,6 +7,8 @@ #include "events.h" #include "helpers.h" +#define _MODULE_NAME "codec/protocol" + faith_status_code_t faith_encode_frame(uint8_t *out_buf, size_t *out_size, size_t buf_cap_in_bytes, const faith_frame_t *in) { @@ -44,15 +46,17 @@ faith_status_code_t faith_encode_frame(uint8_t *out_buf, size_t *out_size, frame_too_large: nob_log(ERROR, - "Failed to encode frame; Frame is too large, " + "[%s] Failed to encode frame; Frame is too large, " "frame_size=%u, MAX_FRAME_LEN=%i", - (uint32_t)frame_size, (int32_t)FAITH_MAX_FRAME_LEN); + _MODULE_NAME, (uint32_t)frame_size, (int32_t)FAITH_MAX_FRAME_LEN); return FAITH_ERR_TOO_LARGE; payload_too_large: nob_log(ERROR, - "Failed to encode frame; Payload is too large, " + "[%s] Failed to encode frame; Payload is too large, " "payload_size=%u, MAX_PAYLOAD_SIZE=%i", - (uint32_t)in->payload_size, (int32_t)FAITH_MAX_PAYLOAD_SIZE); + + _MODULE_NAME, (uint32_t)in->payload_size, + (int32_t)FAITH_MAX_PAYLOAD_SIZE); return FAITH_ERR_TOO_LARGE; } @@ -85,18 +89,18 @@ faith_status_code_t faith_decode_frame(const uint8_t *payload, if (frame_payload_size > FAITH_MAX_PAYLOAD_SIZE) { nob_log(ERROR, - "Failed to parse frame from buffer; " + "[%s] Failed to parse frame from buffer; " "payload_size=%zu MAX_PAYLOAD_SIZE=%zu", - payload_size, (size_t)FAITH_MAX_PAYLOAD_SIZE); + _MODULE_NAME, payload_size, (size_t)FAITH_MAX_PAYLOAD_SIZE); return FAITH_ERR_TOO_LARGE; } if (frame_size > FAITH_MAX_FRAME_LEN) { nob_log(ERROR, - "Failed to parse frame from buffer; Frame is too large, " + "[%s] Failed to parse frame from buffer; Frame is too large, " "frame_size=%i MAX_FRAME_LEN=%i", - (int32_t)frame_size, (int32_t)FAITH_MAX_FRAME_LEN); + _MODULE_NAME, (int32_t)frame_size, (int32_t)FAITH_MAX_FRAME_LEN); return FAITH_ERR_TOO_LARGE; } @@ -768,9 +772,9 @@ faith_codec_event_batch_data_size(faith_envl_stc_event_t *events, if (n_events > FAITH_EVENT_BATCH_MAX_EVENTS) { nob_log(ERROR, - "Invalid EVENT_BATCH body: event count %" PRIu16 + "[%s] Invalid EVENT_BATCH body: event count %" PRIu16 " exceeds maximum %u.", - n_events, FAITH_EVENT_BATCH_MAX_EVENTS); + _MODULE_NAME, n_events, FAITH_EVENT_BATCH_MAX_EVENTS); return FAITH_ERR_INVALID; } @@ -783,9 +787,9 @@ faith_codec_event_batch_data_size(faith_envl_stc_event_t *events, if (body_size > UINT16_MAX) { nob_log(ERROR, - "Cannot encode EVENT_BATCH: event %" PRIu16 + "[%s] Cannot encode EVENT_BATCH: event %" PRIu16 " body size (%zu bytes) exceeds UINT16_MAX.", - i, body_size); + _MODULE_NAME, i, body_size); return FAITH_ERR_TOO_LARGE; } @@ -793,9 +797,9 @@ faith_codec_event_batch_data_size(faith_envl_stc_event_t *events, if (encoded_elem_size > UINT32_MAX - total_data_size) { nob_log(ERROR, - "Cannot encode EVENT_BATCH: adding event %" PRIu16 + "[%s] Cannot encode EVENT_BATCH: adding event %" PRIu16 " would make the total event data exceed UINT32_MAX.", - i); + _MODULE_NAME, i); return FAITH_ERR_TOO_LARGE; } @@ -845,9 +849,9 @@ faith_encode_event_batch_body(uint8_t *out_buf, faith_body_size_t *out_size, if ((size_t)returned_body_size != body_size) { nob_log(ERROR, - "EVENT encoder returned an unexpected body size: " + "[%s] EVENT encoder returned an unexpected body size: " "expected %zu bytes, got %" PRIu32 " bytes.", - body_size, returned_body_size); + _MODULE_NAME, body_size, returned_body_size); return FAITH_ERR_INVALID; } offset += body_size; @@ -875,9 +879,9 @@ faith_decode_event_batch_body(const uint8_t *payload, if (out->n_events > FAITH_EVENT_BATCH_MAX_EVENTS) { nob_log(ERROR, - "Invalid EVENT_BATCH body: event count %" PRIu16 + "[%s] Invalid EVENT_BATCH body: event count %" PRIu16 " exceeds maximum %u.", - out->n_events, FAITH_EVENT_BATCH_MAX_EVENTS); + _MODULE_NAME, out->n_events, FAITH_EVENT_BATCH_MAX_EVENTS); return FAITH_ERR_BAD_ENVELOPE; } @@ -889,9 +893,9 @@ faith_decode_event_batch_body(const uint8_t *payload, if ((size_t)payload_size < decoded_size) { nob_log(ERROR, - "Invalid EVENT_BATCH body: declared events data size (%" PRIu32 + "[%s] Invalid EVENT_BATCH body: declared events data size (%" PRIu32 " bytes) exceeds remaining payload size (%" PRIu32 " bytes).", - out->events_data_size, + _MODULE_NAME, out->events_data_size, payload_size - FAITH_ENVL_STC_EVENT_BATCH_BODY_SIZE_FIXED); return FAITH_ERR_OVERFLOW; @@ -900,8 +904,9 @@ faith_decode_event_batch_body(const uint8_t *payload, size_t events_end = offset + (size_t)out->events_data_size; if (events_end != (size_t)payload_size) { - nob_log(ERROR, "Invalid EVENT_BATCH body: payload has %zu trailing bytes.", - (size_t)payload_size - events_end); + nob_log(ERROR, + "[%s] Invalid EVENT_BATCH body: payload has %zu trailing bytes.", + _MODULE_NAME, (size_t)payload_size - events_end); return FAITH_ERR_BAD_ENVELOPE; } @@ -919,19 +924,19 @@ faith_decode_event_batch_body(const uint8_t *payload, if (elem_size < FAITH_ENVL_STC_EVENT_BODY_SIZE_FIXED) { nob_log(ERROR, - "Invalid EVENT_BATCH body: event %" PRIu16 + "[%s] Invalid EVENT_BATCH body: event %" PRIu16 " declares an invalid body size of %" PRIu16 " bytes. The minimum required size for an event is: %" PRIu32 " bytes.", - i, elem_size, FAITH_ENVL_STC_EVENT_BODY_SIZE_FIXED); + _MODULE_NAME, i, elem_size, FAITH_ENVL_STC_EVENT_BODY_SIZE_FIXED); _FH_RETURN_DEFER(FAITH_ERR_BAD_ENVELOPE); } if (offset > payload_size || payload_size - offset < (size_t)elem_size) { nob_log(ERROR, - "Invalid EVENT_BATCH body: event %" PRIu16 " declares %" PRIu16 - " bytes, but only %zu bytes remain.", - i, elem_size, events_end - offset); + "[%s] Invalid EVENT_BATCH body: event %" PRIu16 + " declares %" PRIu16 " bytes, but only %zu bytes remain.", + _MODULE_NAME, i, elem_size, events_end - offset); _FH_RETURN_DEFER(FAITH_ERR_BAD_FRAME); } diff --git a/faithd/src/commands/conversation.c b/faithd/src/commands/conversation.c index 113a8f5..79f2847 100644 --- a/faithd/src/commands/conversation.c +++ b/faithd/src/commands/conversation.c @@ -7,7 +7,7 @@ static faith_status_code_t send_conversation_created( server_state_t *s, client_conn_t *cl, const faith_event_conversation_created_t *conv_created, - const faith_auth_id_t *conservant_id) { + const faith_auth_id_t* conservant_id) { if (!s || !cl || !conv_created) return FAITH_ERR_INVALID; @@ -18,19 +18,17 @@ static faith_status_code_t send_conversation_created( _FH_CHECK_RETURN(faith_encode_event_conversation_created( data, &data_size, sizeof(data), conv_created)); - _FH_CHECK_RETURN( - delivery_queue_event(s, &cl->ident.auth_id, &cl->ident.device_id, - FAITH_EVENT_CONVERSATION_CREATED, data, data_size)); + _FH_CHECK_RETURN(delivery_queue_event(s, &cl->ident.auth_id, &cl->ident.device_id, FAITH_EVENT_CONVERSATION_CREATED, + data, data_size)); faith_status_code_t device_loop_rc = FAITH_OK; - _FH_FOR_EACH_AUTH_DEVICE_SESSION( - s, conservant_id, recipient_sess, device_loop_rc, { - _FH_CHECK_RETURN(delivery_queue_event( - s, conservant_id, &recipient_sess->ident.device_id, - FAITH_EVENT_CONVERSATION_CREATED, data, data_size)); - }); + _FH_FOR_EACH_AUTH_DEVICE_SESSION(s, conservant_id, recipient_sess, device_loop_rc, { + _FH_CHECK_RETURN(delivery_queue_event( + s, conservant_id, &recipient_sess->ident.device_id, + FAITH_EVENT_CONVERSATION_CREATED, data, data_size)); + }); - return FAITH_OK; + return device_loop_rc; } faith_status_code_t conv_handle_create_conversation( @@ -65,15 +63,15 @@ faith_status_code_t conv_handle_create_conversation( faith_event_conversation_created_t conv_created = {.conversation_id = conv_id}; - _FH_CHECK_DEFER(send_conversation_created(s, cl, &conv_created, - &create_conv_cmd.conversant_id)); + _FH_CHECK_DEFER(send_conversation_created(s, cl, &conv_created, &create_conv_cmd.conversant_id)); *o_result = FAITH_COMMAND_RESULT_ACCEPTED; return FAITH_OK; defer: + (void)_fh_result; *o_result = FAITH_COMMAND_RESULT_REJECTED; *o_err = potential_err; - return _fh_result; + return FAITH_OK; } diff --git a/faithd/src/commands/dispatch.c b/faithd/src/commands/dispatch.c index eb7d076..23f1043 100644 --- a/faithd/src/commands/dispatch.c +++ b/faithd/src/commands/dispatch.c @@ -9,6 +9,8 @@ #include "conversation.h" +#define _MODULE_NAME "commands/dispatch" + static faith_status_code_t queue_command_result(server_state_t *s, client_conn_t *cl, const faith_command_id_t *cmd_id, @@ -47,8 +49,6 @@ faith_status_code_t command_dispatch(server_state_t *s, client_conn_t *cl, if (envl->type != FAITH_ENVELOPE_COMMAND) return FAITH_ERR_INVALID; - faith_status_code_t _fh_result = FAITH_OK; - faith_command_result_err_t err = FAITH_COMMAND_ERR_NONE; faith_command_result_t result = FAITH_COMMAND_RESULT_NONE; faith_envl_cts_command_t cmd = {0}; @@ -66,29 +66,23 @@ faith_status_code_t command_dispatch(server_state_t *s, client_conn_t *cl, switch (cmd.type) { case FAITH_COMMAND_CREATE_CONVERSATION: - _FH_CHECK_DEFER( + _FH_CHECK_RETURN( conv_handle_create_conversation(s, cl, &cmd, &result, &err)); break; default: - nob_log(ERROR, "[client=%" PRIu64 " fd=%i] Server got invalid COMMAND.", - cl->conn.id, cl->conn.fd); + nob_log(ERROR, "[%s: client=%" PRIu64 " fd=%i] Server got invalid COMMAND.", + _MODULE_NAME, cl->conn.id, cl->conn.fd); err = FAITH_COMMAND_ERR_BAD_COMMAND; result = FAITH_COMMAND_RESULT_REJECTED; - _FH_RETURN_DEFER(FAITH_ERR_INVALID); } if (result == FAITH_COMMAND_RESULT_NONE) { err = FAITH_COMMAND_ERR_BAD_COMMAND; result = FAITH_COMMAND_RESULT_REJECTED; - _FH_RETURN_DEFER(FAITH_ERR_INVALID); } -defer: { - _FH_CHECK(queue_command_result(s, cl, &cmd.cmd_id, cmd.type, err, result)); - if (_fh_rc != FAITH_OK) { - _fh_result = _fh_rc; - } -} - return _fh_result; + _FH_CHECK_RETURN( + queue_command_result(s, cl, &cmd.cmd_id, cmd.type, err, result)); + return FAITH_OK; } diff --git a/faithd/src/core/crypto.c b/faithd/src/core/crypto.c index 643a714..a3fee71 100644 --- a/faithd/src/core/crypto.c +++ b/faithd/src/core/crypto.c @@ -2,6 +2,8 @@ #include #include +#define _MODULE_NAME "core/crypto" + faith_status_code_t faith_random_bytes(uint8_t *o_buf, int num) { if (RAND_bytes(o_buf, num) != 1) { nob_log(ERROR, "Failed to generate auth_id with OpenSSL RAND_bytes()"); @@ -48,8 +50,8 @@ faith_gen_ed25519_keypair(void *handle, } if (priv_len != FAITH_ED25519_PRIVATE_KEY_SIZE) { - nob_log(ERROR, "Generated private key has unexpected byte size: %zu", - priv_len); + nob_log(ERROR, "[%s] Generated private key has unexpected byte size: %zu", + _MODULE_NAME, priv_len); status = FAITH_ERR_INVALID; goto cleanup; } @@ -69,8 +71,8 @@ faith_gen_ed25519_keypair(void *handle, } if (pub_len != FAITH_ED25519_PUBLIC_KEY_SIZE) { - nob_log(ERROR, "Generated public key has unexpected byte size: %zu", - pub_len); + nob_log(ERROR, "[%s] Generated public key has unexpected byte size: %zu", + _MODULE_NAME, pub_len); status = FAITH_ERR_INVALID; goto cleanup; } diff --git a/faithd/src/delivery/event_inbox.c b/faithd/src/delivery/event_inbox.c index 0377cdc..dad1a05 100644 --- a/faithd/src/delivery/event_inbox.c +++ b/faithd/src/delivery/event_inbox.c @@ -3,6 +3,8 @@ #include "../../third_party/stb_ds.h" #include +#define _MODULE_NAME "delivery/event_inbox" + void device_event_inbox_init(device_event_inbox_t *o_inbox) { if (!o_inbox) return; @@ -27,7 +29,8 @@ device_event_inbox_push_event(device_event_inbox_t *inbox, return FAITH_ERR_OVERFLOW; if (inbox->last_sent_seq != UINT64_MAX && event->seq_num != inbox->next_seq) { - nob_log(ERROR, "Tried to push event with invalid sequence order.\n"); + nob_log(ERROR, "[%s] Tried to push event with invalid sequence order.\n", + _MODULE_NAME); return FAITH_ERR_INVALID; } diff --git a/faithd/src/delivery/routing.c b/faithd/src/delivery/routing.c index 185722f..e837298 100644 --- a/faithd/src/delivery/routing.c +++ b/faithd/src/delivery/routing.c @@ -3,6 +3,8 @@ #include "../../third_party/stb_ds.h" +#define _MODULE_NAME "delivery/routing" + faith_status_code_t delivery_route_envelope_to_auth_id(server_state_t *s, client_conn_t *cl_sender, const faith_auth_id_t *recipient_auth_id, @@ -30,8 +32,9 @@ delivery_route_envelope_to_auth_id(server_state_t *s, client_conn_t *cl_sender, faith_id128_to_hex(recipient_auth_id->bytes, recipient_auth_id_hex)); nob_log(INFO, - "[client=%" PRIu64 " fd=%i] Envelope %s: Recipient " + "[%s: client=%" PRIu64 " fd=%i] Envelope %s: Recipient " "(auth_id: %s) is offline; Not routing envelope.", + _MODULE_NAME, cl_sender->conn.id, cl_sender->conn.fd, faith_envelope_name(envl->type), recipient_auth_id_hex); @@ -58,9 +61,10 @@ delivery_route_envelope_to_auth_id(server_state_t *s, client_conn_t *cl_sender, if (_fh_rc != FAITH_OK) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Envelope %s: Failed to route envelope to " "recipient device (auth_id: %s, device_id: %s).", + _MODULE_NAME, cl_sender->conn.id, cl_sender->conn.fd, faith_envelope_name(envl->type), recipient_auth_id_hex, recipient_device_id_hex); @@ -68,9 +72,10 @@ delivery_route_envelope_to_auth_id(server_state_t *s, client_conn_t *cl_sender, } nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Envelope %s: Routed envelope to recipient " "device (auth_id: %s, device_id: %s).", + _MODULE_NAME, cl_sender->conn.id, cl_sender->conn.fd, faith_envelope_name(envl->type), recipient_auth_id_hex, recipient_device_id_hex); diff --git a/faithd/src/server/client_io.c b/faithd/src/server/client_io.c index 4b1c4f8..7c8b60a 100644 --- a/faithd/src/server/client_io.c +++ b/faithd/src/server/client_io.c @@ -9,6 +9,8 @@ #include "dispatch.h" +#define _MODULE_NAME "server/client_io" + faith_status_code_t server_queue_frame(server_state_t *s, client_conn_t *cl, const faith_frame_t *frame) { if (!cl || cl->closing || !s || !frame || @@ -50,9 +52,9 @@ faith_status_code_t server_queue_frame(server_state_t *s, client_conn_t *cl, } } - nob_log(INFO, "[client=%" PRIu64 " fd=%d] queued frame: %s (%zu bytes)", - cl->conn.id, cl->conn.fd, faith_frame_msg_name(frame->msg_type), - wire_size); + nob_log(INFO, "[%s: client=%" PRIu64 " fd=%d] queued frame: %s (%zu bytes)", + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_frame_msg_name(frame->msg_type), wire_size); return FAITH_OK; defer: @@ -84,10 +86,10 @@ faith_status_code_t server_queue_envelope(server_state_t *s, client_conn_t *cl, _FH_CHECK_DEFER(server_queue_frame(s, cl, &frame)); nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server enqueued envelope: type=%s body_size=%u", - cl->conn.id, cl->conn.fd, faith_envelope_name(envl->type), - envl->body_size); + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_envelope_name(envl->type), envl->body_size); defer: free(payload); @@ -101,9 +103,9 @@ server_queue_envelope_or_mark_dead(server_state_t *s, client_conn_t *cl, if (_fh_rc == FAITH_OK) return FAITH_OK; - nob_log(ERROR, "[client=%" PRIu64 " fd=%d] Failed to queue %s: %s", - cl->conn.id, cl->conn.fd, faith_envelope_name(envl->type), - faith_status_code_name(_fh_rc)); + nob_log(ERROR, "[%s: client=%" PRIu64 " fd=%d] Failed to queue %s: %s", + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_envelope_name(envl->type), faith_status_code_name(_fh_rc)); cl->closing = true; return _fh_rc; @@ -214,8 +216,9 @@ faith_status_code_t server_drive_client_read(server_state_t *s, return -1; if (g_verbose_logging) { - nob_log(INFO, "[client=%" PRIu64 " fd=%i] Success handling client frame.", - cl->conn.id, cl->conn.fd); + nob_log(INFO, + "[%s: client=%" PRIu64 " fd=%i] Success handling client frame.", + _MODULE_NAME, cl->conn.id, cl->conn.fd); } reactor_events_t desired_interests = @@ -254,8 +257,9 @@ faith_status_code_t server_drive_client_read(server_state_t *s, "Connection closed while reading incomplete frame."); return -1; default: - nob_log(ERROR, "[client=%" PRIu64 " fd=%i] Failed to read client frame.", - cl->conn.id, cl->conn.fd); + nob_log(ERROR, + "[%s: client=%" PRIu64 " fd=%i] Failed to read client frame.", + _MODULE_NAME, cl->conn.id, cl->conn.fd); server_client_queue_disconnect(s, cl, FAITH_DISCONNECT_BAD_PROTOCOL, FAITH_CLIENT_RECONNECT_ALLOWED, 0, 0, @@ -265,8 +269,8 @@ faith_status_code_t server_drive_client_read(server_state_t *s, fail_ev_mask: nob_log(ERROR, - "[client=%" PRIu64 " fd=%d] reactor_modify_interests failed: %s", - cl->conn.id, cl->conn.fd, strerror(errno)); + "[%s: client=%" PRIu64 " fd=%d] reactor_modify_interests failed: %s", + _MODULE_NAME, cl->conn.id, cl->conn.fd, strerror(errno)); server_client_queue_disconnect(s, cl, FAITH_DISCONNECT_INTERNAL_ERROR, FAITH_CLIENT_RECONNECT_ALLOWED, 0, 0, diff --git a/faithd/src/server/client_lifecycle.c b/faithd/src/server/client_lifecycle.c index 5ddb19b..9315ae1 100644 --- a/faithd/src/server/client_lifecycle.c +++ b/faithd/src/server/client_lifecycle.c @@ -6,6 +6,8 @@ #include "../../third_party/stb_ds.h" +#define _MODULE_NAME "server/client_lifecycle" + faith_status_code_t server_client_adopt_fd(server_state_t *s, int client_fd) { struct client_conn_t *cl = calloc(1, sizeof(*cl)); @@ -60,9 +62,10 @@ faith_status_code_t server_close_client(server_state_t *s, if (rc != FAITH_OK) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%d] Failed to cancel pending device-link request: %s", - cl->conn.id, cl->conn.fd, faith_status_code_name(rc)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_status_code_name(rc)); if (result == FAITH_OK) result = rc; @@ -84,9 +87,10 @@ faith_status_code_t server_close_client(server_state_t *s, sess_registry_get_devices(&s->rt, &cl->ident.auth_id, &devices); if (rc != FAITH_OK || devices == NULL) { nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%d] Failed to enumerate account devices: %s", - cl->conn.id, cl->conn.fd, faith_status_code_name(rc)); + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_status_code_name(rc)); if (result == FAITH_OK) result = rc; } @@ -133,8 +137,8 @@ faith_status_code_t server_close_client(server_state_t *s, if (cl->conn.fd >= 0) { if (close(cl->conn.fd) < 0) { - nob_log(ERROR, "[client=%" PRIu64 " fd=%d] close failed: %s", cl->conn.id, - cl->conn.fd, strerror(errno)); + nob_log(ERROR, "[%s: client=%" PRIu64 " fd=%d] close failed: %s", + _MODULE_NAME, cl->conn.id, cl->conn.fd, strerror(errno)); if (result == FAITH_OK) result = FAITH_ERR_IO; @@ -157,8 +161,8 @@ faith_status_code_t server_close_client(server_state_t *s, } } - nob_log(INFO, "[client=%" PRIu64 " fd=%d] Closed client", log_conn_id, - log_fd); + nob_log(INFO, "[%s: client=%" PRIu64 " fd=%d] Closed client", _MODULE_NAME, + log_conn_id, log_fd); free(cl); diff --git a/faithd/src/server/dispatch.c b/faithd/src/server/dispatch.c index 47c5370..204d65c 100644 --- a/faithd/src/server/dispatch.c +++ b/faithd/src/server/dispatch.c @@ -12,6 +12,8 @@ #include "../commands/dispatch.h" +#define _MODULE_NAME "server/dispatch" + static faith_status_code_t server_dispatch_envelope(server_state_t *s, client_conn_t *cl, faith_frame_t *frame); @@ -33,10 +35,10 @@ static faith_status_code_t server_dispatch_envelope(server_state_t *s, faith_decode_envelope(frame->payload, frame->payload_size, &envl)); nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server is handling envelope: type=%s body_size=%u", - cl->conn.id, cl->conn.fd, faith_envelope_name(envl.type), - envl.body_size); + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_envelope_name(envl.type), envl.body_size); switch (envl.type) { case FAITH_ENVELOPE_HELLO: @@ -66,10 +68,10 @@ static faith_status_code_t server_dispatch_envelope(server_state_t *s, } nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server successfully handled envelope: type=%s body_size=%u", - cl->conn.id, cl->conn.fd, faith_envelope_name(envl.type), - envl.body_size); + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_envelope_name(envl.type), envl.body_size); defer: if (envl.body != NULL) @@ -90,9 +92,10 @@ server_handle_ping(server_state_t *s, client_conn_t *cl, faith_frame_t *frame) { faith_decode_ping(frame->payload, frame->payload_size, &ping)); nob_log(INFO, - "[client=%" PRIu64 " fd=%i] server got PING: nonce=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] server got PING: nonce=%" PRIu64 ", client_sent_at_ms=%lu", - cl->conn.id, cl->conn.fd, ping.nonce, ping.client_sent_at_ms); + _MODULE_NAME, cl->conn.id, cl->conn.fd, ping.nonce, + ping.client_sent_at_ms); /* 2. Send PONG over wire protocol */ uint64_t server_sent_at_ms = faith_now_ms(); @@ -116,9 +119,9 @@ server_handle_ping(server_state_t *s, client_conn_t *cl, faith_frame_t *frame) { nob_log( INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server sent PONG to client. nonce=%lu, server_sent_at_ms=%lu", - cl->conn.id, cl->conn.fd, ping.nonce, server_sent_at_ms); + _MODULE_NAME, cl->conn.id, cl->conn.fd, ping.nonce, server_sent_at_ms); return FAITH_OK; } @@ -129,10 +132,10 @@ faith_status_code_t server_dispatch_frame(server_state_t *s, client_conn_t *cl, return FAITH_ERR_INVALID; nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Server got frame: msg_type=%s payload_size=%u", - cl->conn.id, cl->conn.fd, faith_frame_msg_name(frame->msg_type), - frame->payload_size); + _MODULE_NAME, cl->conn.id, cl->conn.fd, + faith_frame_msg_name(frame->msg_type), frame->payload_size); switch (frame->msg_type) { case FAITH_MSG_PING: diff --git a/faithd/src/server/server.c b/faithd/src/server/server.c index 77f1030..b19000e 100644 --- a/faithd/src/server/server.c +++ b/faithd/src/server/server.c @@ -13,6 +13,8 @@ #include "../../third_party/nob.h" #include "../../third_party/stb_ds.h" +#define _MODULE_NAME "server/server" + static const char *client_state_name(client_state_t state); static void accept_clients(server_state_t *s); static void handle_client_event(server_state_t *s, client_conn_t *cl, @@ -395,7 +397,7 @@ void server_set_client_state(server_state_t *s, struct client_conn_t *cl, cl->state = state; if (g_verbose_logging) { - nob_log(INFO, "[client=%" PRIu64 " fd=%i] Client changed state to %s", - cl->conn.id, cl->conn.fd, client_state_name(state)); + nob_log(INFO, "[%s: client=%" PRIu64 " fd=%i] Client changed state to %s", + _MODULE_NAME, cl->conn.id, cl->conn.fd, client_state_name(state)); } } diff --git a/faithd/src/server/sess_registry.c b/faithd/src/server/sess_registry.c index a01862c..e7028d9 100644 --- a/faithd/src/server/sess_registry.c +++ b/faithd/src/server/sess_registry.c @@ -5,6 +5,8 @@ #define STB_DS_IMPLEMENTATION #include "../../third_party/stb_ds.h" +#define _MODULE_NAME "server/sess_registry" + faith_status_code_t sess_registry_get_user_from_auth_id(sess_registry_state_t *rt, const faith_auth_id_t *auth_id, @@ -86,10 +88,10 @@ faith_status_code_t sess_registry_register_session( _FH_CHECK_DEFER(faith_id128_to_hex(auth_id->bytes, auth_id_hex)); _FH_CHECK_DEFER(faith_id128_to_hex(device_id->bytes, device_id_hex)); - nob_log( - INFO, - "Registered session with auth_id=%s, device_id=%s (online clients: %zu)", - auth_id_hex, device_id_hex, hmlen(rt->active_users)); + nob_log(INFO, + "[%s] Registered session with auth_id=%s, device_id=%s (online " + "clients: %zu)", + _MODULE_NAME, auth_id_hex, device_id_hex, hmlen(rt->active_users)); return FAITH_OK; defer: @@ -164,9 +166,10 @@ sess_registry_unregister_session(sess_registry_state_t *rt, _FH_CHECK_RETURN(faith_id128_to_hex(device_id->bytes, device_id_hex)); nob_log(INFO, - "Unregistered session with auth_id=%s, device_id=%s (online clients: " + "[%s] Unregistered session with auth_id=%s, device_id=%s (online " + "clients: " "%zu)", - auth_id_hex, device_id_hex, hmlen(rt->active_users)); + _MODULE_NAME, auth_id_hex, device_id_hex, hmlen(rt->active_users)); return FAITH_OK; } diff --git a/faithd/src/test/client_test_suite.c b/faithd/src/test/client_test_suite.c index f758dd8..7fd1915 100644 --- a/faithd/src/test/client_test_suite.c +++ b/faithd/src/test/client_test_suite.c @@ -57,7 +57,8 @@ static bool client_id_from_hex(const char *hex, faith_auth_id_t *out) { } int main(int argc, char **argv) { - faith_client_init_global(true); + bool verbose_logging = true; + faith_client_init_global(verbose_logging); faith_client_config_t cfg = { .insecure_skip_verify = 1, @@ -223,8 +224,6 @@ int main(int argc, char **argv) { if (pending_device_link_request) printf("(y)es/n(o) ? "); - else - printf("> "); fflush(stdout); faith_client_free_event(&ev); @@ -236,12 +235,12 @@ int main(int argc, char **argv) { continue; } - printf("\rGot event: %s", faith_event_name(ev.type)); + if (verbose_logging) { + nob_log(INFO, "\rGot event: %s", faith_event_name(ev.type)); - if (strlen(ev.message) != 0) - printf(" message => %s\n", ev.message); - else - printf("\n"); + if (strlen(ev.message) != 0) + printf(" message => %s\n", ev.message); + } switch (ev.type) { case FAITH_EVENT_DEVICE_LINK_REQUEST: @@ -261,7 +260,6 @@ int main(int argc, char **argv) { } } - printf("> "); break; case FAITH_EVENT_AUTHORIZED: @@ -271,8 +269,6 @@ int main(int argc, char **argv) { default: if (pending_device_link_request) printf("(y)es/n(o) ? "); - else - printf("> "); break; } diff --git a/faithd/src/transport/conn.c b/faithd/src/transport/conn.c index 63cc5b3..78d5b3c 100644 --- a/faithd/src/transport/conn.c +++ b/faithd/src/transport/conn.c @@ -4,7 +4,7 @@ #include "../logging/logging.h" -#define _MODULE_NAME "[transport/conn] " +#define _MODULE_NAME "transport/conn" faith_status_code_t conn_init(transport_conn_t *conn) { if (!conn) @@ -25,7 +25,7 @@ transport_result_t conn_read_more_ssl_bytes(transport_conn_t *conn) { int nread = 0; int err = tls_read(&conn->tls, tmp, sizeof(tmp), &nread); if (err == INT_MAX) { - nob_log(ERROR, _MODULE_NAME "Invalid arguments specified for tls_read()"); + nob_log(ERROR, "[%s] Invalid arguments specified for tls_read()", _MODULE_NAME); return TRANSPORT_RES_ERROR; } @@ -47,7 +47,7 @@ transport_result_t conn_read_more_ssl_bytes(transport_conn_t *conn) { if (err == SSL_ERROR_ZERO_RETURN) return TRANSPORT_RES_CLOSED; - nob_log(ERROR, "tls_read() failed. SSL error: %i", err); + nob_log(ERROR, "[%s] tls_read() failed. SSL error: %i", _MODULE_NAME, err); ERR_print_errors_fp(stderr); return TRANSPORT_RES_ERROR; @@ -62,9 +62,9 @@ faith_status_code_t conn_flush_output(transport_conn_t *conn, if (!conn->out.buf) { nob_log(WARNING, - "[client=%" PRIu64 " fd=%i] Requested to flush output but output " + "[%s: client=%" PRIu64 " fd=%i] Requested to flush output but output " "queue buffer is not allocated.", - conn->id, conn->fd); + _MODULE_NAME, conn->id, conn->fd); return FAITH_OK; } @@ -80,15 +80,15 @@ faith_status_code_t conn_flush_output(transport_conn_t *conn, if (err == INT_MAX) { nob_log(ERROR, - "[client=%" PRIu64 " fd=%i] failed to write %i bytes over the " + "[%s: client=%" PRIu64 " fd=%i] failed to write %i bytes over the " "wire. Invalid arguments specified.", - conn->id, conn->fd, nwrite); + _MODULE_NAME, conn->id, conn->fd, nwrite); /* Fatal argument error => return immediately */ return FAITH_ERR_INVALID; } - nob_log(INFO, "[client=%" PRIu64 " fd=%i] wrote %i bytes over the wire.", - conn->id, conn->fd, nwrite); + nob_log(INFO, "[%s: client=%" PRIu64 " fd=%i] wrote %i bytes over the wire.", + _MODULE_NAME, conn->id, conn->fd, nwrite); if (nwrite > 0) { conn->out.off += (size_t)nwrite; @@ -107,7 +107,7 @@ faith_status_code_t conn_flush_output(transport_conn_t *conn, return FAITH_OK; default: *o_res = TRANSPORT_RES_ERROR; - nob_log(ERROR, "tls_write() failed."); + nob_log(ERROR, "[%s] tls_write() failed.", _MODULE_NAME); ERR_print_errors_fp(stderr); return FAITH_ERR_IO; } @@ -140,13 +140,13 @@ faith_status_code_t conn_queue_enqueue_bytes(transport_queue_t *queue, const char *type = queue->type == TRANSPORT_QUEUE_INPUT ? "input" : "output"; if (g_verbose_logging) { - nob_log(INFO, _MODULE_NAME "Trying to enqueue %zu %s bytes...", n_bytes, + nob_log(INFO, "[%s] Trying to enqueue %zu %s bytes...", _MODULE_NAME, n_bytes, type); } if (n_bytes == 0) { if (g_verbose_logging) { - nob_log(WARNING, _MODULE_NAME "Tried to enqueue zero-length %s", type); + nob_log(WARNING, "[%s] Tried to enqueue zero-length %s", _MODULE_NAME, type); } return FAITH_OK; @@ -193,7 +193,7 @@ faith_status_code_t conn_queue_enqueue_bytes(transport_queue_t *queue, queue->size = needed; if (g_verbose_logging) { - nob_log(INFO, _MODULE_NAME "Successfully enqueued %zu %s bytes", n_bytes, + nob_log(INFO, "[%s] Successfully enqueued %zu %s bytes", _MODULE_NAME, n_bytes, type); } diff --git a/faithd/src/transport/frame.c b/faithd/src/transport/frame.c index c1ae277..6fe329c 100644 --- a/faithd/src/transport/frame.c +++ b/faithd/src/transport/frame.c @@ -3,6 +3,8 @@ #include "../logging/logging.h" +#define _MODULE_NAME "transport/frame" + transport_result_t frame_try_full_read(transport_conn_t *conn, faith_frame_t *frame) { while (1) { @@ -10,8 +12,8 @@ transport_result_t frame_try_full_read(transport_conn_t *conn, if (g_verbose_logging) { nob_log(INFO, - "[client=%" PRIu64 " fd=%i] Trying to parse frame buffer...", - conn->id, conn->fd); + "[%s: client=%" PRIu64 " fd=%i] Trying to parse frame buffer...", + _MODULE_NAME, conn->id, conn->fd); } faith_status_code_t rc = frame_try_parse_from_buffer( @@ -22,9 +24,9 @@ transport_result_t frame_try_full_read(transport_conn_t *conn, if (g_verbose_logging) { nob_log( INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Successfully parsed full frame from buffer (%li bytes)", - conn->id, conn->fd, consumed); + _MODULE_NAME, conn->id, conn->fd, consumed); } size_t remaining = conn->in.size - consumed; @@ -42,18 +44,18 @@ transport_result_t frame_try_full_read(transport_conn_t *conn, /* Not enough bytes yet, so read more decrypted TLS data. */ if (g_verbose_logging) { nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Frame incomplete, reading more bytes...", - conn->id, conn->fd); + _MODULE_NAME, conn->id, conn->fd); } transport_result_t res = conn_read_more_ssl_bytes(conn); if (res == TRANSPORT_RES_GOT_BYTES) { if (g_verbose_logging) { nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Got new bytes, parsing frame again...", - conn->id, conn->fd); + _MODULE_NAME, conn->id, conn->fd); } continue; } @@ -61,9 +63,9 @@ transport_result_t frame_try_full_read(transport_conn_t *conn, if (res == TRANSPORT_RES_WANT_READ) { if (g_verbose_logging) { nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] SSL_read needs to wait for socket to be readable", - conn->id, conn->fd); + _MODULE_NAME, conn->id, conn->fd); } return res; } @@ -71,30 +73,30 @@ transport_result_t frame_try_full_read(transport_conn_t *conn, if (res == TRANSPORT_RES_WANT_WRITE) { if (g_verbose_logging) { nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] SSL_read needs to wait for socket to be writable", - conn->id, conn->fd); + _MODULE_NAME, conn->id, conn->fd); } return res; } if (res == TRANSPORT_RES_CLOSED) { nob_log(INFO, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Connection closed while reading incomplete frame.", - conn->id, conn->fd); + _MODULE_NAME, conn->id, conn->fd); return res; } nob_log(ERROR, - "[client=%" PRIu64 + "[%s: client=%" PRIu64 " fd=%i] Error while reading incomplete frame. Error=%i", - conn->id, conn->fd, res); + _MODULE_NAME, conn->id, conn->fd, res); return res; } - nob_log(ERROR, "[client=%" PRIu64 " fd=%i] Failed to read frame", conn->id, + nob_log(ERROR, "[%s: client=%" PRIu64 " fd=%i] Failed to read frame", _MODULE_NAME, conn->id, conn->fd); return TRANSPORT_RES_ERROR; diff --git a/faithd/src/transport/tls.c b/faithd/src/transport/tls.c index 62b8b1f..aecd06b 100644 --- a/faithd/src/transport/tls.c +++ b/faithd/src/transport/tls.c @@ -130,12 +130,14 @@ int tls_accept(tls_state_fd_t *state) { int err = SSL_get_error(state->ssl, rc); - if (err == SSL_ERROR_WANT_READ && g_verbose_logging) { - nob_log(INFO, _MODULE_NAME "TLS handshake wants read for fd: %i", - state->fd); - } else if (err == SSL_ERROR_WANT_WRITE && g_verbose_logging) { - nob_log(INFO, _MODULE_NAME "TLS handshake wants write for fd: %i", - state->fd); + if (err == SSL_ERROR_WANT_READ) { + if (g_verbose_logging) + nob_log(INFO, _MODULE_NAME "TLS handshake wants read for fd: %i", + state->fd); + } else if (err == SSL_ERROR_WANT_WRITE) { + if (g_verbose_logging) + nob_log(INFO, _MODULE_NAME "TLS handshake wants write for fd: %i", + state->fd); } else { nob_log(ERROR, _MODULE_NAME "SSL_accept failed: rc=%i ssl_error=%i fd=%i", rc, err, state->fd);