Files
codebase-memory-mcp/tests/test_log.c
T
Andrew Hundt 59def6aaeb merge(upstream): integrate main through Laravel route fixes
Merge upstream/main at 2469ecc3 into integrate-upstream-split-search-tools while retaining branch-specific incremental indexing, MCP API consolidation, and graph extraction behavior.

The staged tree adds upstream's Mojo and Perl grammar support, issue reproduction suites, Graph UI changes, Windows smoke coverage, TOON graph output, subprocess supervision, and Laravel facade route handling. Conflict resolutions in src/pipeline/httplink.c and pass_httplinks.c retain dynamic growth and IMPORTS edge identity; scripts/smoke-test.sh and scripts/soak-test.sh retain hermetic cache isolation.

Validation against the merge plus the follow-up working-tree reconciliation: ASan/UBSan MCP suite 216/216 passed. Follow-up semantic and concurrency fixes remain intentionally unstaged for the next focused commit.
2026-07-14 01:47:43 -04:00

344 lines
10 KiB
C

/*
* test_log.c — RED phase tests for foundation/log.
*
* Testing logging is tricky since output goes to stderr.
* We redirect stderr to a pipe and read back the output.
*/
#include "test_framework.h"
#include "../src/foundation/log.h"
#include "../src/foundation/compat.h"
#include <stdbool.h>
#ifndef _WIN32
#include <unistd.h>
#include <fcntl.h>
#else
#include <io.h>
#include <fcntl.h>
#endif
/* Simple strstr wrapper used by log tests (avoids circular dep on str_util) */
static inline bool cbm_str_contains_raw(const char *s, const char *sub) {
return strstr(s, sub) != NULL;
}
static char log_buf[4096];
static char sink_buf[4096];
static int saved_stderr;
static int pipe_fds[2];
static void test_log_sink(const char *line) {
if (!line) {
return;
}
size_t used = strlen(sink_buf);
if (used >= sizeof(sink_buf) - 1) {
return;
}
snprintf(sink_buf + used, sizeof(sink_buf) - used, "%s\n", line);
}
static void capture_start(void) {
fflush(stderr);
saved_stderr = dup(STDERR_FILENO);
cbm_pipe(pipe_fds);
#ifndef _WIN32
/* Set read end to non-blocking */
fcntl(pipe_fds[0], F_SETFL, O_NONBLOCK);
#endif
dup2(pipe_fds[1], STDERR_FILENO);
close(pipe_fds[1]);
}
static const char *capture_end(void) {
fflush(stderr);
dup2(saved_stderr, STDERR_FILENO);
close(saved_stderr);
ssize_t n = read(pipe_fds[0], log_buf, sizeof(log_buf) - 1);
close(pipe_fds[0]);
if (n < 0)
n = 0;
log_buf[n] = '\0';
return log_buf;
}
TEST(log_level_default) {
/* Default level should be INFO */
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_INFO);
PASS();
}
TEST(log_level_set) {
cbm_log_set_level(CBM_LOG_WARN);
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_WARN);
cbm_log_set_level(CBM_LOG_INFO); /* restore */
PASS();
}
TEST(log_info_output) {
cbm_log_set_level(CBM_LOG_DEBUG);
capture_start();
cbm_log_info("test.msg", "key1", "val1", "key2", "val2");
const char *output = capture_end();
cbm_log_set_level(CBM_LOG_INFO);
ASSERT(cbm_str_contains_raw(output, "level=info"));
ASSERT(cbm_str_contains_raw(output, "msg=test.msg"));
ASSERT(cbm_str_contains_raw(output, "key1=val1"));
ASSERT(cbm_str_contains_raw(output, "key2=val2"));
PASS();
}
TEST(log_filtered_by_level) {
cbm_log_set_level(CBM_LOG_WARN);
capture_start();
cbm_log_info("should.not.appear");
const char *output = capture_end();
cbm_log_set_level(CBM_LOG_INFO);
/* Should be empty — info is below warn threshold */
ASSERT_EQ(strlen(output), 0);
PASS();
}
TEST(log_error_output) {
cbm_log_set_level(CBM_LOG_DEBUG);
capture_start();
cbm_log_error("critical.fail", "err", "OOM");
const char *output = capture_end();
cbm_log_set_level(CBM_LOG_INFO);
ASSERT(cbm_str_contains_raw(output, "level=error"));
ASSERT(cbm_str_contains_raw(output, "msg=critical.fail"));
ASSERT(cbm_str_contains_raw(output, "err=OOM"));
PASS();
}
TEST(log_int_helper) {
cbm_log_set_level(CBM_LOG_DEBUG);
capture_start();
cbm_log_int(CBM_LOG_INFO, "pass.timing", "elapsed_ms", 42);
const char *output = capture_end();
cbm_log_set_level(CBM_LOG_INFO);
ASSERT(cbm_str_contains_raw(output, "elapsed_ms=42"));
PASS();
}
TEST(log_profile_mirror_is_opt_in_and_prof_only) {
cbm_log_set_level(CBM_LOG_DEBUG);
cbm_log_set_profile_stderr_mirror(false);
sink_buf[0] = '\0';
cbm_log_set_sink(test_log_sink);
capture_start();
cbm_log_info("prof", "phase", "unit", "sub", "sink_only");
const char *output = capture_end();
ASSERT_EQ(strlen(output), 0);
ASSERT(cbm_str_contains_raw(sink_buf, "msg=prof"));
sink_buf[0] = '\0';
cbm_log_set_profile_stderr_mirror(true);
capture_start();
cbm_log_info("prof", "phase", "unit", "sub", "mirrored");
output = capture_end();
ASSERT(cbm_str_contains_raw(output, "msg=prof"));
ASSERT(cbm_str_contains_raw(output, "sub=mirrored"));
ASSERT(cbm_str_contains_raw(sink_buf, "msg=prof"));
sink_buf[0] = '\0';
capture_start();
cbm_log_info("not.prof", "key", "value");
output = capture_end();
ASSERT_EQ(strlen(output), 0);
ASSERT(cbm_str_contains_raw(sink_buf, "msg=not.prof"));
cbm_log_set_sink(NULL);
cbm_log_set_profile_stderr_mirror(false);
cbm_log_set_level(CBM_LOG_INFO);
PASS();
}
TEST(log_json_output) {
cbm_log_set_level(CBM_LOG_DEBUG);
cbm_log_set_format(CBM_LOG_FORMAT_JSON);
capture_start();
cbm_log_info("test.msg", "key1", "val1", "key2", "line\nbreak");
const char *output = capture_end();
cbm_log_set_format(CBM_LOG_FORMAT_TEXT);
cbm_log_set_level(CBM_LOG_INFO);
ASSERT(cbm_str_contains_raw(output, "\"level\":\"info\""));
ASSERT(cbm_str_contains_raw(output, "\"event\":\"test.msg\""));
ASSERT(cbm_str_contains_raw(output, "\"key1\":\"val1\""));
ASSERT(cbm_str_contains_raw(output, "\"key2\":\"line\\nbreak\""));
PASS();
}
TEST(log_text_sanitizes_control_chars) {
cbm_log_set_level(CBM_LOG_DEBUG);
cbm_log_set_format(CBM_LOG_FORMAT_TEXT);
capture_start();
cbm_log_info("test\nmsg", "key", "line\r\nbreak\tvalue");
const char *output = capture_end();
cbm_log_set_level(CBM_LOG_INFO);
ASSERT(cbm_str_contains_raw(output, "msg=test_msg"));
ASSERT(cbm_str_contains_raw(output, "key=line__break_value"));
ASSERT_EQ(output[strlen(output) - 1], '\n');
ASSERT_NULL(strchr(output, '\r'));
PASS();
}
TEST(log_sink_tee_keeps_stderr) {
sink_buf[0] = '\0';
cbm_log_set_level(CBM_LOG_DEBUG);
cbm_log_set_format(CBM_LOG_FORMAT_TEXT);
cbm_log_set_sink_ex(test_log_sink, CBM_LOG_SINK_TEE);
capture_start();
cbm_log_info("tee.msg", "key", "val");
const char *output = capture_end();
cbm_log_set_sink(NULL);
cbm_log_set_level(CBM_LOG_INFO);
ASSERT(cbm_str_contains_raw(output, "msg=tee.msg"));
ASSERT(cbm_str_contains_raw(sink_buf, "msg=tee.msg"));
PASS();
}
TEST(log_operational_helpers) {
cbm_log_set_level(CBM_LOG_DEBUG);
cbm_log_set_format(CBM_LOG_FORMAT_TEXT);
capture_start();
cbm_log_mcp_request("tools/call", "search_graph", false, 1250);
cbm_log_http_request("graph_ui", "GET", "/api/layout", 200, 7, 0, 42);
const char *output = capture_end();
cbm_log_set_level(CBM_LOG_INFO);
ASSERT(cbm_str_contains_raw(output, "msg=mcp.request"));
ASSERT(cbm_str_contains_raw(output, "protocol=jsonrpc"));
ASSERT(cbm_str_contains_raw(output, "method=tools/call"));
ASSERT(cbm_str_contains_raw(output, "tool=search_graph"));
ASSERT(cbm_str_contains_raw(output, "msg=http.request"));
ASSERT(cbm_str_contains_raw(output, "method=GET"));
ASSERT(cbm_str_contains_raw(output, "path=/api/layout"));
ASSERT(cbm_str_contains_raw(output, "status=200"));
PASS();
}
TEST(log_format_from_env) {
cbm_setenv("CBM_LOG_FORMAT", "json", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_format(), CBM_LOG_FORMAT_JSON);
cbm_setenv("CBM_LOG_FORMAT", "text", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_format(), CBM_LOG_FORMAT_TEXT);
cbm_unsetenv("CBM_LOG_FORMAT");
cbm_log_set_format(CBM_LOG_FORMAT_TEXT);
PASS();
}
TEST(log_format_unset_keeps_current) {
cbm_unsetenv("CBM_LOG_FORMAT");
cbm_log_set_format(CBM_LOG_FORMAT_JSON);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_format(), CBM_LOG_FORMAT_JSON);
cbm_log_set_format(CBM_LOG_FORMAT_TEXT);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_format(), CBM_LOG_FORMAT_TEXT);
PASS();
}
/* CBM_LOG_LEVEL parsing — distilled from #414 (closes #413). */
TEST(log_level_from_env_textual) {
cbm_setenv("CBM_LOG_LEVEL", "error", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_ERROR);
cbm_setenv("CBM_LOG_LEVEL", "debug", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_DEBUG);
cbm_setenv("CBM_LOG_LEVEL", "none", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_NONE);
/* Matching is case-insensitive */
cbm_setenv("CBM_LOG_LEVEL", "WARN", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_WARN);
cbm_setenv("CBM_LOG_LEVEL", "Info", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_INFO);
cbm_unsetenv("CBM_LOG_LEVEL");
cbm_log_set_level(CBM_LOG_INFO); /* restore */
PASS();
}
TEST(log_level_from_env_numeric) {
/* 0=debug 1=info 2=warn 3=error 4=none — mirrors CBMLogLevel */
cbm_setenv("CBM_LOG_LEVEL", "0", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_DEBUG);
cbm_setenv("CBM_LOG_LEVEL", "3", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_ERROR);
cbm_setenv("CBM_LOG_LEVEL", "4", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_NONE);
/* Out-of-range numeric is ignored — level unchanged */
cbm_log_set_level(CBM_LOG_INFO);
cbm_setenv("CBM_LOG_LEVEL", "5", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_INFO);
cbm_unsetenv("CBM_LOG_LEVEL");
cbm_log_set_level(CBM_LOG_INFO); /* restore */
PASS();
}
TEST(log_level_from_env_invalid_ignored) {
/* Unknown string and empty/unset both leave the level unchanged (fail-open) */
cbm_log_set_level(CBM_LOG_WARN);
cbm_setenv("CBM_LOG_LEVEL", "verbose", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_WARN);
cbm_setenv("CBM_LOG_LEVEL", "", 1);
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_WARN);
cbm_unsetenv("CBM_LOG_LEVEL");
cbm_log_init_from_env();
ASSERT_EQ(cbm_log_get_level(), CBM_LOG_WARN);
cbm_log_set_level(CBM_LOG_INFO); /* restore */
PASS();
}
SUITE(log) {
RUN_TEST(log_level_default);
RUN_TEST(log_level_set);
RUN_TEST(log_info_output);
RUN_TEST(log_filtered_by_level);
RUN_TEST(log_error_output);
RUN_TEST(log_int_helper);
RUN_TEST(log_profile_mirror_is_opt_in_and_prof_only);
RUN_TEST(log_json_output);
RUN_TEST(log_text_sanitizes_control_chars);
RUN_TEST(log_sink_tee_keeps_stderr);
RUN_TEST(log_operational_helpers);
RUN_TEST(log_format_from_env);
RUN_TEST(log_format_unset_keeps_current);
RUN_TEST(log_level_from_env_textual);
RUN_TEST(log_level_from_env_numeric);
RUN_TEST(log_level_from_env_invalid_ignored);
}