feat(history): flat-file backend with bidirectional SQLite migration
All checks were successful
CI Code / Check spelling (push) Successful in 21s
CI Code / Check coding style (push) Successful in 31s
CI Code / Code Coverage (push) Successful in 2m21s
CI Code / Linux (ubuntu) (push) Successful in 4m30s
CI Code / Linux (debian) (push) Successful in 6m43s
CI Code / Linux (arch) (push) Successful in 10m8s

A flat-file alternative to the SQLite chatlog backend with runtime
switching, full migration tooling, integrity verification, and a
synthetic load harness. SQLite remains the default; both backends share
one dispatch layer (db_backend_t vtable) so callers don't change.

Storage layout
- Per-contact append-only `flatlog/<account>/<contact>/history.log`
  under XDG_DATA_HOME, one line per message
- Single-line file header with embedded format-version marker
  (FLATFILE_FORMAT_VERSION); reader warns on missing or mismatched
  marker, writer and checker stay in sync via preprocessor
  stringification
- Deterministic key=value metadata (`id`, `aid`, `corrects`, `to`,
  `to_res`, `read`) plus escaped body \u2014 `\|`, `\]`, `\\`, `\n`, `\r`
  literals prevent log injection
- Sparse byte-offset index (FF_INDEX_STEP=500) per contact for
  O(log n) time-range lookups; rebuilt on inode / size / mtime
  change, extended in-place when the file just grew
- Per-contact GHashTable caches for archive_id presence and
  stanza_id \u2192 from_jid mapping (O(1) MAM dedup, O(1) LMC sender
  validation)

Hardening
- Path-traversal protection: JID directory name normalisation
  (`@` \u2192 `_at_`, slashes and `..` rejected at construction); every
  per-contact path is anchored under the account's flatlog/
  directory and validated before open
- Symlink-attack protection: every fopen / open uses O_NOFOLLOW; on
  ELOOP the operation aborts with an error rather than following
- Filesystem permissions: log files created with mode 0600,
  directories with mode 0700; both enforced at creation, verified
  on each open and reported on drift by `/history verify`
- Atomic crash-safe export: write to a temp file via mkstemp (mode
  0600, random suffix, no name collisions between concurrent
  exports), fsync, then rename \u2014 partial state never replaces the
  live file
- Concurrency: advisory flock(LOCK_EX) held for the duration of
  every write, including append from live messages and full rewrite
  from export, so two profanity processes can't interleave bytes
  on the same log
- DoS / abuse guards:
    * FF_MAX_LINE_LEN = 10 MB \u2014 lines longer than this are rejected
      at read with a warning; the parser will not allocate
      unbounded memory for a single record
    * FF_MAX_LMC_DEPTH = 100 \u2014 `corrects:` chain walk stops at this
      depth and emits a warning, preventing a malicious correction
      cycle from spinning the apply pass
    * FF_VERSION_SCAN_MAX = 16 \u2014 header version probe never reads
      past 16 leading comment lines, even on garbage input
    * Empty / inverted byte-range early-return in page-up read path
      so a malformed time filter cannot cause an unbounded scan
    * Zero-entry index guard so a file whose every line failed to
      parse cannot cause a NULL deref on later page-up
- LMC sender validation: an incoming correction whose sender does
  not match the original message's sender is rejected at write
  time and surfaced via cons_show_error; a cycle in the apply pass
  is broken via a visited-set
- jid_create_from_bare_and_resource treats NULL, empty string, and
  the literal "(null)" as no resource and returns a bare jid;
  similar normalisation for barejid eliminates the legacy
  "user@host/(null)" artefact that leaked into stored fulljids
  whenever g_strdup_printf("%s", NULL) ran inside create_fulljid

Commands
- `/history switch sqlite|flatfile` \u2014 runtime backend swap, closes
  the old backend and opens the new one without reconnecting
- `/history export [<jid>]` \u2014 SQLite -> flat-file, merging with any
  existing flatlog (dedup keyed on a SHA-256 hash mixing stanza_id,
  timestamp, from_jid, body \u2014 robust against id reuse by older
  clients)
- `/history import [<jid>]` \u2014 flat-file -> SQLite, same merge
  semantics, runs inside a single SQLite transaction with rollback
  on per-contact failure
- `/history verify [<jid>]` \u2014 integrity check; emits a structured
  list of issues (ERROR / WARNING / INFO) per file:
    * file-level: missing log, wrong permissions (\u2260 0600), UTF-8
      BOM present, CRLF line endings, empty file
    * line-level: invalid UTF-8 (with byte offset), embedded
      control characters, unparsable lines, timestamps out of
      order, duplicate `id:` and `aid:` (tracked separately so a
      stanza/archive id collision isn't double-reported)
    * cross-line: broken `corrects:` references whose target id is
      not present in the file
- `/history backend` \u2014 show currently active backend
- Active backend indicator `[sqlite]` / `[flatfile]` in the status
  bar next to the JID
- Roster-JID autocomplete for verify / export / import
- export and import open a SQLite handle on demand when the
  flatfile backend is currently active, so migration works
  regardless of which backend is live

Tests
- Unit: database_export (parser round-trip, escape/unescape, dedup
  key stability, JID normalisation), database_stress (14 cases
  exercising rapid writes, large messages, deep LMC chains, MAM
  dedup, concurrent contacts)
- Functional: history persistence across reconnects, export /
  import round-trip with content equality, MUC migration,
  timestamp normalisation across timezones
- Bench harness P1\u2013P5 (synthetic load: bulk insert, time-range
  read, page-up scroll, MAM ingest, mixed workload) and failure
  modes F1\u2013F17 (page-up cursor and forward-iteration symmetry,
  oversized lines, MAM dedup, LMC depth and cycles, BOM/CRLF,
  missing log, empty file, mtime+inode flip, broken corrects, etc.)
- All bench tests integrate with the existing make targets and
  emit CSV rows for baseline comparison

Author: jabber.developer2 <jabber.developer2@jabber.space>
Reviewed-by: jabber.developer <jabber.developer@jabber.space>
This commit is contained in:
2026-05-05 19:26:07 +00:00
parent 0feacbc9da
commit 3f36c303c2
50 changed files with 13811 additions and 793 deletions

View File

@@ -13,6 +13,7 @@
#include <sys/select.h>
#include <regex.h>
#include <signal.h>
#include <time.h>
#include <stabber.h>
@@ -25,34 +26,41 @@
#define PORTS_PER_GROUP 50
/* Base port and fallback scan range for stabber */
#define BASE_PORT 5230
#define FALLBACK_PORT_RANGE (TEST_GROUPS * PORTS_PER_GROUP)
#define BASE_PORT 5230
#define FALLBACK_PORT_RANGE (TEST_GROUPS * PORTS_PER_GROUP)
/* Shutdown polling: interval and maximum attempts before escalating signals */
#define MS_TO_US 1000
#define SHUTDOWN_POLL_MS 50
#define SHUTDOWN_POLL_MAX 100 /* 100 x 50ms = 5s */
#define SIGTERM_POLL_MAX 20 /* 20 x 50ms = 1s */
#define QUIT_GRACE_MS 100 /* grace for /quit to be read from pty */
#define INIT_WAIT_MS 50 /* wait for child process to initialize */
#define INPUT_DELAY_MS 10 /* let profanity process input */
#define OUTPUT_POLL_MS 50 /* polling interval for output checks */
#define READ_TIMEOUT_MS 100 /* select() timeout for pty reads */
#define MS_TO_US 1000
#define SHUTDOWN_POLL_MS 50
#define SHUTDOWN_POLL_MAX 100 /* 100 x 50ms = 5s */
#define SIGTERM_POLL_MAX 20 /* 20 x 50ms = 1s */
#define QUIT_GRACE_MS 100 /* grace for /quit to be read from pty */
#define INIT_WAIT_MS 50 /* wait for child process to initialize */
#define INPUT_DELAY_MS 10 /* let profanity process input */
#define OUTPUT_POLL_MS 50 /* polling interval for output checks */
#define READ_TIMEOUT_MS 100 /* select() timeout for pty reads */
/* Expect timeouts (seconds) */
#define EXPECT_TIMEOUT_DEFAULT 30
#define EXPECT_TIMEOUT_CONNECT 60
#define EXPECT_TIMEOUT_DEFAULT 30
#define EXPECT_TIMEOUT_CONNECT 60
/* Test duration thresholds (seconds) */
#define SLOW_TEST_THRESHOLD_S 20
#define FAST_TEST_THRESHOLD_S 0.3
/* Sentinel "infinity" for min-elapsed tracking (any real test is faster) */
#define MIN_ELAPSED_INIT 1e9
/* Terminal dimensions for forkpty */
#define PTY_ROWS 24
#define PTY_COLS 300
#define PTY_ROWS 24
#define PTY_COLS 300
/* Preprocessor stringification (for setenv from numeric #define) */
#define STRINGIFY_(x) #x
#define STRINGIFY(x) STRINGIFY_(x)
char *config_orig;
char *data_orig;
char* config_orig;
char* data_orig;
int fd = 0;
int stub_port = BASE_PORT;
@@ -77,8 +85,21 @@ static size_t output_len = 0;
/* Timeout for expect operations in seconds */
static int expect_timeout = EXPECT_TIMEOUT_DEFAULT;
/* Per-test wall-clock timer */
static struct timespec test_start_ts;
static const char* current_test_name;
static double min_elapsed = MIN_ELAPSED_INIT;
static const char* min_test_name = "(none)";
/* Per-test threshold overrides (0 = use default) */
double prof_test_slow_threshold = 0;
double prof_test_fast_threshold = 0;
/* Timezone for profanity child process (see proftest.h) */
const char* prof_test_tz = "UTC";
gboolean
_create_dir(const char *name)
_create_dir(const char* name)
{
struct stat sb;
@@ -96,14 +117,14 @@ _create_dir(const char *name)
}
gboolean
_mkdir_recursive(const char *dir)
_mkdir_recursive(const char* dir)
{
int i;
gboolean result = TRUE;
for (i = 1; i <= strlen(dir); i++) {
if (dir[i] == '/' || dir[i] == '\0') {
gchar *next_dir = g_strndup(dir, i);
gchar* next_dir = g_strndup(dir, i);
result = _create_dir(next_dir);
g_free(next_dir);
if (!result) {
@@ -118,7 +139,7 @@ _mkdir_recursive(const char *dir)
void
_create_config_dir(void)
{
GString *profanity_dir = g_string_new(xdg_config_home);
GString* profanity_dir = g_string_new(xdg_config_home);
g_string_append(profanity_dir, "/profanity");
if (!_mkdir_recursive(profanity_dir->str)) {
@@ -131,7 +152,7 @@ _create_config_dir(void)
void
_create_data_dir(void)
{
GString *profanity_dir = g_string_new(xdg_data_home);
GString* profanity_dir = g_string_new(xdg_data_home);
g_string_append(profanity_dir, "/profanity");
if (!_mkdir_recursive(profanity_dir->str)) {
@@ -144,7 +165,7 @@ _create_data_dir(void)
void
_create_chatlogs_dir(void)
{
GString *chatlogs_dir = g_string_new(xdg_data_home);
GString* chatlogs_dir = g_string_new(xdg_data_home);
g_string_append(chatlogs_dir, "/profanity/chatlogs");
if (!_mkdir_recursive(chatlogs_dir->str)) {
@@ -157,7 +178,7 @@ _create_chatlogs_dir(void)
void
_create_logs_dir(void)
{
GString *logs_dir = g_string_new(xdg_data_home);
GString* logs_dir = g_string_new(xdg_data_home);
g_string_append(logs_dir, "/profanity/logs");
if (!_mkdir_recursive(logs_dir->str)) {
@@ -170,12 +191,12 @@ _create_logs_dir(void)
void
_cleanup_dirs(void)
{
const char *group_env = getenv("PROF_TEST_GROUP");
const char* group_env = getenv("PROF_TEST_GROUP");
int group = group_env ? atoi(group_env) : 0;
int dir_id = (group >= 1 && group <= TEST_GROUPS) ? group : stub_port;
printf("[PROF_TEST] Cleaning up directories for group %d (dir_id %d)\n", group, dir_id);
char cmd[512];
snprintf(cmd, sizeof(cmd), "rm -rf ./test-files/%d", dir_id);
int res = system(cmd);
@@ -199,26 +220,26 @@ _read_output(int timeout_ms)
{
fd_set readfds;
struct timeval tv;
FD_ZERO(&readfds);
FD_SET(fd, &readfds);
tv.tv_sec = timeout_ms / MS_TO_US;
tv.tv_usec = (timeout_ms % MS_TO_US) * MS_TO_US;
int ret = select(fd + 1, &readfds, NULL, NULL, &tv);
if (ret <= 0) {
return ret;
}
size_t space = OUTPUT_BUF_SIZE - output_len - 1;
if (space <= 0) {
/* Buffer full, shift content */
memmove(output_buffer, output_buffer + OUTPUT_BUF_SIZE/2, OUTPUT_BUF_SIZE/2);
output_len = OUTPUT_BUF_SIZE/2;
memmove(output_buffer, output_buffer + OUTPUT_BUF_SIZE / 2, OUTPUT_BUF_SIZE / 2);
output_len = OUTPUT_BUF_SIZE / 2;
space = OUTPUT_BUF_SIZE - output_len - 1;
}
ssize_t n = read(fd, output_buffer + output_len, space);
if (n > 0) {
output_len += n;
@@ -239,50 +260,60 @@ prof_start(void)
ws.ws_col = PTY_COLS;
ws.ws_xpixel = 0;
ws.ws_ypixel = 0;
/* Reset output buffer */
output_len = 0;
output_buffer[0] = '\0';
/* Force UTC so delay-stamp timestamps render deterministically
* regardless of the host timezone (needed for functional tests
* that verify rendered timestamp strings). */
setenv("TZ", prof_test_tz, 1);
tzset();
child_pid = forkpty(&fd, NULL, NULL, &ws);
if (child_pid < 0) {
fd = -1;
return;
}
if (child_pid == 0) {
/* Child process */
setenv("COLUMNS", STRINGIFY(PTY_COLS), 1);
setenv("TERM", "xterm", 1);
execl("./profanity", "./profanity", "-l", "DEBUG", NULL);
/* If exec fails */
fprintf(stderr, "execl failed: %s\n", strerror(errno));
_exit(127);
}
/* Parent process */
/* Set non-blocking mode for reading */
int flags = fcntl(fd, F_GETFL, 0);
fcntl(fd, F_SETFL, flags | O_NONBLOCK);
/* Brief wait for process to initialize */
sleep_ms(INIT_WAIT_MS);
}
int
init_prof_test(void **state)
init_prof_test(void** state)
{
clock_gettime(CLOCK_MONOTONIC, &test_start_ts);
current_test_name = state && *state ? (const char*)*state : "unknown";
prof_test_slow_threshold = 0;
prof_test_fast_threshold = 0;
/* Get test group from environment for static resource allocation */
const char *group_env = getenv("PROF_TEST_GROUP");
const char* group_env = getenv("PROF_TEST_GROUP");
int group = group_env ? atoi(group_env) : 0;
/* Get build index for port offset (for parallel CI builds) */
const char *build_env = getenv("PROF_BUILD_INDEX");
const char* build_env = getenv("PROF_BUILD_INDEX");
int build_idx = build_env ? atoi(build_env) : 0;
/* Calculate port base: each build uses a different range of
* TEST_GROUPS * PORTS_PER_GROUP ports.
* Build 0 (local/default): 5230-5429, Full: 5230-5429, Minimal: 5430-5629, etc.
@@ -290,7 +321,7 @@ init_prof_test(void **state)
* or sequential run (no parallel builds), while Full/Minimal/NoEncrypt/Default
* are used in CI where they run in parallel. */
int port_base = BASE_PORT + ((build_idx > 0 ? build_idx - 1 : 0) * TEST_GROUPS * PORTS_PER_GROUP);
/* Each group gets a dedicated range of ports for parallel execution.
* Group 1: port_base..port_base+PORTS_PER_GROUP-1
* Group 2: port_base+PORTS_PER_GROUP..port_base+2*PORTS_PER_GROUP-1, etc.
@@ -322,7 +353,7 @@ init_prof_test(void **state)
}
}
}
if (!started) {
fprintf(stderr, "[PROF_TEST] ERROR: could not start stabber on any port\n");
return -1;
@@ -335,8 +366,8 @@ init_prof_test(void **state)
"./test-files/%d/xdg_config_home", dir_id);
snprintf(xdg_data_home, sizeof(xdg_data_home),
"./test-files/%d/xdg_data_home", dir_id);
printf("[PROF_TEST] Group %d using directories: config=%s, data=%s\n",
printf("[PROF_TEST] Group %d using directories: config=%s, data=%s\n",
group, xdg_config_home, xdg_data_home);
config_orig = getenv("XDG_CONFIG_HOME");
@@ -387,7 +418,7 @@ init_prof_test(void **state)
}
int
close_prof_test(void **state)
close_prof_test(void** state)
{
if (fd > 0 && child_pid > 0) {
prof_input("/quit");
@@ -408,7 +439,10 @@ close_prof_test(void **state)
if (!exited) {
kill(child_pid, SIGTERM);
for (int i = 0; i < SIGTERM_POLL_MAX; i++) {
if (waitpid(child_pid, NULL, WNOHANG) != 0) { exited = 1; break; }
if (waitpid(child_pid, NULL, WNOHANG) != 0) {
exited = 1;
break;
}
sleep_ms(SHUTDOWN_POLL_MS);
}
if (!exited) {
@@ -427,18 +461,39 @@ close_prof_test(void **state)
}
stbbr_stop();
struct timespec now;
clock_gettime(CLOCK_MONOTONIC, &now);
double elapsed = (now.tv_sec - test_start_ts.tv_sec)
+ (now.tv_nsec - test_start_ts.tv_nsec) / 1e9;
if (elapsed < min_elapsed) {
min_elapsed = elapsed;
min_test_name = current_test_name;
}
printf("[PROF_TEST] test '%s' took %.3f s (min: %.3fs '%s')\n",
current_test_name, elapsed, min_elapsed, min_test_name);
double slow_thr = prof_test_slow_threshold > 0 ? prof_test_slow_threshold : SLOW_TEST_THRESHOLD_S;
double fast_thr = prof_test_fast_threshold > 0 ? prof_test_fast_threshold : FAST_TEST_THRESHOLD_S;
if (elapsed >= slow_thr) {
print_message("[PROF_TEST] WARNING: slow test '%s' \u2014 %.1fs (threshold %.1fs)\n",
current_test_name, elapsed, slow_thr);
} else if (elapsed < fast_thr) {
print_message("[PROF_TEST] WARNING: suspiciously fast test '%s' \u2014 %.3fs (min %.3fs)\n",
current_test_name, elapsed, fast_thr);
}
return 0;
}
void
prof_input(const char *input)
prof_input(const char* input)
{
GString *inp_str = g_string_new(input);
GString* inp_str = g_string_new(input);
g_string_append(inp_str, "\r");
ssize_t _wn = write(fd, inp_str->str, inp_str->len);
(void)_wn;
g_string_free(inp_str, TRUE);
/* Small delay to let profanity process input */
sleep_ms(INPUT_DELAY_MS);
}
@@ -448,24 +503,24 @@ prof_input(const char *input)
* Returns 1 if found, 0 if timeout.
*/
int
prof_output_exact(const char *text)
prof_output_exact(const char* text)
{
time_t start = time(NULL);
while (time(NULL) - start < expect_timeout) {
/* Read any available output */
while (_read_output(READ_TIMEOUT_MS) > 0) {
/* Keep reading while data available */
}
/* Check if text is in buffer */
if (strstr(output_buffer, text) != NULL) {
return 1;
}
sleep_ms(OUTPUT_POLL_MS);
}
return 0;
}
@@ -474,34 +529,34 @@ prof_output_exact(const char *text)
* Returns 1 if found, 0 if timeout.
*/
int
prof_output_regex(const char *pattern)
prof_output_regex(const char* pattern)
{
regex_t regex;
int ret;
ret = regcomp(&regex, pattern, REG_EXTENDED | REG_NOSUB);
if (ret != 0) {
return 0;
}
time_t start = time(NULL);
while (time(NULL) - start < expect_timeout) {
/* Read any available output */
while (_read_output(READ_TIMEOUT_MS) > 0) {
/* Keep reading while data available */
}
/* Check if pattern matches */
ret = regexec(&regex, output_buffer, 0, NULL, 0);
if (ret == 0) {
regfree(&regex);
return 1;
}
sleep_ms(OUTPUT_POLL_MS);
}
/* Timeout reached - log diagnostic info */
fprintf(stderr, "Timeout waiting for regex '%s' after %d seconds. Last output:\n", pattern, expect_timeout);
size_t len = strlen(output_buffer);
@@ -511,23 +566,21 @@ prof_output_regex(const char *pattern)
fprintf(stderr, "%s", output_buffer);
}
fprintf(stderr, "\n");
regfree(&regex);
return 0;
}
void
prof_connect_with_roster(const char *roster)
prof_connect_with_roster(const char* roster)
{
GString *roster_str = g_string_new(
GString* roster_str = g_string_new(
"<iq type='result' to='stabber@localhost/profanity'>"
"<query xmlns='jabber:iq:roster' ver='362'>"
);
"<query xmlns='jabber:iq:roster' ver='362'>");
g_string_append(roster_str, roster);
g_string_append(roster_str,
"</query>"
"</iq>"
);
"</query>"
"</iq>");
stbbr_for_query("jabber:iq:roster", roster_str->str);
g_string_free(roster_str, TRUE);
@@ -537,7 +590,7 @@ prof_connect_with_roster(const char *roster)
char connect_cmd[128];
snprintf(connect_cmd, sizeof(connect_cmd), "/connect stabber@localhost server 127.0.0.1 port %d tls disable auth legacy", stub_port);
prof_input(connect_cmd);
assert_true(prof_output_regex("password:"));
prof_input("password");
@@ -545,15 +598,14 @@ prof_connect_with_roster(const char *roster)
assert_true(prof_output_regex("Connecting as stabber@localhost"));
assert_true(prof_output_regex("logged in successfully"));
assert_true(prof_output_regex(".+online.+ \\(priority 0\\)\\."));
expect_timeout = EXPECT_TIMEOUT_CONNECT;
// Wait for presence stanza to be sent (content-based, not ID-based)
// Match the actual attribute order from stanza_attach_caps
assert_true(stbbr_received(
"<presence id=\"*\">"
"<c xmlns=\"http://jabber.org/protocol/caps\" hash=\"sha-1\" node=\"http://profanity-im.github.io\" ver=\"*\"/>"
"</presence>"
));
"<c xmlns=\"http://jabber.org/protocol/caps\" hash=\"sha-1\" node=\"http://profanity-im.github.io\" ver=\"*\"/>"
"</presence>"));
}
void
@@ -573,6 +625,5 @@ prof_connect(void)
{
prof_connect_with_roster(
"<item jid='buddy1@localhost' subscription='both' name='Buddy1'/>"
"<item jid='buddy2@localhost' subscription='both' name='Buddy2'/>"
);
"<item jid='buddy2@localhost' subscription='both' name='Buddy2'/>");
}