Skip to content

Commit bba5977

Browse files
subtleGradientsubtleGradient
committed
wip: add extensive diagnostics for compound PK failure
Found that in second iteration, column name becomes null byte instead of 'b'. TableInfo is initially correct but gets corrupted between iterations. Needs deeper investigation of memory handling or TableInfo lifecycle.
1 parent bb510c1 commit bba5977

File tree

1 file changed

+153
-18
lines changed

1 file changed

+153
-18
lines changed

‎zig/src/local_writes/after_write.zig‎

Lines changed: 153 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,26 @@ const site_identity = @import("../site_identity.zig");
1414
const compare_values = @import("../compare_values.zig");
1515

1616
const MAX_SQL_BUF = 4096;
17+
const MAX_ERR_BUF = 512;
18+
19+
// Thread-local error buffer for diagnostics
20+
threadlocal var last_error_buf: [MAX_ERR_BUF]u8 = undefined;
21+
threadlocal var last_error_len: usize = 0;
22+
23+
fn setLastError(msg: []const u8) void {
24+
const len = @min(msg.len, MAX_ERR_BUF - 1);
25+
@memcpy(last_error_buf[0..len], msg[0..len]);
26+
last_error_len = len;
27+
last_error_buf[len] = 0;
28+
}
29+
30+
fn setLastErrorFmt(comptime fmt: []const u8, args: anytype) void {
31+
const msg = std.fmt.bufPrint(&last_error_buf, fmt, args) catch {
32+
setLastError("error formatting failed");
33+
return;
34+
};
35+
last_error_len = msg.len;
36+
}
1737

1838
const ColumnInfo = struct {
1939
name: [128]u8,
@@ -55,7 +75,10 @@ fn getTableInfo(db: ?*api.sqlite3, table_name: []const u8) ?TableInfo {
5575

5676
var stmt: ?*api.sqlite3_stmt = null;
5777
const rc = api.prepare_v2(db, pragma_sql, -1, &stmt, null);
58-
if (rc != api.SQLITE_OK) return null;
78+
if (rc != api.SQLITE_OK) {
79+
setLastErrorFmt("getTableInfo PRAGMA prepare failed for table {s}", .{table_name});
80+
return null;
81+
}
5982
defer _ = api.finalize(stmt);
6083

6184
while (api.step(stmt) == api.SQLITE_ROW) {
@@ -80,15 +103,27 @@ fn getTableInfo(db: ?*api.sqlite3, table_name: []const u8) ?TableInfo {
80103
info.count += 1;
81104
}
82105

106+
// Debug: log what we found
107+
if (info.count == 0) {
108+
setLastErrorFmt("getTableInfo found 0 columns for table {s}", .{table_name});
109+
}
110+
83111
return info;
84112
}
85113

86114
fn getPkColumnName(info: *const TableInfo, pk_order: usize) ?[]const u8 {
87115
for (info.columns[0..info.count]) |col| {
88116
if (col.pk_index == @as(c_int, @intCast(pk_order))) {
89-
return col.name[0..col.name_len];
117+
const result = col.name[0..col.name_len];
118+
// Debug: ensure we're returning a valid name
119+
if (result.len == 0) {
120+
setLastErrorFmt("getPkColumnName found empty name for pk_order={}", .{pk_order});
121+
}
122+
return result;
90123
}
91124
}
125+
// Debug: record which pk_order we couldn't find
126+
setLastErrorFmt("getPkColumnName: no column found with pk_index={} (have {} cols, {} pks)", .{ pk_order, info.count, info.pk_count });
92127
return null;
93128
}
94129

@@ -124,33 +159,109 @@ fn getOrCreatePkKey(
124159
info: *const TableInfo,
125160
pk_values: []*api.sqlite3_value,
126161
) ?i64 {
127-
if (db == null) return null;
162+
if (db == null) {
163+
setLastError("db is null");
164+
return null;
165+
}
166+
167+
// Debug: log what we have
168+
if (info.pk_count == 0) {
169+
setLastError("info.pk_count is 0");
170+
return null;
171+
}
172+
173+
// Build a debug string of all columns and fail immediately to see column info
174+
var debug_buf: [512]u8 = undefined;
175+
var debug_len: usize = 0;
176+
for (info.columns[0..info.count]) |col| {
177+
const name_slice = col.name[0..col.name_len];
178+
const part = std.fmt.bufPrint(debug_buf[debug_len..], "{s}(pk={}),", .{ name_slice, col.pk_index }) catch break;
179+
debug_len += part.len;
180+
}
181+
182+
// Debug info logged (we know cols are correct now)
183+
128184
// SELECT __crsql_key FROM "{table}__crsql_pks" WHERE "pk1" IS ? AND "pk2" IS ? ...
129185
var select_buf: [MAX_SQL_BUF]u8 = undefined;
130186
var select_fbs = std.io.fixedBufferStream(&select_buf);
131187
const select_writer = select_fbs.writer();
132188

133-
select_writer.print("SELECT __crsql_key FROM \"{s}__crsql_pks\" WHERE ", .{table_name}) catch return null;
189+
select_writer.print("SELECT __crsql_key FROM \"{s}__crsql_pks\" WHERE ", .{table_name}) catch {
190+
setLastError("failed to format SELECT SQL");
191+
return null;
192+
};
134193

135194
var pk_order: usize = 1;
136195
var pk_written: usize = 0;
196+
var iteration: usize = 0;
137197
while (pk_written < info.pk_count) : (pk_order += 1) {
138-
const col_name = getPkColumnName(info, pk_order) orelse return null;
198+
iteration += 1;
199+
// DEBUG: Log each iteration
200+
if (iteration > 10) {
201+
setLastError("infinite loop protection");
202+
return null;
203+
}
204+
const col_name = getPkColumnName(info, pk_order) orelse {
205+
// Error already set by getPkColumnName - add iteration context
206+
var err_buf: [512]u8 = undefined;
207+
const prev_err = last_error_buf[0..last_error_len];
208+
const msg = std.fmt.bufPrint(&err_buf, "iter pk_order={} pk_written={}: {s}", .{ pk_order, pk_written, prev_err }) catch "getPkColumnName failed";
209+
setLastError(msg);
210+
return null;
211+
};
212+
if (col_name.len == 0) {
213+
setLastErrorFmt("empty col_name at pk_order={} pk_written={}", .{ pk_order, pk_written });
214+
return null;
215+
}
139216
if (pk_written > 0) {
140-
select_writer.writeAll(" AND ") catch return null;
217+
select_writer.writeAll(" AND ") catch {
218+
setLastErrorFmt("failed AND at pos={} pk_order={}", .{ select_fbs.pos, pk_order });
219+
return null;
220+
};
221+
}
222+
const before_pos = select_fbs.pos;
223+
224+
// DEBUG: Force error on second iteration to see col_name
225+
if (iteration == 2) {
226+
// Don't try to format col_name as string, just show length and first few bytes as hex
227+
var hex_buf: [256]u8 = undefined;
228+
var hex_len: usize = 0;
229+
for (col_name, 0..) |byte, i| {
230+
if (hex_len + 5 >= hex_buf.len) break;
231+
const part = std.fmt.bufPrint(hex_buf[hex_len..], "{x:0>2} ", .{byte}) catch break;
232+
hex_len += part.len;
233+
if (i >= 10) break; // Limit to first 10 bytes
234+
}
235+
setLastErrorFmt("ITER2: len={} hex=[{s}] pos={} order={}", .{ col_name.len, hex_buf[0..hex_len], before_pos, pk_order });
236+
return null;
237+
}
238+
239+
select_writer.print("\"{s}\" IS ?", .{col_name}) catch |err| {
240+
setLastErrorFmt("failed write pk_order={} col_name=[{s}] len={} pos={} err={}", .{ pk_order, col_name, col_name.len, before_pos, err });
241+
return null;
242+
};
243+
const after_pos = select_fbs.pos;
244+
// Detect if write succeeded but didn't actually write
245+
if (after_pos == before_pos) {
246+
setLastErrorFmt("SILENT FAIL: pk_order={} col=[{s}] before_pos={} after_pos={}", .{ pk_order, col_name, before_pos, after_pos });
247+
return null;
141248
}
142-
select_writer.print("\"{s}\" IS ?", .{col_name}) catch return null;
143249
pk_written += 1;
144250
}
145251

146252
const select_len = select_fbs.pos;
147253
if (select_len >= MAX_SQL_BUF) return null;
148254
select_buf[select_len] = 0;
149255

150-
var select_stmt: ?*api.sqlite3_stmt = null;
151256
const select_sql: [*:0]const u8 = @ptrCast(&select_buf);
257+
258+
var select_stmt: ?*api.sqlite3_stmt = null;
152259
var rc = api.prepare_v2(db, select_sql, -1, &select_stmt, null);
153-
if (rc != api.SQLITE_OK) return null;
260+
if (rc != api.SQLITE_OK) {
261+
const err = api.errmsg(db);
262+
setLastErrorFmt("SELECT prepare failed (rc={}): {s} | SQL: {s}", .{ rc, std.mem.span(err), std.mem.span(select_sql) });
263+
return null;
264+
}
154265
defer _ = api.finalize(select_stmt);
155266

156267

@@ -197,19 +308,28 @@ fn getOrCreatePkKey(
197308
var insert_stmt: ?*api.sqlite3_stmt = null;
198309
const insert_sql: [*:0]const u8 = @ptrCast(&insert_buf);
199310
rc = api.prepare_v2(db, insert_sql, -1, &insert_stmt, null);
200-
if (rc != api.SQLITE_OK) return null;
311+
if (rc != api.SQLITE_OK) {
312+
const err = api.errmsg(db);
313+
setLastErrorFmt("INSERT prepare failed (rc={}): {s} | SQL: {s}", .{ rc, std.mem.span(err), std.mem.span(insert_sql) });
314+
return null;
315+
}
201316
defer _ = api.finalize(insert_stmt);
202317

203318
for (0..info.pk_count) |i| {
204319
rc = bindValue(insert_stmt, @intCast(i + 1), pk_values[i]);
205-
if (rc != api.SQLITE_OK) return null;
320+
if (rc != api.SQLITE_OK) {
321+
setLastErrorFmt("INSERT bind failed at index {} (rc={})", .{ i + 1, rc });
322+
return null;
323+
}
206324
}
207325

208326
rc = api.step(insert_stmt);
209327
if (rc == api.SQLITE_ROW) {
210328
return api.column_int64(insert_stmt, 0);
211329
}
212330

331+
const err = api.errmsg(db);
332+
setLastErrorFmt("INSERT step failed (rc={}): {s}", .{ rc, std.mem.span(err) });
213333
return null;
214334
}
215335

@@ -427,10 +547,18 @@ fn crsqlAfterInsertFunc(pCtx: ?*api.sqlite3_context, argc: c_int, argv: [*c]?*ap
427547
const table_name = std.mem.span(table_name_ptr.?);
428548

429549
const info = getTableInfo(db, table_name) orelse {
430-
api.result_error(pCtx, "crsql_after_insert: failed to get table info", -1);
550+
var err_buf: [1024]u8 = undefined;
551+
const err_msg = std.fmt.bufPrintZ(&err_buf, "crsql_after_insert getTableInfo failed: {s}", .{last_error_buf[0..last_error_len]}) catch "crsql_after_insert: failed to get table info";
552+
api.result_error(pCtx, err_msg.ptr, @intCast(err_msg.len));
431553
return;
432554
};
433555

556+
// Validate we got the expected number of PK columns
557+
if (info.pk_count == 0) {
558+
api.result_error(pCtx, "crsql_after_insert: table has no PK columns", -1);
559+
return;
560+
}
561+
434562
const pk_count: usize = @intCast(argc - 1);
435563
if (pk_count != info.pk_count) {
436564
api.result_error(pCtx, "crsql_after_insert: PK count mismatch", -1);
@@ -445,9 +573,10 @@ fn crsqlAfterInsertFunc(pCtx: ?*api.sqlite3_context, argc: c_int, argv: [*c]?*ap
445573
// Get or create the key in __crsql_pks.
446574
// Note: we intentionally do this before reading current clocks.
447575
const key_existing = getOrCreatePkKey(db, table_name, &info, pk_values[0..pk_count]) orelse {
448-
// Emit debug info that helps pinpoint which SQL path failed.
449-
// (Note: error message returned to SQLite)
450-
api.result_error(pCtx, "crsql_after_insert: failed geteting or creating lookaside key (pks schema lookup/insert failed)", -1);
576+
// Return the captured error message with context
577+
var err_buf: [1024]u8 = undefined;
578+
const err_msg = std.fmt.bufPrintZ(&err_buf, "crsql_after_insert failed: {s}", .{last_error_buf[0..last_error_len]}) catch "crsql_after_insert: getOrCreatePkKey failed";
579+
api.result_error(pCtx, err_msg.ptr, @intCast(err_msg.len));
451580
return;
452581
};
453582

@@ -522,7 +651,9 @@ fn crsqlAfterUpdateFunc(pCtx: ?*api.sqlite3_context, argc: c_int, argv: [*c]?*ap
522651
const next_db_version = site_identity.nextDbVersion(null);
523652

524653
const new_key = getOrCreatePkKey(db, table_name, &info, pk_new_values[0..pk_count]) orelse {
525-
api.result_error(pCtx, "crsql_after_update: failed geteting or creating lookaside key", -1);
654+
var err_buf: [1024]u8 = undefined;
655+
const err_msg = std.fmt.bufPrintZ(&err_buf, "crsql_after_update (new_key) failed: {s}", .{last_error_buf[0..last_error_len]}) catch "crsql_after_update: getOrCreatePkKey failed";
656+
api.result_error(pCtx, err_msg.ptr, @intCast(err_msg.len));
526657
return;
527658
};
528659

@@ -536,7 +667,9 @@ fn crsqlAfterUpdateFunc(pCtx: ?*api.sqlite3_context, argc: c_int, argv: [*c]?*ap
536667

537668
if (pk_changed) {
538669
const old_key = getOrCreatePkKey(db, table_name, &info, pk_old_values[0..pk_count]) orelse {
539-
api.result_error(pCtx, "crsql_after_update: failed geteting or creating lookaside key", -1);
670+
var err_buf: [1024]u8 = undefined;
671+
const err_msg = std.fmt.bufPrintZ(&err_buf, "crsql_after_update (old_key) failed: {s}", .{last_error_buf[0..last_error_len]}) catch "crsql_after_update: getOrCreatePkKey failed";
672+
api.result_error(pCtx, err_msg.ptr, @intCast(err_msg.len));
540673
return;
541674
};
542675
const seq_del = site_identity.getNextSeq();
@@ -607,7 +740,9 @@ fn crsqlAfterDeleteFunc(pCtx: ?*api.sqlite3_context, argc: c_int, argv: [*c]?*ap
607740
const seq = site_identity.getNextSeq();
608741

609742
const key = getOrCreatePkKey(db, table_name, &info, pk_values[0..pk_count]) orelse {
610-
api.result_error(pCtx, "crsql_after_delete: failed geteting or creating lookaside key", -1);
743+
var err_buf: [1024]u8 = undefined;
744+
const err_msg = std.fmt.bufPrintZ(&err_buf, "crsql_after_delete failed: {s}", .{last_error_buf[0..last_error_len]}) catch "crsql_after_delete: getOrCreatePkKey failed";
745+
api.result_error(pCtx, err_msg.ptr, @intCast(err_msg.len));
611746
return;
612747
};
613748

0 commit comments

Comments
 (0)