From 3085482e34afa4c6f9d84e79c8177399d3a03532 Mon Sep 17 00:00:00 2001 From: Ryan Fleury Date: Tue, 14 May 2024 08:10:02 -0700 Subject: [PATCH] expand base layer logging mechanism with bucketing info; make one bucket for passive log collection, another for user-facing errors; always consume user errors at the top-level and display; use user-error mechanism to communicate bad 32-bit app launches from demon --- src/base/base_log.c | 17 ++++---- src/base/base_log.h | 26 ++++++++++-- src/ctrl/ctrl_core.c | 65 +++++++++++++++++------------- src/ctrl/ctrl_core.h | 6 +-- src/demon/win32/demon_core_win32.c | 2 +- src/df/core/df_core.c | 39 ++++++++++-------- src/raddbg/raddbg.c | 10 ++++- 7 files changed, 104 insertions(+), 61 deletions(-) diff --git a/src/base/base_log.c b/src/base/base_log.c index af7b25ec..b04a041e 100644 --- a/src/base/base_log.c +++ b/src/base/base_log.c @@ -37,17 +37,17 @@ log_select(Log *log) //~ rjf: Log Building/Clearing internal void -log_msg(String8 string) +log_msg(LogMsgKind kind, String8 string) { if(log_active != 0 && log_active->top_scope != 0) { String8 string_copy = push_str8_copy(log_active->arena, string); - str8_list_push(log_active->arena, &log_active->top_scope->strings, string_copy); + str8_list_push(log_active->arena, &log_active->top_scope->strings[kind], string_copy); } } internal void -log_msgf(char *fmt, ...) +log_msgf(LogMsgKind kind, char *fmt, ...) { if(log_active != 0) { @@ -55,7 +55,7 @@ log_msgf(char *fmt, ...) va_list args; va_start(args, fmt); String8 string = push_str8fv(scratch.arena, fmt, args); - log_msg(string); + log_msg(kind, string); va_end(args); scratch_end(scratch); } @@ -76,10 +76,10 @@ log_scope_begin(void) } } -internal String8 +internal LogScopeResult log_scope_end(Arena *arena) { - String8 result = {0}; + LogScopeResult result = {0}; if(log_active != 0) { LogScope *scope = log_active->top_scope; @@ -88,7 +88,10 @@ log_scope_end(Arena *arena) SLLStackPop(log_active->top_scope); if(arena != 0) { - result = str8_list_join(arena, &scope->strings, 0); + for(EachEnumVal(LogMsgKind, kind)) + { + result.strings[kind] = str8_list_join(arena, &scope->strings[kind], 0); + } } arena_pop_to(log_active->arena, scope->pos); } diff --git a/src/base/base_log.h b/src/base/base_log.h index ff4ac6e4..b5054b40 100644 --- a/src/base/base_log.h +++ b/src/base/base_log.h @@ -7,12 +7,26 @@ //////////////////////////////// //~ rjf: Log Types +typedef enum LogMsgKind +{ + LogMsgKind_Info, + LogMsgKind_UserError, + LogMsgKind_COUNT +} +LogMsgKind; + typedef struct LogScope LogScope; struct LogScope { LogScope *next; U64 pos; - String8List strings; + String8List strings[LogMsgKind_COUNT]; +}; + +typedef struct LogScopeResult LogScopeResult; +struct LogScopeResult +{ + String8 strings[LogMsgKind_COUNT]; }; typedef struct Log Log; @@ -32,13 +46,17 @@ internal void log_select(Log *log); //////////////////////////////// //~ rjf: Log Building -internal void log_msg(String8 string); -internal void log_msgf(char *fmt, ...); +internal void log_msg(LogMsgKind kind, String8 string); +internal void log_msgf(LogMsgKind kind, char *fmt, ...); +#define log_info(s) log_msg(LogMsgKind_Info, (s)) +#define log_infof(fmt, ...) log_msgf(LogMsgKind_Info, (fmt), __VA_ARGS__) +#define log_user_error(s) log_msg(LogMsgKind_UserError, (s)) +#define log_user_errorf(fmt, ...) log_msgf(LogMsgKind_UserError, (fmt), __VA_ARGS__) //////////////////////////////// //~ rjf: Log Scopes internal void log_scope_begin(void); -internal String8 log_scope_end(Arena *arena); +internal LogScopeResult log_scope_end(Arena *arena); #endif // BASE_LOG_H diff --git a/src/ctrl/ctrl_core.c b/src/ctrl/ctrl_core.c index 541c7f0d..625b6485 100644 --- a/src/ctrl/ctrl_core.c +++ b/src/ctrl/ctrl_core.c @@ -1796,8 +1796,17 @@ ctrl_thread__entry_point(void *p) } } - String8 log = log_scope_end(scratch.arena); - ctrl_thread__flush_log(log); + //- rjf: gather & output logs + LogScopeResult log = log_scope_end(scratch.arena); + ctrl_thread__flush_info_log(log.strings[LogMsgKind_Info]); + if(log.strings[LogMsgKind_UserError].size != 0) + { + CTRL_EventList evts = {0}; + CTRL_Event *evt = ctrl_event_list_push(scratch.arena, &evts); + evt->kind = CTRL_EventKind_Error; + evt->string = log.strings[LogMsgKind_UserError]; + ctrl_c2u_push_events(&evts); + } } scratch_end(scratch); @@ -1944,16 +1953,16 @@ ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg, if(next_event_node != 0) CTRL_CtrlThreadLogScope { DMN_Event *ev = &next_event_node->v; - log_msgf("--- event ---\n"); - log_msgf("kind: %S\n", dmn_event_kind_string_table[ev->kind]); - log_msgf("exception_kind: %S\n", dmn_exception_kind_string_table[ev->exception_kind]); - log_msgf("process: [%I64u]\n", ev->process.u64[0]); - log_msgf("thread: [%I64u]\n", ev->thread.u64[0]); - log_msgf("module: [%I64u]\n", ev->module.u64[0]); - log_msgf("arch: %S\n", string_from_architecture(ev->arch)); - log_msgf("address: 0x%I64x\n", ev->address); - log_msgf("string: \"%S\"\n", ev->string); - log_msgf("ip_vaddr: 0x%I64x\n", ev->instruction_pointer); + log_infof("--- event ---\n"); + log_infof("kind: %S\n", dmn_event_kind_string_table[ev->kind]); + log_infof("exception_kind: %S\n", dmn_exception_kind_string_table[ev->exception_kind]); + log_infof("process: [%I64u]\n", ev->process.u64[0]); + log_infof("thread: [%I64u]\n", ev->thread.u64[0]); + log_infof("module: [%I64u]\n", ev->module.u64[0]); + log_infof("arch: %S\n", string_from_architecture(ev->arch)); + log_infof("address: 0x%I64x\n", ev->address); + log_infof("string: \"%S\"\n", ev->string); + log_infof("ip_vaddr: 0x%I64x\n", ev->instruction_pointer); } // rjf: determine if we should filter @@ -2106,9 +2115,9 @@ ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg, // rjf: run for new events ProfScope("run for new events") { - CTRL_CtrlThreadLogScope log_msgf("{dmn_ctrl_run ..."); + CTRL_CtrlThreadLogScope log_infof("{dmn_ctrl_run ..."); DMN_EventList events = dmn_ctrl_run(scratch.arena, ctrl_ctx, run_ctrls); - CTRL_CtrlThreadLogScope log_msgf("}\n"); + CTRL_CtrlThreadLogScope log_infof("}\n"); for(DMN_EventNode *src_n = events.first; src_n != 0; src_n = src_n->next) { DMN_EventNode *dst_n = ctrl_state->free_dmn_event_node; @@ -2298,17 +2307,17 @@ ctrl_eval_memory_read(void *u, void *out, U64 addr, U64 size) //- rjf: log flusher internal void -ctrl_thread__flush_log(String8 string) +ctrl_thread__flush_info_log(String8 string) { os_append_data_to_file_path(ctrl_state->ctrl_thread_log_path, string); } internal void -ctrl_thread__end_and_flush_log(void) +ctrl_thread__end_and_flush_info_log(void) { Temp scratch = scratch_begin(0, 0); - String8 log = log_scope_end(scratch.arena); - ctrl_thread__flush_log(log); + LogScopeResult log = log_scope_end(scratch.arena); + ctrl_thread__flush_info_log(log.strings[LogMsgKind_Info]); scratch_end(scratch); } @@ -2754,25 +2763,25 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) case DMN_EventKind_Trap: { hard_stop = 1; - log_msgf(">>> stepping >>> hard stop\n"); + log_infof(">>> stepping >>> hard stop\n"); }break; case DMN_EventKind_Exception: case DMN_EventKind_Breakpoint: { use_stepping_logic = 1; - log_msgf(">>> stepping >>> exception or breakpoint - begin stepping logic\n"); + log_infof(">>> stepping >>> exception or breakpoint - begin stepping logic\n"); }break; case DMN_EventKind_CreateProcess: { DMN_TrapChunkList new_traps = {0}; ctrl_thread__append_resolved_process_user_bp_traps(scratch.arena, CTRL_MachineID_Local, event->process, &msg->user_bps, &new_traps); - log_msgf(">>> stepping >>> create process -> resolve new BPs\n"); + log_infof(">>> stepping >>> create process -> resolve new BPs\n"); for(DMN_TrapChunkNode *n = new_traps.first; n != 0; n = n->next) { for(U64 idx = 0; idx < n->count; idx += 1) { DMN_Trap *trap = &n->v[idx]; - log_msgf(" trap: {process:%I64d, vaddr:0x%I64x}\n", trap->process.u64[0], trap->vaddr); + log_infof(" trap: {process:%I64d, vaddr:0x%I64x}\n", trap->process.u64[0], trap->vaddr); } } dmn_trap_chunk_list_concat_shallow_copy(scratch.arena, &joined_traps, &new_traps); @@ -2784,7 +2793,7 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) ctrl_thread__append_resolved_module_user_bp_traps(scratch.arena, CTRL_MachineID_Local, event->process, event->module, &msg->user_bps, &new_traps); dmn_trap_chunk_list_concat_shallow_copy(scratch.arena, &joined_traps, &new_traps); dmn_trap_chunk_list_concat_shallow_copy(scratch.arena, &user_traps, &new_traps); - log_msgf(">>> stepping >>> load module -> resolve new BPs\n"); + log_infof(">>> stepping >>> load module -> resolve new BPs\n"); }break; } @@ -3158,13 +3167,13 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) { hit_user_bp = 0; hit_conditional_bp_but_filtered = 1; - log_msgf(">>> stepping >>> conditional breakpoint hit, but condition eval'd to 0, and so filtered\n"); + log_infof(">>> stepping >>> conditional breakpoint hit, but condition eval'd to 0, and so filtered\n"); } else { hit_user_bp = 1; hit_conditional_bp_but_filtered = 0; - log_msgf(">>> stepping >>> conditional breakpoint hit\n"); + log_infof(">>> stepping >>> conditional breakpoint hit\n"); break; } } @@ -3185,8 +3194,8 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) } } - log_msgf(">>> stepping >>> stepping logic - BP event -> hit_user_bp: %i\n", hit_user_bp); - log_msgf(">>> stepping >>> stepping logic - BP event -> hit_entry: %i\n", hit_entry); + log_infof(">>> stepping >>> stepping logic - BP event -> hit_user_bp: %i\n", hit_user_bp); + log_infof(">>> stepping >>> stepping logic - BP event -> hit_entry: %i\n", hit_entry); temp_end(temp); } } @@ -3420,7 +3429,7 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) { stage_stop_cause = CTRL_EventCause_Finished; } - log_msgf(">>> stepping >>> stage stop cause -> %i\n", stage_stop_cause); + log_infof(">>> stepping >>> stage stop cause -> %i\n", stage_stop_cause); if(stage_stop_cause != CTRL_EventCause_Null) { stop_event = event; diff --git a/src/ctrl/ctrl_core.h b/src/ctrl/ctrl_core.h index 2c078221..0666e237 100644 --- a/src/ctrl/ctrl_core.h +++ b/src/ctrl/ctrl_core.h @@ -556,7 +556,7 @@ read_only global CTRL_Entity ctrl_entity_nil = //////////////////////////////// //~ rjf: Logging Markup -#define CTRL_CtrlThreadLogScope DeferLoop(log_scope_begin(), ctrl_thread__end_and_flush_log()) +#define CTRL_CtrlThreadLogScope DeferLoop(log_scope_begin(), ctrl_thread__end_and_flush_info_log()) //////////////////////////////// //~ rjf: Basic Type Functions @@ -716,8 +716,8 @@ internal DMN_Event *ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ internal B32 ctrl_eval_memory_read(void *u, void *out, U64 addr, U64 size); //- rjf: log flusher -internal void ctrl_thread__flush_log(String8 string); -internal void ctrl_thread__end_and_flush_log(void); +internal void ctrl_thread__flush_info_log(String8 string); +internal void ctrl_thread__end_and_flush_info_log(void); //- rjf: msg kind implementations internal void ctrl_thread__launch(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg); diff --git a/src/demon/win32/demon_core_win32.c b/src/demon/win32/demon_core_win32.c index 28abb910..5e765be6 100644 --- a/src/demon/win32/demon_core_win32.c +++ b/src/demon/win32/demon_core_win32.c @@ -1205,7 +1205,7 @@ dmn_ctrl_launch(DMN_CtrlCtx *ctx, OS_LaunchOptions *options) IsWow64Process(process_info.hProcess, &is_wow); if(is_wow) { - MessageBox(0, "Sorry, The RAD Debugger only debugs 64-bit applications currently.", "Process error", MB_OK|MB_ICONSTOP); + log_user_errorf("Only 64-bit applications can be debugged currently."); DebugActiveProcessStop(process_info.dwProcessId); TerminateProcess(process_info.hProcess,0xffffffff); } diff --git a/src/df/core/df_core.c b/src/df/core/df_core.c index 29055c8d..3e1c986e 100644 --- a/src/df/core/df_core.c +++ b/src/df/core/df_core.c @@ -1799,7 +1799,7 @@ df_entity_alloc(DF_StateDeltaHistory *hist, DF_Entity *parent, DF_EntityKind kin df_entity_notify_mutation(entity); // rjf: log - log_msgf("new entity: %S $%I64d\n", df_g_entity_kind_display_string_table[kind], entity->id); + log_infof("new entity: %S $%I64d\n", df_g_entity_kind_display_string_table[kind], entity->id); return entity; } @@ -1844,7 +1844,7 @@ df_entity_release(DF_StateDeltaHistory *hist, DF_Entity *entity) t->e = child; SLLQueuePush(first_task, last_task, t); } - log_msgf("end entity: %S $%I64d\n", df_g_entity_kind_display_string_table[task->e->kind], task->e->id); + log_infof("end entity: %S $%I64d\n", df_g_entity_kind_display_string_table[task->e->kind], task->e->id); df_state_delta_history_push_struct_delta(hist, &task->e->first); df_state_delta_history_push_struct_delta(hist, &task->e->last); df_state_delta_history_push_struct_delta(hist, &task->e->next); @@ -6457,8 +6457,8 @@ df_push_cmd__root(DF_CmdParams *params, DF_CmdSpec *spec) { Temp scratch = scratch_begin(0, 0); DF_Entity *entity = df_entity_from_handle(params->entity); - log_msgf("debug frontend command pushed: \"%S\"\n", spec->info.string); -#define HandleParamPrint(mem_name) if(!df_handle_match(df_handle_zero(), params->mem_name)) { log_msgf("| %s: [0x%I64x, 0x%I64x]\n", #mem_name, params->mem_name.u64[0], params->mem_name.u64[1]); } + log_infof("debug frontend command pushed: \"%S\"\n", spec->info.string); +#define HandleParamPrint(mem_name) if(!df_handle_match(df_handle_zero(), params->mem_name)) { log_infof("| %s: [0x%I64x, 0x%I64x]\n", #mem_name, params->mem_name.u64[0], params->mem_name.u64[1]); } HandleParamPrint(window); HandleParamPrint(panel); HandleParamPrint(dest_panel); @@ -6467,7 +6467,7 @@ df_push_cmd__root(DF_CmdParams *params, DF_CmdSpec *spec) if(!df_entity_is_nil(entity)) { String8 entity_name = df_display_string_from_entity(scratch.arena, entity); - log_msgf("| entity: \"%S\"\n", entity_name); + log_infof("| entity: \"%S\"\n", entity_name); } U64 idx = 0; for(DF_HandleNode *n = params->entity_list.first; n != 0; n = n->next, idx += 1) @@ -6476,20 +6476,20 @@ df_push_cmd__root(DF_CmdParams *params, DF_CmdSpec *spec) if(!df_entity_is_nil(entity)) { String8 entity_name = df_display_string_from_entity(scratch.arena, entity); - log_msgf("| entity_list[%I64u]: \"%S\"\n", idx, entity_name); + log_infof("| entity_list[%I64u]: \"%S\"\n", idx, entity_name); } } if(!df_cmd_spec_is_nil(params->cmd_spec)) { - log_msgf("| cmd_spec: \"%S\"\n", params->cmd_spec->info.string); + log_infof("| cmd_spec: \"%S\"\n", params->cmd_spec->info.string); } - if(params->string.size != 0) { log_msgf("| string: \"%S\"\n", params->string); } - if(params->file_path.size != 0) { log_msgf("| file_path: \"%S\"\n", params->file_path); } - if(params->text_point.line != 0){ log_msgf("| text_point: [line:%I64d, col:%I64d]\n", params->text_point.line, params->text_point.column); } - if(params->vaddr != 0) { log_msgf("| vaddr: 0x%I64x\n", params->vaddr); } - if(params->voff != 0) { log_msgf("| voff: 0x%I64x\n", params->voff); } - if(params->index != 0) { log_msgf("| index: 0x%I64x\n", params->index); } - if(params->id != 0) { log_msgf("| id: 0x%I64x\n", params->id); } + if(params->string.size != 0) { log_infof("| string: \"%S\"\n", params->string); } + if(params->file_path.size != 0) { log_infof("| file_path: \"%S\"\n", params->file_path); } + if(params->text_point.line != 0){ log_infof("| text_point: [line:%I64d, col:%I64d]\n", params->text_point.line, params->text_point.column); } + if(params->vaddr != 0) { log_infof("| vaddr: 0x%I64x\n", params->vaddr); } + if(params->voff != 0) { log_infof("| voff: 0x%I64x\n", params->voff); } + if(params->index != 0) { log_infof("| index: 0x%I64x\n", params->index); } + if(params->id != 0) { log_infof("| id: 0x%I64x\n", params->id); } if(params->os_event != 0) { String8 kind_string = str8_lit(""); @@ -6506,10 +6506,10 @@ df_push_cmd__root(DF_CmdParams *params, DF_CmdSpec *spec) case OS_EventKind_FileDrop: {kind_string = str8_lit("filedrop");}break; case OS_EventKind_Wakeup: {kind_string = str8_lit("wakeup");}break; } - log_msgf("| os_event->kind: %S\n", kind_string); + log_infof("| os_event->kind: %S\n", kind_string); } #undef HandleParamPrint - log_msgf("--------------------------------\n"); + log_infof("--------------------------------\n"); scratch_end(scratch); } df_cmd_list_push(df_state->root_cmd_arena, &df_state->root_cmds, params, spec); @@ -6703,6 +6703,13 @@ df_core_begin_frame(Arena *arena, DF_CmdList *cmds, F32 dt) { default:{}break; + //- rjf: errors + + case CTRL_EventKind_Error: + { + log_user_error(event->string); + }break; + //- rjf: starts/stops case CTRL_EventKind_Started: diff --git a/src/raddbg/raddbg.c b/src/raddbg/raddbg.c index 465fa1b0..e68ef468 100644 --- a/src/raddbg/raddbg.c +++ b/src/raddbg/raddbg.c @@ -378,8 +378,14 @@ update_and_render(OS_Handle repaint_window_handle, void *user_data) //- rjf: end logging // { - String8 log = log_scope_end(scratch.arena); - os_append_data_to_file_path(main_thread_log_path, log); + LogScopeResult log = log_scope_end(scratch.arena); + os_append_data_to_file_path(main_thread_log_path, log.strings[LogMsgKind_Info]); + if(log.strings[LogMsgKind_UserError].size != 0) + { + DF_CmdParams p = df_cmd_params_from_gfx(); + p.string = log.strings[LogMsgKind_UserError]; + df_push_cmd__root(&p, df_cmd_spec_from_core_cmd_kind(DF_CoreCmdKind_Error)); + } } scratch_end(scratch);