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

This commit is contained in:
Ryan Fleury
2024-05-14 08:10:02 -07:00
parent 6c200a59cd
commit 3085482e34
7 changed files with 104 additions and 61 deletions
+10 -7
View File
@@ -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);
}
+22 -4
View File
@@ -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
+37 -28
View File
@@ -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;
+3 -3
View File
@@ -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);
+1 -1
View File
@@ -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);
}
+23 -16
View File
@@ -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("<unknown>");
@@ -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:
+8 -2
View File
@@ -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);