diff --git a/docs/logging.md b/docs/logging.md index 1bb6b871..3d4e8ec9 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -87,7 +87,7 @@ exclude = ["console"] **json** — structured JSONL (one JSON object per line). Used for file sinks and machine consumption. ```json -{"actor_id":"a3f12...","timestamp":1702656000.5,"channel":"console","event":"server started","source":{"file":"main.ce","line":5,"column":3,"function":"init"}} +{"actor_id":"a3f12...","timestamp":1702656000.5,"channel":"console","event":"server started","source":{"file":"main.ce","line":5,"col":3,"fn":"init"}} ``` ## Log Records @@ -103,14 +103,44 @@ Every log call produces a record: source: { file: "main.ce", line: 5, - column: 3, - function: "init" + col: 3, + fn: "init" } } ``` File sinks write one JSON-encoded record per line. Console sinks format the record according to their format setting. +## Stack Traces + +Set `stack = true` at the top level of `.cell/log.toml` to capture a full call stack with every log record. + +```toml +stack = true + +[sink.terminal] +type = "console" +format = "pretty" +channels = ["console", "error"] +``` + +With pretty format, the stack is printed indented below each message: + +``` +[a3f12] [error] server.ce:42 connection failed + at handle_request (server.ce:42:3) + at process (router.ce:18:5) + at main (main.ce:5:1) +``` + +With JSON format, a `stack` array is added to the record: + +```json +{"actor_id":"a3f12...","channel":"error","event":"connection failed","source":{"file":"server.ce","line":42,"col":3,"fn":"handle_request"},"stack":[{"fn":"handle_request","file":"server.ce","line":42,"col":3},{"fn":"process","file":"router.ce","line":18,"col":5},{"fn":"main","file":"main.ce","line":5,"col":1}]} +``` + +When `stack` is not set or `false`, no stack is captured and the `stack` field is omitted from records. Capturing stacks adds overhead — enable it for debugging, not production. + ## CLI The `pit log` command manages sinks and reads log files. See [CLI — pit log](/docs/cli/#pit-log) for the full reference. diff --git a/internal/engine.cm b/internal/engine.cm index 22123d58..2ef5b826 100644 --- a/internal/engine.cm +++ b/internal/engine.cm @@ -324,6 +324,7 @@ var log_config = null var channel_sinks = {} var wildcard_sinks = [] var warned_channels = {} +var log_stack_enabled = false function log(name, args) { var msg = args[0] @@ -476,15 +477,27 @@ function load_log_config() { } } build_sink_routing() + log_stack_enabled = log_config.stack == true } function pretty_format(rec) { var aid = text(rec.actor_id, 0, 5) var src = "" + var ev = null + var out = null + var i = 0 + var fr = null if (rec.source && rec.source.file) src = rec.source.file + ":" + text(rec.source.line) - var ev = is_text(rec.event) ? rec.event : json.encode(rec.event, false) - return `[${aid}] [${rec.channel}] ${src} ${ev}\n` + ev = is_text(rec.event) ? rec.event : json.encode(rec.event, false) + out = `[${aid}] [${rec.channel}] ${src} ${ev}\n` + if (rec.stack && length(rec.stack) > 0) { + for (i = 0; i < length(rec.stack); i = i + 1) { + fr = rec.stack[i] + out = out + ` at ${fr.fn} (${fr.file}:${text(fr.line)}:${text(fr.col)})\n` + } + } + return out } function bare_format(rec) { @@ -523,6 +536,9 @@ load_log_config() log = function(name, args) { var sinks = channel_sinks[name] var event = args[0] + var caller = null + var stack = null + var rec = null if (!sinks && length(wildcard_sinks) == 0) { if (!warned_channels[name]) { @@ -532,14 +548,16 @@ log = function(name, args) { return } - var caller = caller_info(2) - var rec = { + caller = caller_info(2) + if (log_stack_enabled) stack = os.stack(1) + rec = { actor_id: _cell.id, timestamp: time.number(), channel: name, event: event, source: caller } + if (stack) rec.stack = stack if (sinks) arrfor(sinks, function(sink) { dispatch_to_sink(sink, rec) }) arrfor(wildcard_sinks, function(sink) { dispatch_to_sink(sink, rec) }) diff --git a/internal/os.c b/internal/os.c index 5fe6442e..4fa6d549 100644 --- a/internal/os.c +++ b/internal/os.c @@ -674,6 +674,27 @@ static JSValue js_os_embedded_module(JSContext *js, JSValue self, int argc, JSVa return js_new_blob_stoned_copy(js, (void *)entry->data, entry->size); } +static JSValue js_os_stack(JSContext *js, JSValue self, int argc, JSValue *argv) { + (void)self; + int skip = 0; + if (argc > 0) JS_ToInt32(js, &skip, argv[0]); + + JSValue full = JS_GetStack(js); + if (skip <= 0) return full; + + int64_t n = 0; + JS_GetLength(js, full, &n); + if (skip >= (int)n) return JS_NewArray(js); + + JS_FRAME(js); + JS_ROOT(arr, JS_NewArray(js)); + for (int i = skip; i < (int)n; i++) { + JSValue item = JS_GetPropertyNumber(js, full, i); + JS_SetPropertyNumber(js, arr.val, i - skip, item); + } + JS_RETURN(arr.val); +} + static const JSCFunctionListEntry js_os_funcs[] = { MIST_FUNC_DEF(os, platform, 0), MIST_FUNC_DEF(os, arch, 0), @@ -701,6 +722,7 @@ static const JSCFunctionListEntry js_os_funcs[] = { MIST_FUNC_DEF(os, random, 0), MIST_FUNC_DEF(os, getenv, 1), MIST_FUNC_DEF(os, qbe, 1), + MIST_FUNC_DEF(os, stack, 1), }; JSValue js_core_os_use(JSContext *js) { diff --git a/source/quickjs-internal.h b/source/quickjs-internal.h index 332583d2..0f2a051e 100644 --- a/source/quickjs-internal.h +++ b/source/quickjs-internal.h @@ -1427,7 +1427,7 @@ static JSValue js_cell_number_remainder (JSContext *ctx, JSValue this_val, int a static JSValue js_cell_object (JSContext *ctx, JSValue this_val, int argc, JSValue *argv); static JSValue js_cell_text_format (JSContext *ctx, JSValue this_val, int argc, JSValue *argv); static JSValue js_print (JSContext *ctx, JSValue this_val, int argc, JSValue *argv); -cJSON *JS_GetStack(JSContext *ctx); +JSValue JS_GetStack(JSContext *ctx); JSValue JS_ThrowOutOfMemory (JSContext *ctx); @@ -1595,7 +1595,7 @@ uint64_t get_text_hash (JSText *text); void pack_utf32_to_words (const uint32_t *utf32, uint32_t len, uint64_t *packed); int text_equal (JSText *a, const uint64_t *packed_b, uint32_t len_b); -void print_backtrace (JSContext *ctx, const char *filename, int line_num, int col_num); +void print_backtrace (JSContext *ctx, JSValue stack, const char *filename, int line_num, int col_num); JSValue JS_ThrowError2 (JSContext *ctx, JSErrorEnum error_num, const char *fmt, va_list ap, BOOL add_backtrace); JSValue gc_copy_value (JSContext *ctx, JSValue v, uint8_t *from_base, uint8_t *from_end, uint8_t *to_base, uint8_t **to_free, uint8_t *to_end); PPretext *ppretext_init (int capacity); diff --git a/source/quickjs.h b/source/quickjs.h index d1979738..1c02f2eb 100644 --- a/source/quickjs.h +++ b/source/quickjs.h @@ -1047,10 +1047,10 @@ void JS_DumpMachBin(JSContext *ctx, const uint8_t *data, size_t size, JSValue en /* Compile mcode JSON IR to MachCode binary. */ MachCode *mach_compile_mcode(struct cJSON *mcode_json); -/* Get stack trace as cJSON array of frame objects. - Returns NULL if no register VM frame is active. - Caller must call cJSON_Delete() on the result. */ -struct cJSON *JS_GetStack (JSContext *ctx); +/* Get stack trace as JS array of {fn, file, line, col} objects. + Returns an empty array if no register VM frame is active. + Does NOT clear reg_current_frame — caller is responsible if needed. */ +JSValue JS_GetStack (JSContext *ctx); #undef js_unlikely #undef inline diff --git a/source/runtime.c b/source/runtime.c index 883ad498..f99557e8 100644 --- a/source/runtime.c +++ b/source/runtime.c @@ -3088,32 +3088,31 @@ static const char *const native_error_name[JS_NATIVE_ERROR_COUNT] = { "AggregateError", }; -/* Print backtrace to stderr. Walks the register VM frame chain via - ctx->reg_current_frame, then falls back to the C stack frame chain. */ -void print_backtrace (JSContext *ctx, const char *filename, int line_num, int col_num) { +/* Print backtrace to stderr from a JS array of {fn, file, line, col} objects. */ +void print_backtrace (JSContext *ctx, JSValue stack, const char *filename, int line_num, int col_num) { if (filename) { fprintf (stderr, " at %s", filename); if (line_num != -1) fprintf (stderr, ":%d:%d", line_num, col_num); fputc ('\n', stderr); } - /* Walk register VM frame chain (mach / mcode) */ - if (!JS_IsNull (ctx->reg_current_frame)) { - cJSON *stack = JS_GetStack (ctx); - if (stack) { - int n = cJSON_GetArraySize (stack); - for (int i = 0; i < n; i++) { - cJSON *fr = cJSON_GetArrayItem (stack, i); - const char *fn = cJSON_GetStringValue (cJSON_GetObjectItem (fr, "function")); - const char *file = cJSON_GetStringValue (cJSON_GetObjectItem (fr, "file")); - int ln = (int)cJSON_GetNumberValue (cJSON_GetObjectItem (fr, "line")); - int cn = (int)cJSON_GetNumberValue (cJSON_GetObjectItem (fr, "column")); - fprintf (stderr, " at %s (%s:%d:%d)\n", - fn ? fn : "", file ? file : "", ln, cn); - } - cJSON_Delete (stack); - } - return; + int64_t n = 0; + JS_GetLength(ctx, stack, &n); + for (int i = 0; i < (int)n; i++) { + JSValue fr = JS_GetPropertyNumber(ctx, stack, i); + JSValue fn_val = JS_GetPropertyStr(ctx, fr, "fn"); + JSValue file_val = JS_GetPropertyStr(ctx, fr, "file"); + const char *fn = JS_ToCString(ctx, fn_val); + const char *file = JS_ToCString(ctx, file_val); + int32_t ln = 0, cn = 0; + JSValue line_v = JS_GetPropertyStr(ctx, fr, "line"); + JSValue col_v = JS_GetPropertyStr(ctx, fr, "col"); + JS_ToInt32(ctx, &ln, line_v); + JS_ToInt32(ctx, &cn, col_v); + fprintf (stderr, " at %s (%s:%d:%d)\n", + fn ? fn : "", file ? file : "", ln, cn); + if (fn) JS_FreeCString(ctx, fn); + if (file) JS_FreeCString(ctx, file); } } @@ -3124,7 +3123,9 @@ JSValue JS_ThrowError2 (JSContext *ctx, JSErrorEnum error_num, const char *fmt, vsnprintf (buf, sizeof (buf), fmt, ap); fprintf (stderr, "%s: %s\n", native_error_name[error_num], buf); if (add_backtrace) { - print_backtrace (ctx, NULL, 0, 0); + JSValue stack = JS_GetStack(ctx); + ctx->reg_current_frame = JS_NULL; + print_backtrace (ctx, stack, NULL, 0, 0); } return JS_Throw (ctx, JS_TRUE); } @@ -8127,70 +8128,44 @@ static JSValue js_print (JSContext *ctx, JSValue this_val, int argc, JSValue *ar } static JSValue js_stacktrace (JSContext *ctx, JSValue this_val, int argc, JSValue *argv) { - cJSON *stack = JS_GetStack(ctx); - if (stack) { - int n = cJSON_GetArraySize(stack); - for (int i = 0; i < n; i++) { - cJSON *fr = cJSON_GetArrayItem(stack, i); - const char *fn = cJSON_GetStringValue(cJSON_GetObjectItemCaseSensitive(fr, "function")); - const char *file = cJSON_GetStringValue(cJSON_GetObjectItemCaseSensitive(fr, "file")); - int line = (int)cJSON_GetNumberValue(cJSON_GetObjectItemCaseSensitive(fr, "line")); - int col = (int)cJSON_GetNumberValue(cJSON_GetObjectItemCaseSensitive(fr, "column")); - printf(" at %s (%s:%d:%d)\n", fn ? fn : "", file ? file : "", line, col); - } - cJSON_Delete(stack); + (void)this_val; (void)argc; (void)argv; + JSValue stack = JS_GetStack(ctx); + int64_t n = 0; + JS_GetLength(ctx, stack, &n); + for (int i = 0; i < (int)n; i++) { + JSValue fr = JS_GetPropertyNumber(ctx, stack, i); + JSValue fn_val = JS_GetPropertyStr(ctx, fr, "fn"); + JSValue file_val = JS_GetPropertyStr(ctx, fr, "file"); + const char *fn = JS_ToCString(ctx, fn_val); + const char *file = JS_ToCString(ctx, file_val); + int32_t line = 0, col = 0; + JS_ToInt32(ctx, &line, JS_GetPropertyStr(ctx, fr, "line")); + JS_ToInt32(ctx, &col, JS_GetPropertyStr(ctx, fr, "col")); + printf(" at %s (%s:%d:%d)\n", fn ? fn : "", file ? file : "", line, col); + if (fn) JS_FreeCString(ctx, fn); + if (file) JS_FreeCString(ctx, file); } return JS_NULL; } static JSValue js_caller_info (JSContext *ctx, JSValue this_val, int argc, JSValue *argv) { + (void)this_val; int depth = 0; if (argc > 0) JS_ToInt32(ctx, &depth, argv[0]); - /* Save frame pointer — JS_GetStack clears it */ - JSValue saved_frame = ctx->reg_current_frame; - uint32_t saved_pc = ctx->current_register_pc; + JSValue stack = JS_GetStack(ctx); - cJSON *stack = JS_GetStack(ctx); + int64_t n = 0; + JS_GetLength(ctx, stack, &n); - /* Restore so other callers still see the frame */ - ctx->reg_current_frame = saved_frame; - ctx->current_register_pc = saved_pc; + /* depth 0 = immediate caller of caller_info, which is frame index 1 + (frame 0 is caller_info itself) */ + int idx = depth + 1; + if (idx >= (int)n) idx = (int)n - 1; + if (idx < 0) idx = 0; - const char *fn_str = ""; - const char *file_str = ""; - int line = 0, col = 0; - - if (stack) { - int n = cJSON_GetArraySize(stack); - /* depth 0 = immediate caller of caller_info, which is frame index 1 - (frame 0 is caller_info itself) */ - int idx = depth + 1; - if (idx >= n) idx = n - 1; - if (idx < 0) idx = 0; - - cJSON *fr = cJSON_GetArrayItem(stack, idx); - const char *v; - v = cJSON_GetStringValue(cJSON_GetObjectItemCaseSensitive(fr, "function")); - if (v) fn_str = v; - v = cJSON_GetStringValue(cJSON_GetObjectItemCaseSensitive(fr, "file")); - if (v) file_str = v; - line = (int)cJSON_GetNumberValue(cJSON_GetObjectItemCaseSensitive(fr, "line")); - col = (int)cJSON_GetNumberValue(cJSON_GetObjectItemCaseSensitive(fr, "column")); - } - - JSGCRef obj; - JS_PushGCRef(ctx, &obj); - obj.val = JS_NewObject(ctx); - JS_SetPropertyStr(ctx, obj.val, "file", JS_NewString(ctx, file_str)); - JS_SetPropertyStr(ctx, obj.val, "line", JS_NewInt32(ctx, line)); - JS_SetPropertyStr(ctx, obj.val, "column", JS_NewInt32(ctx, col)); - JS_SetPropertyStr(ctx, obj.val, "function", JS_NewString(ctx, fn_str)); - JSValue result = obj.val; - JS_PopGCRef(ctx, &obj); - - if (stack) cJSON_Delete(stack); - return result; + if (n > 0) return JS_GetPropertyNumber(ctx, stack, idx); + return JS_NULL; } /* ---------------------------------------------------------------------------- @@ -12771,49 +12746,61 @@ JSValue js_core_math_cycles_use (JSContext *ctx) { JS_PopGCRef (ctx, &obj_ref); return result; } -/* Public API: get stack trace as cJSON array */ -cJSON *JS_GetStack(JSContext *ctx) { - if (JS_IsNull(ctx->reg_current_frame)) return NULL; +/* Public API: get stack trace as JS array of {fn, file, line, col} objects. + Does NOT clear reg_current_frame — caller is responsible if needed. + Two-phase approach for GC safety: Phase 1 collects raw C data on the C stack + (pointers into stable JSCodeRegister fields), Phase 2 allocates JS objects. */ +JSValue JS_GetStack(JSContext *ctx) { + if (JS_IsNull(ctx->reg_current_frame)) return JS_NewArray(ctx); + + /* Phase 1: collect raw frame data (no JS allocations) */ + struct { const char *fn; const char *file; uint16_t line, col; } frames[64]; + int count = 0; JSFrameRegister *frame = (JSFrameRegister *)JS_VALUE_GET_PTR(ctx->reg_current_frame); uint32_t cur_pc = ctx->current_register_pc; - - cJSON *arr = cJSON_CreateArray(); int is_first = 1; - while (frame) { + while (frame && count < 64) { if (!JS_IsFunction(frame->function)) break; JSFunction *fn = JS_VALUE_GET_FUNCTION(frame->function); - const char *func_name = NULL; - const char *file = NULL; - uint16_t line = 0, col = 0; - uint32_t pc = is_first ? cur_pc : 0; - if (fn->kind == JS_FUNC_KIND_REGISTER && fn->u.reg.code) { JSCodeRegister *code = fn->u.reg.code; - file = code->filename_cstr; - func_name = code->name_cstr; - if (!is_first) { - pc = (uint32_t)(JS_VALUE_GET_INT(frame->address) >> 16); - } + uint32_t pc = is_first ? cur_pc : (uint32_t)(JS_VALUE_GET_INT(frame->address) >> 16); + frames[count].fn = code->name_cstr; + frames[count].file = code->filename_cstr; + frames[count].line = 0; + frames[count].col = 0; if (code->line_table && pc < code->instr_count) { - line = code->line_table[pc].line; - col = code->line_table[pc].col; + frames[count].line = code->line_table[pc].line; + frames[count].col = code->line_table[pc].col; } + count++; } - cJSON *entry = cJSON_CreateObject(); - cJSON_AddStringToObject(entry, "function", func_name ? func_name : ""); - cJSON_AddStringToObject(entry, "file", file ? file : ""); - cJSON_AddNumberToObject(entry, "line", line); - cJSON_AddNumberToObject(entry, "column", col); - cJSON_AddItemToArray(arr, entry); - if (JS_IsNull(frame->caller)) break; frame = (JSFrameRegister *)JS_VALUE_GET_PTR(frame->caller); is_first = 0; } - ctx->reg_current_frame = JS_NULL; - return arr; + /* Phase 2: create JS objects (frame data is on C stack, safe across GC) */ + JSGCRef arr_ref; + JS_PushGCRef(ctx, &arr_ref); + arr_ref.val = JS_NewArray(ctx); + for (int i = 0; i < count; i++) { + JSGCRef item_ref; + JS_PushGCRef(ctx, &item_ref); + item_ref.val = JS_NewObject(ctx); + JS_SetPropertyStr(ctx, item_ref.val, "fn", + JS_NewString(ctx, frames[i].fn ? frames[i].fn : "")); + JS_SetPropertyStr(ctx, item_ref.val, "file", + JS_NewString(ctx, frames[i].file ? frames[i].file : "")); + JS_SetPropertyStr(ctx, item_ref.val, "line", JS_NewInt32(ctx, frames[i].line)); + JS_SetPropertyStr(ctx, item_ref.val, "col", JS_NewInt32(ctx, frames[i].col)); + JS_SetPropertyNumber(ctx, arr_ref.val, i, item_ref.val); + JS_PopGCRef(ctx, &item_ref); + } + JSValue result = arr_ref.val; + JS_PopGCRef(ctx, &arr_ref); + return result; }