refactor: add lots of logging

This commit is contained in:
CJ van den Berg 2026-03-04 21:06:53 +01:00
parent 824faa87da
commit ca4d224db4
Signed by: neurocyte
GPG key ID: 8EB1E1BB660E3FB9

View file

@ -8,6 +8,7 @@
#include <thespian/c/tcp.h> #include <thespian/c/tcp.h>
#include <netinet/in.h> #include <netinet/in.h>
#include <stdio.h>
#include <string.h> #include <string.h>
// --------------------------------------------------------------------------- // ---------------------------------------------------------------------------
@ -35,6 +36,8 @@ static thespian_result send(thespian_handle h, cbor::buffer msg) {
return thespian_handle_send_raw(h, m); return thespian_handle_send_raw(h, m);
} }
#define LOG(...) fprintf(stderr, "[c_api] " __VA_ARGS__)
// --------------------------------------------------------------------------- // ---------------------------------------------------------------------------
// client_connection // client_connection
// --------------------------------------------------------------------------- // ---------------------------------------------------------------------------
@ -46,6 +49,7 @@ struct cc_state {
static void cc_dtor(thespian_behaviour_state s) { static void cc_dtor(thespian_behaviour_state s) {
auto *st = static_cast<cc_state *>(s); auto *st = static_cast<cc_state *>(s);
LOG("cc_dtor: client_connection destroyed\n");
thespian_socket_destroy(st->sock); thespian_socket_destroy(st->sock);
thespian_handle_destroy(st->client); thespian_handle_destroy(st->client);
delete st; delete st;
@ -53,26 +57,35 @@ static void cc_dtor(thespian_behaviour_state s) {
static thespian_result cc_receive(thespian_behaviour_state s, thespian_handle, static thespian_result cc_receive(thespian_behaviour_state s, thespian_handle,
cbor_buffer m) { cbor_buffer m) {
cbor_to_json(m, capture_json);
LOG("cc_receive msg=%s\n", msg_json);
auto *st = static_cast<cc_state *>(s); auto *st = static_cast<cc_state *>(s);
int written = 0; int written = 0;
if (msg_is(m, if (msg_is(m,
"[\"socket\",\"client_connection\",\"read_complete\",\"ping\"]")) { "[\"socket\",\"client_connection\",\"read_complete\",\"ping\"]")) {
LOG("cc_receive: read_complete buf=ping, writing pong\n");
thespian_socket_write(st->sock, "pong", 4); thespian_socket_write(st->sock, "pong", 4);
} else if (msg_extract_int( } else if (msg_extract_int(
m, "[\"socket\",\"client_connection\",\"write_complete\",%d]", m, "[\"socket\",\"client_connection\",\"write_complete\",%d]",
&written)) { &written)) {
LOG("cc_receive: write_complete written=%d\n", written);
thespian_socket_read(st->sock); thespian_socket_read(st->sock);
} else if (msg_is(m, "[\"socket\",\"client_connection\",\"closed\"]")) { } else if (msg_is(m, "[\"socket\",\"client_connection\",\"closed\"]")) {
LOG("cc_receive: closed, sending done\n");
send(st->client, cbor::array("client_connection", "done")); send(st->client, cbor::array("client_connection", "done"));
return thespian_exit("success"); return thespian_exit("success");
} else {
LOG("cc_receive: UNEXPECTED msg=%s\n", msg_json);
} }
return nullptr; return nullptr;
} }
static thespian_result cc_start(thespian_behaviour_state s) { static thespian_result cc_start(thespian_behaviour_state s) {
LOG("cc_start entered\n");
auto *st = static_cast<cc_state *>(s); auto *st = static_cast<cc_state *>(s);
thespian_socket_read(st->sock); thespian_socket_read(st->sock);
thespian_receive(cc_receive, s, cc_dtor); thespian_receive(cc_receive, s, cc_dtor);
LOG("cc_start returning\n");
return nullptr; return nullptr;
} }
@ -88,6 +101,7 @@ struct client_state {
static void client_dtor(thespian_behaviour_state s) { static void client_dtor(thespian_behaviour_state s) {
auto *st = static_cast<client_state *>(s); auto *st = static_cast<client_state *>(s);
LOG("client_dtor: client destroyed\n");
thespian_tcp_connector_destroy(st->connector); thespian_tcp_connector_destroy(st->connector);
thespian_handle_destroy(st->server); thespian_handle_destroy(st->server);
delete st; delete st;
@ -95,25 +109,34 @@ static void client_dtor(thespian_behaviour_state s) {
static thespian_result client_receive(thespian_behaviour_state s, static thespian_result client_receive(thespian_behaviour_state s,
thespian_handle, cbor_buffer m) { thespian_handle, cbor_buffer m) {
cbor_to_json(m, capture_json);
LOG("client_receive msg=%s\n", msg_json);
auto *st = static_cast<client_state *>(s); auto *st = static_cast<client_state *>(s);
int fd = 0; int fd = 0;
if (msg_extract_int(m, "[\"connector\",\"client\",\"connected\",%d]", &fd)) { if (msg_extract_int(m, "[\"connector\",\"client\",\"connected\",%d]", &fd)) {
LOG("client_receive: connected fd=%d, spawning cc\n", fd);
auto *cc = new cc_state{thespian_socket_create("client_connection", fd), auto *cc = new cc_state{thespian_socket_create("client_connection", fd),
thespian_handle_clone(thespian_self())}; thespian_handle_clone(thespian_self())};
thespian_handle out{}; thespian_handle out{};
thespian_spawn_link(cc_start, cc, "client_connection", nullptr, &out); thespian_spawn_link(cc_start, cc, "client_connection", nullptr, &out);
thespian_handle_destroy(out); thespian_handle_destroy(out);
LOG("client_receive: cc spawned\n");
} else if (msg_is(m, "[\"client_connection\",\"done\"]")) { } else if (msg_is(m, "[\"client_connection\",\"done\"]")) {
LOG("client_receive: cc done, sending client done\n");
send(st->server, cbor::array("client", "done")); send(st->server, cbor::array("client", "done"));
return thespian_exit("normal"); return thespian_exit("normal");
} else {
LOG("client_receive: UNEXPECTED msg=%s\n", msg_json);
} }
return nullptr; return nullptr;
} }
static thespian_result client_start(thespian_behaviour_state s) { static thespian_result client_start(thespian_behaviour_state s) {
auto *st = static_cast<client_state *>(s); auto *st = static_cast<client_state *>(s);
LOG("client_start entered port=%d\n", st->port);
thespian_tcp_connector_connect(st->connector, in6addr_loopback, st->port); thespian_tcp_connector_connect(st->connector, in6addr_loopback, st->port);
thespian_receive(client_receive, s, client_dtor); thespian_receive(client_receive, s, client_dtor);
LOG("client_start returning\n");
return nullptr; return nullptr;
} }
@ -128,6 +151,7 @@ struct sc_state {
static void sc_dtor(thespian_behaviour_state s) { static void sc_dtor(thespian_behaviour_state s) {
auto *st = static_cast<sc_state *>(s); auto *st = static_cast<sc_state *>(s);
LOG("sc_dtor: server_connection destroyed\n");
thespian_socket_destroy(st->sock); thespian_socket_destroy(st->sock);
thespian_handle_destroy(st->server); thespian_handle_destroy(st->server);
delete st; delete st;
@ -135,26 +159,35 @@ static void sc_dtor(thespian_behaviour_state s) {
static thespian_result sc_receive(thespian_behaviour_state s, thespian_handle, static thespian_result sc_receive(thespian_behaviour_state s, thespian_handle,
cbor_buffer m) { cbor_buffer m) {
cbor_to_json(m, capture_json);
LOG("sc_receive msg=%s\n", msg_json);
auto *st = static_cast<sc_state *>(s); auto *st = static_cast<sc_state *>(s);
int written = 0; int written = 0;
if (msg_extract_int( if (msg_extract_int(
m, "[\"socket\",\"server_connection\",\"write_complete\",%d]", m, "[\"socket\",\"server_connection\",\"write_complete\",%d]",
&written)) { &written)) {
LOG("sc_receive: write_complete written=%d, reading\n", written);
thespian_socket_read(st->sock); thespian_socket_read(st->sock);
} else if (msg_is(m, "[\"socket\",\"server_connection\",\"read_complete\"," } else if (msg_is(m, "[\"socket\",\"server_connection\",\"read_complete\","
"\"pong\"]")) { "\"pong\"]")) {
LOG("sc_receive: read_complete buf=pong, closing\n");
thespian_socket_close(st->sock); thespian_socket_close(st->sock);
} else if (msg_is(m, "[\"socket\",\"server_connection\",\"closed\"]")) { } else if (msg_is(m, "[\"socket\",\"server_connection\",\"closed\"]")) {
LOG("sc_receive: closed, sending done\n");
send(st->server, cbor::array("server_connection", "done")); send(st->server, cbor::array("server_connection", "done"));
return thespian_exit("success"); return thespian_exit("success");
} else {
LOG("sc_receive: UNEXPECTED msg=%s\n", msg_json);
} }
return nullptr; return nullptr;
} }
static thespian_result sc_start(thespian_behaviour_state s) { static thespian_result sc_start(thespian_behaviour_state s) {
LOG("sc_start entered\n");
auto *st = static_cast<sc_state *>(s); auto *st = static_cast<sc_state *>(s);
thespian_socket_write(st->sock, "ping", 4); thespian_socket_write(st->sock, "ping", 4);
thespian_receive(sc_receive, s, sc_dtor); thespian_receive(sc_receive, s, sc_dtor);
LOG("sc_start returning\n");
return nullptr; return nullptr;
} }
@ -163,7 +196,7 @@ static thespian_result sc_start(thespian_behaviour_state s) {
// --------------------------------------------------------------------------- // ---------------------------------------------------------------------------
struct server_state { struct server_state {
thespian_tcp_acceptor_handle *acceptor; thespian_tcp_acceptor_handle *acceptor{};
bool acceptor_closed{false}; bool acceptor_closed{false};
bool client_done{false}; bool client_done{false};
bool server_conn_done{false}; bool server_conn_done{false};
@ -171,46 +204,65 @@ struct server_state {
static void server_dtor(thespian_behaviour_state s) { static void server_dtor(thespian_behaviour_state s) {
auto *st = static_cast<server_state *>(s); auto *st = static_cast<server_state *>(s);
LOG("server_dtor: server destroyed\n");
thespian_tcp_acceptor_destroy(st->acceptor); thespian_tcp_acceptor_destroy(st->acceptor);
delete st; delete st;
} }
static thespian_result server_receive(thespian_behaviour_state s, static thespian_result server_receive(thespian_behaviour_state s,
thespian_handle, cbor_buffer m) { thespian_handle, cbor_buffer m) {
cbor_to_json(m, capture_json);
LOG("server_receive msg=%s\n", msg_json);
auto *st = static_cast<server_state *>(s); auto *st = static_cast<server_state *>(s);
int fd = 0; int fd = 0;
if (msg_extract_int(m, "[\"acceptor\",\"server\",\"accept\",%d]", &fd)) { if (msg_extract_int(m, "[\"acceptor\",\"server\",\"accept\",%d]", &fd)) {
LOG("server_receive: accept fd=%d, spawning sc\n", fd);
auto *sc = new sc_state{thespian_socket_create("server_connection", fd), auto *sc = new sc_state{thespian_socket_create("server_connection", fd),
thespian_handle_clone(thespian_self())}; thespian_handle_clone(thespian_self())};
thespian_handle out{}; thespian_handle out{};
thespian_spawn_link(sc_start, sc, "server_connection", nullptr, &out); thespian_spawn_link(sc_start, sc, "server_connection", nullptr, &out);
thespian_handle_destroy(out); thespian_handle_destroy(out);
thespian_tcp_acceptor_close(st->acceptor); thespian_tcp_acceptor_close(st->acceptor);
LOG("server_receive: sc spawned, acceptor closing\n");
} else if (msg_is(m, "[\"acceptor\",\"server\",\"closed\"]")) { } else if (msg_is(m, "[\"acceptor\",\"server\",\"closed\"]")) {
LOG("server_receive: acceptor closed (client=%d conn=%d)\n",
st->client_done, st->server_conn_done);
st->acceptor_closed = true; st->acceptor_closed = true;
} else if (msg_is(m, "[\"client\",\"done\"]")) { } else if (msg_is(m, "[\"client\",\"done\"]")) {
LOG("server_receive: client done (acceptor=%d conn=%d)\n",
st->acceptor_closed, st->server_conn_done);
st->client_done = true; st->client_done = true;
} else if (msg_is(m, "[\"server_connection\",\"done\"]")) { } else if (msg_is(m, "[\"server_connection\",\"done\"]")) {
LOG("server_receive: sc done (acceptor=%d client=%d)\n",
st->acceptor_closed, st->client_done);
st->server_conn_done = true; st->server_conn_done = true;
} else {
LOG("server_receive: UNEXPECTED msg=%s\n", msg_json);
} }
if (st->acceptor_closed && st->client_done && st->server_conn_done) if (st->acceptor_closed && st->client_done && st->server_conn_done) {
LOG("server_receive: all done, exiting success\n");
return thespian_exit("success"); return thespian_exit("success");
}
return nullptr; return nullptr;
} }
static thespian_result server_start(thespian_behaviour_state s) { static thespian_result server_start(thespian_behaviour_state s) {
LOG("server_start entered\n");
auto *st = static_cast<server_state *>(s); auto *st = static_cast<server_state *>(s);
st->acceptor = thespian_tcp_acceptor_create("server"); st->acceptor = thespian_tcp_acceptor_create("server");
uint16_t port = uint16_t port =
thespian_tcp_acceptor_listen(st->acceptor, in6addr_loopback, 0); thespian_tcp_acceptor_listen(st->acceptor, in6addr_loopback, 0);
LOG("server_start: listening on port=%d\n", port);
auto *cl = new client_state{thespian_tcp_connector_create("client"), auto *cl = new client_state{thespian_tcp_connector_create("client"),
thespian_handle_clone(thespian_self()), port}; thespian_handle_clone(thespian_self()), port};
thespian_handle out{}; thespian_handle out{};
thespian_spawn_link(client_start, cl, "client", nullptr, &out); thespian_spawn_link(client_start, cl, "client", nullptr, &out);
thespian_handle_destroy(out); thespian_handle_destroy(out);
LOG("server_start: client spawned, calling receive\n");
thespian_receive(server_receive, s, server_dtor); thespian_receive(server_receive, s, server_dtor);
LOG("server_start returning\n");
return nullptr; return nullptr;
} }
@ -226,6 +278,7 @@ auto ip_tcp_client_server_c(thespian::context &ctx, bool &result,
reinterpret_cast<thespian_context>(&ctx), // NOLINT reinterpret_cast<thespian_context>(&ctx), // NOLINT
server_start, st, server_start, st,
[](thespian_exit_handler_state r, const char *msg, size_t len) { [](thespian_exit_handler_state r, const char *msg, size_t len) {
LOG("exit_handler: status=%.*s\n", (int)len, msg);
if (strncmp(msg, "success", len) == 0) if (strncmp(msg, "success", len) == 0)
*static_cast<bool *>(r) = true; *static_cast<bool *>(r) = true;
}, },