From 18198cec4c29148058411381e866ad88d043d528 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Tue, 3 Nov 2026 22:41:53 +0000 Subject: [PATCH 1/2] Clarify bot code with KISS cleanups, same behavior MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Name Discord/WebSocket opcodes, DRY JSON int parsing and logging, extract heartbeat/token/dispatch helpers, and drop dead TLS state — keeping the small module layout and readability. Co-authored-by: me --- src/json.c | 84 +++++++++------------ src/king.c | 215 +++++++++++++++++++++++++++++++---------------------- src/log.h | 31 ++++---- src/net.c | 8 +- src/net.h | 3 +- src/ws.c | 39 +++++----- 6 files changed, 198 insertions(+), 182 deletions(-) diff --git a/src/json.c b/src/json.c index 59d26a4..6029bed 100644 --- a/src/json.c +++ b/src/json.c @@ -10,6 +10,28 @@ static const char *skip_ws(const char *p) { return p; } +/* Parse a JSON number at *pp into *out. Advances nothing; returns 0 on failure. */ +static int parse_int_value(const char *p, long long *out) { + if (!p) { + return 0; + } + int neg = 0; + if (*p == '-') { + neg = 1; + p++; + } + if (!isdigit((unsigned char)*p)) { + return 0; + } + long long v = 0; + while (isdigit((unsigned char)*p)) { + v = (v * 10) + (*p - '0'); + p++; + } + *out = neg ? -v : v; + return 1; +} + static int read_string_value(const char *c, char *out, size_t cap) { if (!c || *c != '"') { return 0; @@ -92,25 +114,7 @@ int json_get_string(const char *json, const char *key, char *out, size_t cap) { } int json_get_int(const char *json, const char *key, long long *out) { - const char *p = json_find_key(json, key); - if (!p) { - return 0; - } - int neg = 0; - if (*p == '-') { - neg = 1; - p++; - } - if (!isdigit((unsigned char)*p)) { - return 0; - } - long long v = 0; - while (isdigit((unsigned char)*p)) { - v = (v * 10) + (*p - '0'); - p++; - } - *out = neg ? -v : v; - return 1; + return parse_int_value(json_find_key(json, key), out); } /* Find the byte range of a JSON object value. */ @@ -174,6 +178,7 @@ static const char *find_string_end(const char *s, const char *end) { return NULL; } +/* Scan for `key` at object depth 1 within [start, end); set *val to its value. */ static int scan_key(const char *start, const char *end, const char *key, const char **val) { size_t klen = strlen(key); int depth = 0; @@ -206,45 +211,24 @@ static int scan_key(const char *start, const char *end, const char *key, const c return 0; } -int json_get_string_in_object(const char *json, const json_object_key *key, char *out, size_t cap) { +/* Resolve object_key.member_key to a value pointer inside json. */ +static const char *value_in_object(const char *json, const json_object_key *key) { const char *start; const char *end; const char *val = NULL; if (!find_object_range(json, key->object_key, &start, &end)) { - return 0; + return NULL; } if (!scan_key(start, end, key->member_key, &val)) { - return 0; + return NULL; } - return read_string_value(val, out, cap); + return val; +} + +int json_get_string_in_object(const char *json, const json_object_key *key, char *out, size_t cap) { + return read_string_value(value_in_object(json, key), out, cap); } int json_get_int_in_object(const char *json, const json_object_key *key, long long *out) { - const char *start; - const char *end; - const char *val = NULL; - if (!find_object_range(json, key->object_key, &start, &end)) { - return 0; - } - if (!scan_key(start, end, key->member_key, &val)) { - return 0; - } - if (!val) { - return 0; - } - int neg = 0; - if (*val == '-') { - neg = 1; - val++; - } - if (!isdigit((unsigned char)*val)) { - return 0; - } - long long v = 0; - while (isdigit((unsigned char)*val)) { - v = (v * 10) + (*val - '0'); - val++; - } - *out = neg ? -v : v; - return 1; + return parse_int_value(value_in_object(json, key), out); } diff --git a/src/king.c b/src/king.c index 08c0a52..3e6c5e2 100644 --- a/src/king.c +++ b/src/king.c @@ -19,6 +19,25 @@ #define GATEWAY_PATH "/?v=10&encoding=json" #define BUF_SIZE 65536 +/* Discord Gateway opcodes we care about. */ +enum { + OP_DISPATCH = 0, + OP_HEARTBEAT = 1, + OP_IDENTIFY = 2, + OP_RECONNECT = 7, + OP_INVALID_SESSION = 9, + OP_HELLO = 10, + OP_HEARTBEAT_ACK = 11, +}; + +/* GUILD_MESSAGES (512) | MESSAGE_CONTENT (32768) */ +#define GATEWAY_INTENTS 33280 + +#define HB_MAX_RETRIES 3 +#define HB_RETRY_USEC_START 100000 + +#define DEFAULT_REACTION "\xf0\x9f\x91\x91" /* 👑 */ + /* ── Monotonic clock ──────────────────────────────────────────── */ static long long now_ms(void) { @@ -54,17 +73,20 @@ static void send_message(const char *auth, const char *channel_id, const char *c char body[4096]; char path[256]; char resp[4096]; + json_escape(content, esc, sizeof(esc)); snprintf(body, sizeof(body), "{\"content\":\"%s\"}", esc); snprintf(path, sizeof(path), "/api/v10/channels/%s/messages", channel_id); + if (api_request(auth, "POST", path, body, resp, sizeof(resp)) != 0) { log_error("Failed to send message"); - } else { - int status = http_status_code(resp); - log_info("Message send status %d", status); - if (status >= 400) { - log_error("Message send failed: %.*s", 200, resp); - } + return; + } + + int status = http_status_code(resp); + log_info("Message send status %d", status); + if (status >= 400) { + log_error("Message send failed: %.*s", 200, resp); } } @@ -73,17 +95,20 @@ static void send_reaction(const char *auth, const char *channel_id, const char * if (!emoji || !*emoji) { return; } + char enc[256]; char path[512]; char resp[4096]; + url_encode(emoji, enc, sizeof(enc)); snprintf(path, sizeof(path), "/api/v10/channels/%s/messages/%s/reactions/%s/@me", channel_id, message_id, enc); + if (api_request(auth, "PUT", path, "", resp, sizeof(resp)) != 0) { log_error("Failed to add reaction"); - } else { - log_info("Reaction add status %d", http_status_code(resp)); + return; } + log_info("Reaction add status %d", http_status_code(resp)); } /* ── Gateway operations ───────────────────────────────────────── */ @@ -95,18 +120,30 @@ typedef struct { long long next_heartbeat; } gateway_state; +/* Split DISCORD_TOKEN into REST Authorization header and raw gateway token. */ +static void normalize_token(const char *token, char *auth, size_t auth_cap, char *gateway_token, + size_t gateway_cap) { + if (strncmp(token, "Bot ", 4) == 0) { + snprintf(auth, auth_cap, "%s", token); + snprintf(gateway_token, gateway_cap, "%s", token + 4); + } else { + snprintf(auth, auth_cap, "Bot %s", token); + snprintf(gateway_token, gateway_cap, "%s", token); + } +} + static int send_identify(tls_conn *c, const char *token) { char payload[1024]; int n = snprintf(payload, sizeof(payload), - "{\"op\":2,\"d\":{" + "{\"op\":%d,\"d\":{" "\"token\":\"%s\"," - "\"intents\":33280," /* GUILD_MESSAGES + MESSAGE_CONTENT */ + "\"intents\":%d," "\"properties\":{" "\"os\":\"cosmo\"," "\"browser\":\"king-cosmo\"," "\"device\":\"king-cosmo\"" "}}}", - token); + OP_IDENTIFY, token, GATEWAY_INTENTS); if (n <= 0 || (size_t)n >= sizeof(payload)) { return -1; } @@ -117,9 +154,9 @@ static int send_heartbeat(tls_conn *c, long long seq) { char payload[64]; int n; if (seq >= 0) { - n = snprintf(payload, sizeof(payload), "{\"op\":1,\"d\":%lld}", seq); + n = snprintf(payload, sizeof(payload), "{\"op\":%d,\"d\":%lld}", OP_HEARTBEAT, seq); } else { - n = snprintf(payload, sizeof(payload), "{\"op\":1,\"d\":null}"); + n = snprintf(payload, sizeof(payload), "{\"op\":%d,\"d\":null}", OP_HEARTBEAT); } if (n <= 0 || (size_t)n >= sizeof(payload)) { return -1; @@ -127,9 +164,29 @@ static int send_heartbeat(tls_conn *c, long long seq) { return ws_send_text(c, payload, (size_t)n); } +static int heartbeat_with_retry(gateway_state *s) { + int delay = HB_RETRY_USEC_START; + + for (int attempt = 0; attempt < HB_MAX_RETRIES; attempt++) { + if (send_heartbeat(&s->conn, s->sequence) == 0) { + log_debug("Heartbeat sent"); + s->next_heartbeat = now_ms() + s->heartbeat_interval; + return 0; + } + if (attempt + 1 < HB_MAX_RETRIES) { + log_error("Heartbeat failed, retrying..."); + usleep(delay); + delay *= 2; + } + } + log_error("Heartbeat failed"); + return -1; +} + static int handle_hello(gateway_state *s, const char *token, const char *payload) { long long interval = 0; json_object_key hb_key = {"d", "heartbeat_interval"}; + if (json_get_int_in_object(payload, &hb_key, &interval)) { s->heartbeat_interval = interval; } @@ -151,30 +208,27 @@ static void handle_message_create(const char *auth, const char *reply, const cha char content[2048]; char channel_id[64]; char message_id[64]; - json_object_key ck = {"d", "content"}; - json_object_key chk = {"d", "channel_id"}; - json_object_key mk = {"d", "id"}; + json_object_key content_key = {"d", "content"}; + json_object_key channel_key = {"d", "channel_id"}; + json_object_key id_key = {"d", "id"}; - if (!json_get_string_in_object(payload, &ck, content, sizeof(content))) { - return; - } - if (!json_get_string_in_object(payload, &chk, channel_id, sizeof(channel_id))) { + if (!json_get_string_in_object(payload, &content_key, content, sizeof(content)) || + !json_get_string_in_object(payload, &channel_key, channel_id, sizeof(channel_id)) || + !json_get_string_in_object(payload, &id_key, message_id, sizeof(message_id))) { return; } - if (!json_get_string_in_object(payload, &mk, message_id, sizeof(message_id))) { + + if (!contains_case(content, "king")) { + log_debug("Message ignored"); return; } - if (contains_case(content, "king")) { - log_info("Matched 'king' in channel %s", channel_id); - if (reply && *reply) { - send_message(auth, channel_id, reply); - } - if (reaction && *reaction) { - send_reaction(auth, channel_id, message_id, reaction); - } - } else { - log_debug("Message ignored"); + log_info("Matched 'king' in channel %s", channel_id); + if (reply && *reply) { + send_message(auth, channel_id, reply); + } + if (reaction && *reaction) { + send_reaction(auth, channel_id, message_id, reaction); } } @@ -182,21 +236,19 @@ static int wait_for_hello(gateway_state *s, const char *token, char *buf, size_t size_t len = 0; while (ws_read_text(&s->conn, buf, buf_cap, &len) == 0) { long long op = -1; - if (!json_get_int(buf, "op", &op)) { - continue; - } - if (op == 10) { + if (json_get_int(buf, "op", &op) && op == OP_HELLO) { return handle_hello(s, token, buf); } } return -1; } +/* Returns 0 = payload ready, 1 = idle/timeout, -1 = fatal. */ static int poll_and_read(gateway_state *s, char *buf, size_t buf_cap) { struct pollfd pfd = {.fd = s->conn.fd, .events = POLLIN}; - long long now = now_ms(); int timeout = 1000; + if (s->next_heartbeat > 0) { long long diff = s->next_heartbeat - now; timeout = diff < 0 ? 0 : (int)diff; @@ -210,23 +262,9 @@ static int poll_and_read(gateway_state *s, char *buf, size_t buf_cap) { now = now_ms(); if (s->next_heartbeat > 0 && now >= s->next_heartbeat) { - int hb_ok = 0; - int delay = 100000; - for (int retries = 0; retries < 3 && !hb_ok; retries++) { - if (send_heartbeat(&s->conn, s->sequence) == 0) { - hb_ok = 1; - } else if (retries < 2) { - log_error("Heartbeat failed, retrying..."); - usleep(delay); - delay *= 2; - } - } - if (!hb_ok) { - log_error("Heartbeat failed"); + if (heartbeat_with_retry(s) != 0) { return -1; } - log_debug("Heartbeat sent"); - s->next_heartbeat = now + s->heartbeat_interval; } if (rc == 0 || !(pfd.revents & POLLIN)) { @@ -241,6 +279,38 @@ static int poll_and_read(gateway_state *s, char *buf, size_t buf_cap) { return 0; } +/* Handle one gateway JSON payload. Returns -1 if the connection should drop. */ +static int handle_gateway_payload(gateway_state *s, const char *auth, const char *reply, + const char *reaction, const char *buf) { + long long op = -1; + if (json_get_int(buf, "op", &op)) { + if (op == OP_HEARTBEAT_ACK) { + log_debug("Heartbeat ACK"); + return 0; + } + if (op == OP_RECONNECT || op == OP_INVALID_SESSION) { + log_error("Reconnect requested"); + return -1; + } + } + + long long seq = -1; + if (json_get_int(buf, "s", &seq)) { + s->sequence = seq; + } + + char event[64]; + if (!json_get_string(buf, "t", event, sizeof(event))) { + return 0; + } + if (strcmp(event, "MESSAGE_CREATE") == 0) { + handle_message_create(auth, reply, reaction, buf); + } else if (strcmp(event, "READY") == 0) { + log_info("READY event received"); + } + return 0; +} + /* ── Main ─────────────────────────────────────────────────────── */ int main(void) { @@ -255,19 +325,12 @@ int main(void) { return 1; } if (!reaction) { - reaction = "\xf0\x9f\x91\x91"; /* crown emoji UTF-8 */ + reaction = DEFAULT_REACTION; } - /* Build auth header token (REST needs "Bot " prefix). */ char auth[512]; char gateway_token[512]; - if (strncmp(token, "Bot ", 4) == 0) { - snprintf(auth, sizeof(auth), "%s", token); - snprintf(gateway_token, sizeof(gateway_token), "%s", token + 4); - } else { - snprintf(auth, sizeof(auth), "Bot %s", token); - snprintf(gateway_token, sizeof(gateway_token), "%s", token); - } + normalize_token(token, auth, sizeof(auth), gateway_token, sizeof(gateway_token)); if (tls_init_ca() != 0) { fprintf(stderr, "Failed to init CA certificates\n"); @@ -301,36 +364,10 @@ int main(void) { break; } if (rc > 0) { - continue; - } - - /* Handle gateway opcodes */ - long long op = -1; - if (json_get_int(buf, "op", &op)) { - if (op == 11) { - log_debug("Heartbeat ACK"); - continue; - } - if (op == 7 || op == 9) { - log_error("Reconnect requested"); - break; - } + continue; /* idle / heartbeat-only tick */ } - - /* Update sequence */ - long long seq = -1; - if (json_get_int(buf, "s", &seq)) { - state.sequence = seq; - } - - /* Dispatch events */ - char event[64]; - if (json_get_string(buf, "t", event, sizeof(event))) { - if (strcmp(event, "MESSAGE_CREATE") == 0) { - handle_message_create(auth, reply, reaction, buf); - } else if (strcmp(event, "READY") == 0) { - log_info("READY event received"); - } + if (handle_gateway_payload(&state, auth, reply, reaction, buf) != 0) { + break; } } diff --git a/src/log.h b/src/log.h index bb55020..8beead6 100644 --- a/src/log.h +++ b/src/log.h @@ -27,16 +27,21 @@ static inline void log_init_from_env(void) { } } -#if LOG_LEVEL_COMPILE >= LOG_LEVEL_ERROR -__attribute__((format(printf, 1, 2))) static inline void log_error(const char *fmt, ...) { - if (g_log_level < LOG_LEVEL_ERROR) { +/* Shared writer — keeps the three public log_* helpers DRY. */ +static inline void log_write(int level, const char *tag, const char *fmt, va_list ap) { + if (g_log_level < level) { return; } - va_list ap; - va_start(ap, fmt); - fprintf(stderr, "[ERROR] "); + fprintf(stderr, "%s ", tag); vfprintf(stderr, fmt, ap); fputc('\n', stderr); +} + +#if LOG_LEVEL_COMPILE >= LOG_LEVEL_ERROR +__attribute__((format(printf, 1, 2))) static inline void log_error(const char *fmt, ...) { + va_list ap; + va_start(ap, fmt); + log_write(LOG_LEVEL_ERROR, "[ERROR]", fmt, ap); va_end(ap); } #else @@ -47,14 +52,9 @@ __attribute__((format(printf, 1, 2))) static inline void log_error(const char *f #if LOG_LEVEL_COMPILE >= LOG_LEVEL_INFO __attribute__((format(printf, 1, 2))) static inline void log_info(const char *fmt, ...) { - if (g_log_level < LOG_LEVEL_INFO) { - return; - } va_list ap; va_start(ap, fmt); - fprintf(stderr, "[INFO] "); - vfprintf(stderr, fmt, ap); - fputc('\n', stderr); + log_write(LOG_LEVEL_INFO, "[INFO]", fmt, ap); va_end(ap); } #else @@ -65,14 +65,9 @@ __attribute__((format(printf, 1, 2))) static inline void log_info(const char *fm #if LOG_LEVEL_COMPILE >= LOG_LEVEL_DEBUG __attribute__((format(printf, 1, 2))) static inline void log_debug(const char *fmt, ...) { - if (g_log_level < LOG_LEVEL_DEBUG) { - return; - } va_list ap; va_start(ap, fmt); - fprintf(stderr, "[DEBUG] "); - vfprintf(stderr, fmt, ap); - fputc('\n', stderr); + log_write(LOG_LEVEL_DEBUG, "[DEBUG]", fmt, ap); va_end(ap); } #else diff --git a/src/net.c b/src/net.c index c6c276f..a9952cb 100644 --- a/src/net.c +++ b/src/net.c @@ -53,10 +53,6 @@ static int tcp_connect(const char *host, const char *port) { return fd; } -static int entropy_func(void *data, unsigned char *output, size_t len) { - return mbedtls_entropy_func(data, output, len); -} - /* Custom BIO callbacks for mbedtls over a raw socket fd. */ static int bio_send(void *ctx, const unsigned char *buf, size_t len) { int fd = *(int *)ctx; @@ -90,8 +86,8 @@ int tls_connect(tls_conn *c, const char *host, const char *port) { mbedtls_ctr_drbg_init(&c->drbg); mbedtls_entropy_init(&c->entropy); - if (mbedtls_ctr_drbg_seed(&c->drbg, entropy_func, &c->entropy, (const unsigned char *)"king", - 4) != 0) { + if (mbedtls_ctr_drbg_seed(&c->drbg, mbedtls_entropy_func, &c->entropy, + (const unsigned char *)"king", 4) != 0) { goto fail; } diff --git a/src/net.h b/src/net.h index 03636f5..35eb08f 100644 --- a/src/net.h +++ b/src/net.h @@ -8,14 +8,13 @@ #include #include -/* Opaque TLS connection handle. */ +/* Live TLS session over a TCP socket (mbedtls state owned here). */ typedef struct { int fd; mbedtls_ssl_context ssl; mbedtls_ssl_config conf; mbedtls_ctr_drbg_context drbg; mbedtls_entropy_context entropy; - mbedtls_x509_crt ca; } tls_conn; /* Initialize the global CA certificate store. Call once at startup. */ diff --git a/src/ws.c b/src/ws.c index 257aa3e..a41364b 100644 --- a/src/ws.c +++ b/src/ws.c @@ -6,6 +6,12 @@ #include #include +enum { + WS_OPCODE_TEXT = 0x1, + WS_OPCODE_CLOSE = 0x8, + WS_FIN_TEXT = 0x81, /* FIN bit + text opcode */ +}; + static int random_bytes(unsigned char *buf, size_t len) { return (getrandom(buf, len, 0) == (ssize_t)len) ? 0 : -1; } @@ -67,7 +73,7 @@ int ws_handshake(tls_conn *c, const char *host, const char *path) { int ws_send_text(tls_conn *c, const char *text, size_t len) { unsigned char header[14]; size_t hlen = 0; - header[0] = 0x81; /* FIN + text opcode */ + header[0] = WS_FIN_TEXT; if (len <= 125) { header[1] = 0x80 | (unsigned char)len; @@ -106,6 +112,19 @@ int ws_send_text(tls_conn *c, const char *text, size_t len) { return rc; } +/* Discard `plen` bytes from the TLS stream (oversized / unwanted payload). */ +static int drain_payload(tls_conn *c, size_t plen) { + unsigned char tmp[512]; + while (plen > 0) { + size_t chunk = plen > sizeof(tmp) ? sizeof(tmp) : plen; + if (tls_read_exact(c, tmp, chunk) != 0) { + return -1; + } + plen -= chunk; + } + return 0; +} + int ws_read_text(tls_conn *c, char *out, size_t out_cap, size_t *out_len) { unsigned char hdr[2]; if (tls_read_exact(c, hdr, 2) != 0) { @@ -139,16 +158,7 @@ int ws_read_text(tls_conn *c, char *out, size_t out_cap, size_t *out_len) { } if (plen + 1 > out_cap) { - /* Drain oversized payload */ - unsigned char tmp[512]; - size_t rem = (size_t)plen; - while (rem > 0) { - size_t chunk = rem > sizeof(tmp) ? sizeof(tmp) : rem; - if (tls_read_exact(c, tmp, chunk) != 0) { - return -1; - } - rem -= chunk; - } + (void)drain_payload(c, (size_t)plen); return -1; } @@ -166,12 +176,7 @@ int ws_read_text(tls_conn *c, char *out, size_t out_cap, size_t *out_len) { *out_len = (size_t)plen; } - /* Close frame */ - if (opcode == 0x8) { - return -1; - } - /* Only accept text frames */ - if (opcode != 0x1) { + if (opcode == WS_OPCODE_CLOSE || opcode != WS_OPCODE_TEXT) { return -1; } return 0; From dd00d4be5d15cfb6c40d5f746b3c3a83152a4537 Mon Sep 17 00:00:00 2001 From: Cursor Agent Date: Tue, 3 Nov 2026 22:51:47 +0000 Subject: [PATCH 2/2] Replace diary logs with wide-event NDJSON Apply loggingsucks.com lessons: one structured JSON event per unit of work, high-cardinality Discord IDs, business context on matches, env fields on every line, info/error only, and tail sampling via LOG_SAMPLE_RATE. Never log the bot token. Co-authored-by: me --- .env.sample | 3 + AGENTS.md | 2 +- Makefile | 8 +- README.md | 9 +- src/king.c | 210 ++++++++++++++++++++++++++++-------- src/log.c | 281 ++++++++++++++++++++++++++++++++++++++++++++++++ src/log.h | 136 +++++++++++------------ src/net.c | 15 ++- src/test_king.c | 39 +++++++ 9 files changed, 586 insertions(+), 117 deletions(-) create mode 100644 src/log.c diff --git a/.env.sample b/.env.sample index 5091a04..fb2e6de 100644 --- a/.env.sample +++ b/.env.sample @@ -2,3 +2,6 @@ DISCORD_TOKEN=your_bot_token_here #DISCORD_REPLY= #DISCORD_REACTION=👑 #LOG_LEVEL=info +#LOG_SAMPLE_RATE=1.0 +#KING_VERSION=0.1 +#KING_COMMIT= diff --git a/AGENTS.md b/AGENTS.md index c922b82..16b832b 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -51,7 +51,7 @@ Built with Cosmopolitan Libc and mbedtls for TLS. ~1000 lines of C in `src/`. | `src/net.c` | TCP + mbedtls TLS connect, custom BIO callbacks, HTTPS request helper | | `src/ws.c` | Minimal WebSocket client (masked client frames, text frames only) | | `src/json.c` | Targeted key extraction — not a general-purpose parser | -| `src/log.h` | Header-only runtime log levels; compile-time stripping via `LOG_LEVEL_COMPILE` | +| `src/log.h` / `src/log.c` | Wide-event NDJSON logger (`log_emit`); info/error; env: `LOG_LEVEL`, `LOG_SAMPLE_RATE`, `KING_VERSION`, `KING_COMMIT` | | `src/cacerts.h` | Embedded root CA certificates (PEM) | ### Key structs diff --git a/Makefile b/Makefile index cde3c1d..d05e9b9 100644 --- a/Makefile +++ b/Makefile @@ -54,7 +54,7 @@ MBEDTLS_LIBS = $(MBEDTLS_LIB)/libmbedtls.a \ # ── bot sources ────────────────────────────────────────────────── BIN = king -SRCS = src/king.c src/net.c src/ws.c src/json.c src/str.c +SRCS = src/king.c src/net.c src/ws.c src/json.c src/str.c src/log.c OBJS = $(SRCS:.c=.o) # ── targets ────────────────────────────────────────────────────── @@ -79,7 +79,7 @@ $(MBEDTLS_LIBS): # ── tests ──────────────────────────────────────────────────────── TEST_BIN = test_king -TEST_SRCS = src/test_king.c src/json.c src/str.c +TEST_SRCS = src/test_king.c src/json.c src/str.c src/log.c TEST_OBJS = $(TEST_SRCS:.c=.o) test: $(TEST_BIN) @@ -89,7 +89,7 @@ $(TEST_BIN): $(TEST_OBJS) $(CC) $(LDFLAGS) -o $@ $(TEST_OBJS) # ── lint ───────────────────────────────────────────────────────── -LINT_SRCS = src/king.c src/net.c src/ws.c src/json.c src/str.c src/test_king.c +LINT_SRCS = src/king.c src/net.c src/ws.c src/json.c src/str.c src/log.c src/test_king.c LINT_HDRS = src/json.h src/str.h src/net.h src/ws.h src/log.h src/test.h src/cacerts.h lint: @@ -97,7 +97,7 @@ lint: clang-tidy $(LINT_SRCS) -- -Isrc -I$(MBEDTLS_INC) -Wno-implicit-function-declaration clean: - rm -f $(BIN) $(TEST_BIN) $(OBJS) src/test_king.o *.com.dbg *.aarch64.elf + rm -f $(BIN) $(TEST_BIN) $(OBJS) src/test_king.o src/log.o *.com.dbg *.aarch64.elf rm -rf .aarch64 mbedclean: diff --git a/README.md b/README.md index eaf89f0..7becc51 100644 --- a/README.md +++ b/README.md @@ -65,7 +65,14 @@ You need **Message Content Intent** enabled in the [Discord Developer Portal](ht | `DISCORD_TOKEN` | *(required)* | Bot token (no `Bot ` prefix) | | `DISCORD_REPLY` | *(disabled)* | Reply text, omit to disable | | `DISCORD_REACTION` | `👑` | Reaction emoji | -| `LOG_LEVEL` | `info` | `error`, `info`, or `debug` | +| `LOG_LEVEL` | `info` | `error` or `info` (structured NDJSON on stderr) | +| `LOG_SAMPLE_RATE` | `1.0` | Tail-sample rate for non-error / non-match events (`0.0`–`1.0`) | +| `KING_VERSION` | `0.1` | Included on every log event | +| `KING_COMMIT` | *(empty)* | Optional deploy/commit id on every event | + +### Logging + +Logs follow [wide events / canonical log lines](https://www.loggingsucks.com): one JSON object per unit of work (session, hello, ready, matched message, failures) — not a step-by-step diary. Errors and `matched_king` events are always kept; other info events respect `LOG_SAMPLE_RATE`. Tokens are never logged. ## Test / lint diff --git a/src/king.c b/src/king.c index 3e6c5e2..0b2231a 100644 --- a/src/king.c +++ b/src/king.c @@ -46,6 +46,11 @@ static long long now_ms(void) { return ((long long)ts.tv_sec * 1000LL) + (ts.tv_nsec / 1000000LL); } +static void make_request_id(char *out, size_t cap) { + static unsigned counter; + snprintf(out, cap, "req_%08lx%04x", (unsigned long)time(NULL), (++counter) & 0xffff); +} + /* ── REST API helpers ─────────────────────────────────────────── */ static int api_request(const char *auth, const char *method, const char *path, const char *body, @@ -68,7 +73,8 @@ static int api_request(const char *auth, const char *method, const char *path, c return https_request(API_HOST, API_PORT, req, resp, resp_cap); } -static void send_message(const char *auth, const char *channel_id, const char *content) { +/* Returns HTTP status, or -1 on transport failure. */ +static int send_message(const char *auth, const char *channel_id, const char *content) { char esc[2048]; char body[4096]; char path[256]; @@ -79,21 +85,16 @@ static void send_message(const char *auth, const char *channel_id, const char *c snprintf(path, sizeof(path), "/api/v10/channels/%s/messages", channel_id); if (api_request(auth, "POST", path, body, resp, sizeof(resp)) != 0) { - log_error("Failed to send message"); - return; - } - - int status = http_status_code(resp); - log_info("Message send status %d", status); - if (status >= 400) { - log_error("Message send failed: %.*s", 200, resp); + return -1; } + return http_status_code(resp); } -static void send_reaction(const char *auth, const char *channel_id, const char *message_id, - const char *emoji) { +/* Returns HTTP status, -1 on transport failure, LOG_OMIT_I if emoji disabled. */ +static int send_reaction(const char *auth, const char *channel_id, const char *message_id, + const char *emoji) { if (!emoji || !*emoji) { - return; + return LOG_OMIT_I; } char enc[256]; @@ -105,10 +106,9 @@ static void send_reaction(const char *auth, const char *channel_id, const char * message_id, enc); if (api_request(auth, "PUT", path, "", resp, sizeof(resp)) != 0) { - log_error("Failed to add reaction"); - return; + return -1; } - log_info("Reaction add status %d", http_status_code(resp)); + return http_status_code(resp); } /* ── Gateway operations ───────────────────────────────────────── */ @@ -118,6 +118,9 @@ typedef struct { long long heartbeat_interval; long long sequence; long long next_heartbeat; + long long session_start_ms; + unsigned heartbeats_ok; + unsigned heartbeats_fail; } gateway_state; /* Split DISCORD_TOKEN into REST Authorization header and raw gateway token. */ @@ -169,38 +172,62 @@ static int heartbeat_with_retry(gateway_state *s) { for (int attempt = 0; attempt < HB_MAX_RETRIES; attempt++) { if (send_heartbeat(&s->conn, s->sequence) == 0) { - log_debug("Heartbeat sent"); + s->heartbeats_ok++; s->next_heartbeat = now_ms() + s->heartbeat_interval; return 0; } + s->heartbeats_fail++; if (attempt + 1 < HB_MAX_RETRIES) { - log_error("Heartbeat failed, retrying..."); usleep(delay); delay *= 2; } } - log_error("Heartbeat failed"); + + log_event ev = log_event_new("gateway.heartbeat"); + ev.outcome = "error"; + ev.sequence = s->sequence; + ev.heartbeat_interval_ms = s->heartbeat_interval; + ev.attempt = HB_MAX_RETRIES; + ev.max_attempts = HB_MAX_RETRIES; + ev.error_type = "HeartbeatError"; + ev.error_message = "heartbeat failed after retries"; + log_emit(LOG_LEVEL_ERROR, &ev); return -1; } static int handle_hello(gateway_state *s, const char *token, const char *payload) { long long interval = 0; json_object_key hb_key = {"d", "heartbeat_interval"}; + long long t0 = now_ms(); if (json_get_int_in_object(payload, &hb_key, &interval)) { s->heartbeat_interval = interval; } if (send_identify(&s->conn, token) != 0) { - log_error("Identify failed"); + log_event ev = log_event_new("gateway.identify"); + ev.outcome = "error"; + ev.duration_ms = now_ms() - t0; + ev.gateway_op = OP_HELLO; + ev.heartbeat_interval_ms = s->heartbeat_interval; + ev.error_type = "IdentifyError"; + ev.error_message = "ws send identify failed"; + log_emit(LOG_LEVEL_ERROR, &ev); return -1; } - log_info("Identify sent"); + s->next_heartbeat = now_ms() + s->heartbeat_interval; + + log_event ev = log_event_new("gateway.hello"); + ev.outcome = "success"; + ev.duration_ms = now_ms() - t0; + ev.gateway_op = OP_HELLO; + ev.heartbeat_interval_ms = s->heartbeat_interval; + log_emit(LOG_LEVEL_INFO, &ev); return 0; } -static void handle_message_create(const char *auth, const char *reply, const char *reaction, - const char *payload) { +static void handle_message_create(gateway_state *s, const char *auth, const char *reply, + const char *reaction, const char *payload) { if (strstr(payload, "\"bot\":true")) { return; } @@ -208,6 +235,7 @@ static void handle_message_create(const char *auth, const char *reply, const cha char content[2048]; char channel_id[64]; char message_id[64]; + char request_id[32]; json_object_key content_key = {"d", "content"}; json_object_key channel_key = {"d", "channel_id"}; json_object_key id_key = {"d", "id"}; @@ -218,17 +246,44 @@ static void handle_message_create(const char *auth, const char *reply, const cha return; } - if (!contains_case(content, "king")) { - log_debug("Message ignored"); + long long t0 = now_ms(); + make_request_id(request_id, sizeof(request_id)); + + log_event ev = log_event_new("message.handle"); + ev.request_id = request_id; + ev.channel_id = channel_id; + ev.message_id = message_id; + ev.sequence = s->sequence; + ev.gateway_t = "MESSAGE_CREATE"; + ev.content_len = (int)strlen(content); + ev.reply_enabled = (reply && *reply) ? 1 : 0; + ev.matched_king = contains_case(content, "king") ? 1 : 0; + + if (!ev.matched_king) { + /* Not a unit of business work — skip (avoid diary noise). */ return; } - log_info("Matched 'king' in channel %s", channel_id); if (reply && *reply) { - send_message(auth, channel_id, reply); + ev.reply_http_status = send_message(auth, channel_id, reply); } if (reaction && *reaction) { - send_reaction(auth, channel_id, message_id, reaction); + ev.reaction_http_status = send_reaction(auth, channel_id, message_id, reaction); + } + + ev.duration_ms = now_ms() - t0; + int reply_bad = (ev.reply_http_status != LOG_OMIT_I) && + (ev.reply_http_status < 0 || ev.reply_http_status >= 400); + int reaction_bad = (ev.reaction_http_status != LOG_OMIT_I) && + (ev.reaction_http_status < 0 || ev.reaction_http_status >= 400); + if (reply_bad || reaction_bad) { + ev.outcome = "error"; + ev.error_type = "DiscordRestError"; + ev.error_message = reply_bad ? "reply failed" : "reaction failed"; + log_emit(LOG_LEVEL_ERROR, &ev); + } else { + ev.outcome = "success"; + log_emit(LOG_LEVEL_INFO, &ev); } } @@ -256,7 +311,11 @@ static int poll_and_read(gateway_state *s, char *buf, size_t buf_cap) { int rc = poll(&pfd, 1, timeout); if (rc < 0) { - log_error("poll failed"); + log_event ev = log_event_new("gateway.poll"); + ev.outcome = "error"; + ev.error_type = "PollError"; + ev.error_message = "poll failed"; + log_emit(LOG_LEVEL_ERROR, &ev); return -1; } @@ -273,7 +332,12 @@ static int poll_and_read(gateway_state *s, char *buf, size_t buf_cap) { size_t len = 0; if (ws_read_text(&s->conn, buf, buf_cap, &len) != 0) { - log_error("Gateway read failed"); + log_event ev = log_event_new("gateway.read"); + ev.outcome = "error"; + ev.sequence = s->sequence; + ev.error_type = "GatewayReadError"; + ev.error_message = "ws read failed"; + log_emit(LOG_LEVEL_ERROR, &ev); return -1; } return 0; @@ -285,11 +349,16 @@ static int handle_gateway_payload(gateway_state *s, const char *auth, const char long long op = -1; if (json_get_int(buf, "op", &op)) { if (op == OP_HEARTBEAT_ACK) { - log_debug("Heartbeat ACK"); - return 0; + return 0; /* counted via successful heartbeat send */ } if (op == OP_RECONNECT || op == OP_INVALID_SESSION) { - log_error("Reconnect requested"); + log_event ev = log_event_new("gateway.reconnect"); + ev.outcome = "reconnect"; + ev.gateway_op = op; + ev.sequence = s->sequence; + ev.duration_ms = now_ms() - s->session_start_ms; + ev.error_type = (op == OP_RECONNECT) ? "Reconnect" : "InvalidSession"; + log_emit(LOG_LEVEL_ERROR, &ev); return -1; } } @@ -304,13 +373,33 @@ static int handle_gateway_payload(gateway_state *s, const char *auth, const char return 0; } if (strcmp(event, "MESSAGE_CREATE") == 0) { - handle_message_create(auth, reply, reaction, buf); + handle_message_create(s, auth, reply, reaction, buf); } else if (strcmp(event, "READY") == 0) { - log_info("READY event received"); + log_event ev = log_event_new("gateway.ready"); + ev.outcome = "success"; + ev.gateway_t = "READY"; + ev.sequence = s->sequence; + ev.heartbeat_interval_ms = s->heartbeat_interval; + ev.duration_ms = now_ms() - s->session_start_ms; + log_emit(LOG_LEVEL_INFO, &ev); } return 0; } +static void emit_session_end(gateway_state *s, const char *outcome, const char *error_type, + const char *error_message) { + log_event ev = log_event_new("session.end"); + ev.outcome = outcome; + ev.duration_ms = now_ms() - s->session_start_ms; + ev.sequence = s->sequence; + ev.heartbeat_interval_ms = s->heartbeat_interval; + ev.heartbeats_ok = (int)s->heartbeats_ok; + ev.heartbeats_fail = (int)s->heartbeats_fail; + ev.error_type = error_type; + ev.error_message = error_message; + log_emit(outcome && strcmp(outcome, "error") == 0 ? LOG_LEVEL_ERROR : LOG_LEVEL_INFO, &ev); +} + /* ── Main ─────────────────────────────────────────────────────── */ int main(void) { @@ -321,7 +410,11 @@ int main(void) { const char *reaction = getenv("DISCORD_REACTION"); if (!token || !*token) { - fprintf(stderr, "DISCORD_TOKEN is required\n"); + log_event ev = log_event_new("session.start"); + ev.outcome = "error"; + ev.error_type = "ConfigError"; + ev.error_message = "DISCORD_TOKEN is required"; + log_emit(LOG_LEVEL_ERROR, &ev); return 1; } if (!reaction) { @@ -332,41 +425,74 @@ int main(void) { char gateway_token[512]; normalize_token(token, auth, sizeof(auth), gateway_token, sizeof(gateway_token)); + gateway_state state = { + .heartbeat_interval = 45000, + .sequence = -1, + .next_heartbeat = 0, + .session_start_ms = now_ms(), + }; + if (tls_init_ca() != 0) { - fprintf(stderr, "Failed to init CA certificates\n"); + log_event ev = log_event_new("session.start"); + ev.outcome = "error"; + ev.error_type = "TlsCaError"; + ev.error_message = "CA certificate init failed"; + log_emit(LOG_LEVEL_ERROR, &ev); return 1; } - gateway_state state = {.heartbeat_interval = 45000, .sequence = -1, .next_heartbeat = 0}; - + long long t_connect = now_ms(); if (tls_connect(&state.conn, GATEWAY_HOST, API_PORT) != 0) { - log_error("Gateway TLS connect failed"); + log_event ev = log_event_new("session.start"); + ev.outcome = "error"; + ev.duration_ms = now_ms() - t_connect; + ev.host = GATEWAY_HOST; + ev.error_type = "TlsConnectError"; + ev.error_message = "gateway TLS connect failed"; + log_emit(LOG_LEVEL_ERROR, &ev); return 1; } - log_info("Connected to gateway TLS"); if (ws_handshake(&state.conn, GATEWAY_HOST, GATEWAY_PATH) != 0) { - log_error("WebSocket handshake failed"); + log_event ev = log_event_new("session.start"); + ev.outcome = "error"; + ev.duration_ms = now_ms() - t_connect; + ev.host = GATEWAY_HOST; + ev.error_type = "WsHandshakeError"; + ev.error_message = "websocket handshake failed"; + log_emit(LOG_LEVEL_ERROR, &ev); tls_close(&state.conn); return 1; } - log_info("WebSocket handshake complete"); char buf[BUF_SIZE]; if (wait_for_hello(&state, gateway_token, buf, sizeof(buf)) != 0) { + emit_session_end(&state, "error", "HelloError", "did not receive HELLO/identify"); tls_close(&state.conn); return 1; } + { + log_event ev = log_event_new("session.start"); + ev.outcome = "success"; + ev.duration_ms = now_ms() - state.session_start_ms; + ev.host = GATEWAY_HOST; + ev.heartbeat_interval_ms = state.heartbeat_interval; + log_emit(LOG_LEVEL_INFO, &ev); + } + while (1) { int rc = poll_and_read(&state, buf, sizeof(buf)); if (rc < 0) { + emit_session_end(&state, "error", "GatewayLoopError", "poll/read/heartbeat failed"); break; } if (rc > 0) { continue; /* idle / heartbeat-only tick */ } if (handle_gateway_payload(&state, auth, reply, reaction, buf) != 0) { + /* reconnect event already emitted */ + emit_session_end(&state, "reconnect", NULL, NULL); break; } } diff --git a/src/log.c b/src/log.c new file mode 100644 index 0000000..936885d --- /dev/null +++ b/src/log.c @@ -0,0 +1,281 @@ +/* Wide-event / canonical log line emitter. */ +#include "log.h" + +#include +#include +#include +#include +#include +#include + +static int g_log_level = LOG_LEVEL_INFO; +static double g_sample_rate = 1.0; /* keep all by default — bot traffic is tiny */ +static const char *g_version = "0.1"; +static const char *g_commit = ""; +static unsigned g_sample_counter; + +log_event log_event_new(const char *event) { + log_event ev; + memset(&ev, 0, sizeof(ev)); + ev.event = event; + ev.duration_ms = LOG_OMIT_LL; + ev.gateway_op = LOG_OMIT_LL; + ev.sequence = LOG_OMIT_LL; + ev.heartbeat_interval_ms = LOG_OMIT_LL; + ev.matched_king = LOG_OMIT_I; + ev.reply_enabled = LOG_OMIT_I; + ev.reply_http_status = LOG_OMIT_I; + ev.reaction_http_status = LOG_OMIT_I; + ev.content_len = LOG_OMIT_I; + ev.heartbeats_ok = LOG_OMIT_I; + ev.heartbeats_fail = LOG_OMIT_I; + ev.error_code = LOG_OMIT_ERR; + ev.attempt = LOG_OMIT_I; + ev.max_attempts = LOG_OMIT_I; + ev.http_status = LOG_OMIT_I; + return ev; +} + +void log_init_from_env(void) { + const char *lvl = getenv("LOG_LEVEL"); + if (lvl && strcmp(lvl, "error") == 0) { + g_log_level = LOG_LEVEL_ERROR; + } else if (lvl && (strcmp(lvl, "info") == 0 || strcmp(lvl, "debug") == 0)) { + g_log_level = LOG_LEVEL_INFO; + } + + const char *rate = getenv("LOG_SAMPLE_RATE"); + if (rate && *rate) { + char *end = NULL; + double v = strtod(rate, &end); + if (end != rate && v >= 0.0 && v <= 1.0) { + g_sample_rate = v; + } + } + + const char *ver = getenv("KING_VERSION"); + if (ver && *ver) { + g_version = ver; + } + const char *commit = getenv("KING_COMMIT"); + if (commit && *commit) { + g_commit = commit; + } +} + +static int append_fmt(char *buf, size_t cap, size_t *off, const char *fmt, ...) + __attribute__((format(printf, 4, 5))); + +static int append_fmt(char *buf, size_t cap, size_t *off, const char *fmt, ...) { + if (*off >= cap) { + return -1; + } + va_list ap; + va_start(ap, fmt); + int n = vsnprintf(buf + *off, cap - *off, fmt, ap); + va_end(ap); + if (n < 0 || (size_t)n >= cap - *off) { + *off = cap; + return -1; + } + *off += (size_t)n; + return 0; +} + +static int append_json_str(char *buf, size_t cap, size_t *off, const char *s) { + if (append_fmt(buf, cap, off, "\"") != 0) { + return -1; + } + for (size_t i = 0; s[i]; i++) { + unsigned char ch = (unsigned char)s[i]; + if (ch == '"' || ch == '\\') { + if (append_fmt(buf, cap, off, "\\%c", ch) != 0) { + return -1; + } + } else if (ch == '\n') { + if (append_fmt(buf, cap, off, "\\n") != 0) { + return -1; + } + } else if (ch == '\r') { + if (append_fmt(buf, cap, off, "\\r") != 0) { + return -1; + } + } else if (ch == '\t') { + if (append_fmt(buf, cap, off, "\\t") != 0) { + return -1; + } + } else if (ch < 32) { + if (append_fmt(buf, cap, off, "\\u%04x", ch) != 0) { + return -1; + } + } else { + if (append_fmt(buf, cap, off, "%c", ch) != 0) { + return -1; + } + } + } + return append_fmt(buf, cap, off, "\""); +} + +static int append_field_str(char *buf, size_t cap, size_t *off, int *first, const char *key, + const char *val) { + if (!val) { + return 0; + } + if (!*first && append_fmt(buf, cap, off, ",") != 0) { + return -1; + } + *first = 0; + if (append_fmt(buf, cap, off, "\"%s\":", key) != 0) { + return -1; + } + return append_json_str(buf, cap, off, val); +} + +static int append_field_ll(char *buf, size_t cap, size_t *off, int *first, const char *key, + long long val, long long omit) { + if (val == omit) { + return 0; + } + if (!*first && append_fmt(buf, cap, off, ",") != 0) { + return -1; + } + *first = 0; + return append_fmt(buf, cap, off, "\"%s\":%lld", key, val); +} + +static int append_field_i(char *buf, size_t cap, size_t *off, int *first, const char *key, int val, + int omit) { + if (val == omit) { + return 0; + } + if (!*first && append_fmt(buf, cap, off, ",") != 0) { + return -1; + } + *first = 0; + return append_fmt(buf, cap, off, "\"%s\":%d", key, val); +} + +static int append_field_bool(char *buf, size_t cap, size_t *off, int *first, const char *key, + int val) { + if (val == LOG_OMIT_I) { + return 0; + } + if (!*first && append_fmt(buf, cap, off, ",") != 0) { + return -1; + } + *first = 0; + return append_fmt(buf, cap, off, "\"%s\":%s", key, val ? "true" : "false"); +} + +int log_format_event(char *buf, size_t cap, const log_event *ev) { + if (!buf || cap < 2 || !ev || !ev->event) { + return -1; + } + + size_t off = 0; + int first = 1; + if (append_fmt(buf, cap, &off, "{") != 0) { + return -1; + } + + char ts[32]; + time_t now = time(NULL); + struct tm tm; + gmtime_r(&now, &tm); + strftime(ts, sizeof(ts), "%Y-%m-%dT%H:%M:%SZ", &tm); + + if (append_field_str(buf, cap, &off, &first, "timestamp", ts) != 0 || + append_field_str(buf, cap, &off, &first, "service", "king") != 0 || + append_field_str(buf, cap, &off, &first, "version", g_version) != 0 || + append_field_i(buf, cap, &off, &first, "pid", (int)getpid(), LOG_OMIT_ERR) != 0) { + return -1; + } + if (g_commit && *g_commit) { + if (append_field_str(buf, cap, &off, &first, "commit", g_commit) != 0) { + return -1; + } + } + + if (append_field_str(buf, cap, &off, &first, "event", ev->event) != 0 || + append_field_str(buf, cap, &off, &first, "outcome", ev->outcome) != 0 || + append_field_ll(buf, cap, &off, &first, "duration_ms", ev->duration_ms, LOG_OMIT_LL) != 0 || + append_field_str(buf, cap, &off, &first, "request_id", ev->request_id) != 0 || + append_field_str(buf, cap, &off, &first, "channel_id", ev->channel_id) != 0 || + append_field_str(buf, cap, &off, &first, "message_id", ev->message_id) != 0 || + append_field_ll(buf, cap, &off, &first, "gateway_op", ev->gateway_op, LOG_OMIT_LL) != 0 || + append_field_ll(buf, cap, &off, &first, "sequence", ev->sequence, LOG_OMIT_LL) != 0 || + append_field_str(buf, cap, &off, &first, "gateway_t", ev->gateway_t) != 0 || + append_field_ll(buf, cap, &off, &first, "heartbeat_interval_ms", ev->heartbeat_interval_ms, + LOG_OMIT_LL) != 0 || + append_field_bool(buf, cap, &off, &first, "matched_king", ev->matched_king) != 0 || + append_field_bool(buf, cap, &off, &first, "reply_enabled", ev->reply_enabled) != 0 || + append_field_i(buf, cap, &off, &first, "reply_http_status", ev->reply_http_status, + LOG_OMIT_I) != 0 || + append_field_i(buf, cap, &off, &first, "reaction_http_status", ev->reaction_http_status, + LOG_OMIT_I) != 0 || + append_field_i(buf, cap, &off, &first, "content_len", ev->content_len, LOG_OMIT_I) != 0 || + append_field_i(buf, cap, &off, &first, "heartbeats_ok", ev->heartbeats_ok, LOG_OMIT_I) != + 0 || + append_field_i(buf, cap, &off, &first, "heartbeats_fail", ev->heartbeats_fail, + LOG_OMIT_I) != 0 || + append_field_str(buf, cap, &off, &first, "error_type", ev->error_type) != 0 || + append_field_str(buf, cap, &off, &first, "error_message", ev->error_message) != 0 || + append_field_i(buf, cap, &off, &first, "error_code", ev->error_code, LOG_OMIT_ERR) != 0 || + append_field_i(buf, cap, &off, &first, "attempt", ev->attempt, LOG_OMIT_I) != 0 || + append_field_i(buf, cap, &off, &first, "max_attempts", ev->max_attempts, LOG_OMIT_I) != 0 || + append_field_str(buf, cap, &off, &first, "http_method", ev->http_method) != 0 || + append_field_str(buf, cap, &off, &first, "http_path", ev->http_path) != 0 || + append_field_i(buf, cap, &off, &first, "http_status", ev->http_status, LOG_OMIT_I) != 0 || + append_field_str(buf, cap, &off, &first, "host", ev->host) != 0) { + return -1; + } + + if (append_fmt(buf, cap, &off, "}") != 0) { + return -1; + } + return (int)off; +} + +static int should_emit(int level, const log_event *ev) { + if (level > g_log_level) { + return 0; + } + if (level <= LOG_LEVEL_ERROR) { + return 1; + } + if (ev->outcome && strcmp(ev->outcome, "error") == 0) { + return 1; + } + if (ev->matched_king == 1) { + return 1; + } + if (g_sample_rate >= 1.0) { + return 1; + } + if (g_sample_rate <= 0.0) { + return 0; + } + g_sample_counter++; + unsigned threshold = (unsigned)(g_sample_rate * 1000.0); + return (g_sample_counter % 1000) < threshold; +} + +void log_emit(int level, const log_event *ev) { +#if LOG_LEVEL_COMPILE < LOG_LEVEL_ERROR + (void)level; + (void)ev; +#else + if (!ev || !should_emit(level, ev)) { + return; + } + char line[2048]; + if (log_format_event(line, sizeof(line), ev) < 0) { + fprintf(stderr, + "{\"event\":\"log.format_error\",\"outcome\":\"error\",\"service\":\"king\"}\n"); + return; + } + fputs(line, stderr); + fputc('\n', stderr); +#endif +} diff --git a/src/log.h b/src/log.h index 8beead6..3c7fc56 100644 --- a/src/log.h +++ b/src/log.h @@ -1,79 +1,81 @@ -/* Header-only logging with runtime level and compile-time stripping. */ +/* Wide-event logger (canonical log lines). + * + * Lessons from https://www.loggingsucks.com : + * - emit one context-rich JSON event per unit of work + * - structured key/value fields (queryable), not diary strings + * - high-cardinality IDs + business context on the event + * - info + error levels only; tail-sample boring successes + * + * Never put secrets (DISCORD_TOKEN) into a log_event. + */ #ifndef LOG_H #define LOG_H -#include -#include -#include -#include +#include +#include -enum { LOG_LEVEL_ERROR = 0, LOG_LEVEL_INFO = 1, LOG_LEVEL_DEBUG = 2 }; +enum { LOG_LEVEL_ERROR = 0, LOG_LEVEL_INFO = 1 }; #ifndef LOG_LEVEL_COMPILE -#define LOG_LEVEL_COMPILE LOG_LEVEL_DEBUG +#define LOG_LEVEL_COMPILE LOG_LEVEL_INFO #endif -static int g_log_level = LOG_LEVEL_INFO; - -static inline void log_init_from_env(void) { - const char *lvl = getenv("LOG_LEVEL"); - if (!lvl || !*lvl) { - return; - } - if (strcmp(lvl, "error") == 0) { - g_log_level = LOG_LEVEL_ERROR; - } else if (strcmp(lvl, "debug") == 0) { - g_log_level = LOG_LEVEL_DEBUG; - } -} - -/* Shared writer — keeps the three public log_* helpers DRY. */ -static inline void log_write(int level, const char *tag, const char *fmt, va_list ap) { - if (g_log_level < level) { - return; - } - fprintf(stderr, "%s ", tag); - vfprintf(stderr, fmt, ap); - fputc('\n', stderr); -} - -#if LOG_LEVEL_COMPILE >= LOG_LEVEL_ERROR -__attribute__((format(printf, 1, 2))) static inline void log_error(const char *fmt, ...) { - va_list ap; - va_start(ap, fmt); - log_write(LOG_LEVEL_ERROR, "[ERROR]", fmt, ap); - va_end(ap); -} -#else -#define log_error(...) \ - do { \ - } while (0) -#endif +/* Omitted numeric fields use these sentinels (see log_event_new). */ +#define LOG_OMIT_I (-1) +#define LOG_OMIT_LL LLONG_MIN +#define LOG_OMIT_ERR INT_MIN -#if LOG_LEVEL_COMPILE >= LOG_LEVEL_INFO -__attribute__((format(printf, 1, 2))) static inline void log_info(const char *fmt, ...) { - va_list ap; - va_start(ap, fmt); - log_write(LOG_LEVEL_INFO, "[INFO]", fmt, ap); - va_end(ap); -} -#else -#define log_info(...) \ - do { \ - } while (0) -#endif +typedef struct log_event { + const char *event; /* required: e.g. "message.handle" */ + const char *outcome; /* success | error | ignored | reconnect */ -#if LOG_LEVEL_COMPILE >= LOG_LEVEL_DEBUG -__attribute__((format(printf, 1, 2))) static inline void log_debug(const char *fmt, ...) { - va_list ap; - va_start(ap, fmt); - log_write(LOG_LEVEL_DEBUG, "[DEBUG]", fmt, ap); - va_end(ap); -} -#else -#define log_debug(...) \ - do { \ - } while (0) -#endif + long long duration_ms; + + /* High-cardinality Discord / correlation IDs */ + const char *request_id; + const char *channel_id; + const char *message_id; + + /* Gateway context */ + long long gateway_op; + long long sequence; + const char *gateway_t; + long long heartbeat_interval_ms; + + /* Business context for the king bot */ + int matched_king; /* 0/1, or LOG_OMIT_I */ + int reply_enabled; + int reply_http_status; + int reaction_http_status; + int content_len; + int heartbeats_ok; + int heartbeats_fail; + + /* Errors / retries */ + const char *error_type; + const char *error_message; + int error_code; + int attempt; + int max_attempts; + + /* Optional HTTP / peer context */ + const char *http_method; + const char *http_path; + int http_status; + const char *host; +} log_event; + +/* Zero + omit-sentinels; sets .event. */ +log_event log_event_new(const char *event); + +void log_init_from_env(void); + +/* Format one NDJSON object into buf (NUL-terminated). Returns bytes written + * (excluding NUL), or -1 if truncated/invalid. Pure — used by tests. */ +int log_format_event(char *buf, size_t cap, const log_event *ev); + +/* Emit to stderr if level/sampling allows. Always keeps errors and + * matched_king==1. Other info events subject to LOG_SAMPLE_RATE. */ +void log_emit(int level, const log_event *ev); #endif /* LOG_H */ diff --git a/src/net.c b/src/net.c index a9952cb..abcd91e 100644 --- a/src/net.c +++ b/src/net.c @@ -19,7 +19,12 @@ int tls_init_ca(void) { mbedtls_x509_crt_init(&g_ca); int rc = mbedtls_x509_crt_parse(&g_ca, (const unsigned char *)CA_BUNDLE_PEM, CA_BUNDLE_PEM_LEN); if (rc != 0) { - log_error("CA cert parse failed: -0x%04x", -rc); + log_event ev = log_event_new("tls.ca_init"); + ev.outcome = "error"; + ev.error_type = "CaParseError"; + ev.error_message = "mbedtls_x509_crt_parse failed"; + ev.error_code = -rc; + log_emit(LOG_LEVEL_ERROR, &ev); return -1; } g_ca_ready = 1; @@ -111,7 +116,13 @@ int tls_connect(tls_conn *c, const char *host, const char *port) { int ret = mbedtls_ssl_handshake(&c->ssl); if (ret != 0) { - log_error("TLS handshake failed: -0x%04x", -ret); + log_event ev = log_event_new("tls.handshake"); + ev.outcome = "error"; + ev.host = host; + ev.error_type = "TlsHandshakeError"; + ev.error_message = "mbedtls_ssl_handshake failed"; + ev.error_code = -ret; + log_emit(LOG_LEVEL_ERROR, &ev); goto fail; } diff --git a/src/test_king.c b/src/test_king.c index fb55353..20fc13c 100644 --- a/src/test_king.c +++ b/src/test_king.c @@ -3,10 +3,12 @@ * - json.c (JSON key extraction) * - str.c (string utilities: contains_case, json_escape, url_encode, * http_status_code) + * - log.c (wide-event JSON formatting) * * Build: make test */ #include "json.h" +#include "log.h" #include "str.h" #include "test.h" @@ -230,5 +232,42 @@ int main(void) { ASSERT(http_status_code("") == -1); ASSERT(http_status_code("HTTP/1.1 ") == 0); + /* ================================================================== + * log_format_event — wide-event / canonical JSON line + * ================================================================== */ + { + char line[2048]; + log_event ev = log_event_new("message.handle"); + ev.outcome = "success"; + ev.duration_ms = 42; + ev.request_id = "req_test"; + ev.channel_id = "222"; + ev.message_id = "111"; + ev.matched_king = 1; + ev.reply_http_status = 200; + ev.reaction_http_status = 204; + ev.content_len = 10; + ASSERT(log_format_event(line, sizeof(line), &ev) > 0); + ASSERT(strstr(line, "\"event\":\"message.handle\"") != NULL); + ASSERT(strstr(line, "\"outcome\":\"success\"") != NULL); + ASSERT(strstr(line, "\"duration_ms\":42") != NULL); + ASSERT(strstr(line, "\"request_id\":\"req_test\"") != NULL); + ASSERT(strstr(line, "\"channel_id\":\"222\"") != NULL); + ASSERT(strstr(line, "\"matched_king\":true") != NULL); + ASSERT(strstr(line, "\"service\":\"king\"") != NULL); + ASSERT(strstr(line, "\"reply_http_status\":200") != NULL); + /* omitted fields stay out of the payload */ + ASSERT(strstr(line, "error_type") == NULL); + ASSERT(strstr(line, "gateway_op") == NULL); + + /* escaping */ + log_event bad = log_event_new("test"); + bad.error_message = "say \"hi\"\n"; + ASSERT(log_format_event(line, sizeof(line), &bad) > 0); + ASSERT(strstr(line, "say \\\"hi\\\"\\n") != NULL); + + ASSERT(log_format_event(line, sizeof(line), NULL) < 0); + } + TEST_SUMMARY(); }