diff --git a/src/base/base_log.c b/src/base/base_log.c index b04a041e..a5a917ac 100644 --- a/src/base/base_log.c +++ b/src/base/base_log.c @@ -90,7 +90,10 @@ log_scope_end(Arena *arena) { for(EachEnumVal(LogMsgKind, kind)) { - result.strings[kind] = str8_list_join(arena, &scope->strings[kind], 0); + Temp scratch = scratch_begin(&arena, 1); + String8 result_unindented = str8_list_join(scratch.arena, &scope->strings[kind], 0); + result.strings[kind] = indented_from_string(arena, result_unindented); + scratch_end(scratch); } } arena_pop_to(log_active->arena, scope->pos); diff --git a/src/base/base_log.h b/src/base/base_log.h index b5054b40..52a297d8 100644 --- a/src/base/base_log.h +++ b/src/base/base_log.h @@ -53,6 +53,9 @@ internal void log_msgf(LogMsgKind kind, char *fmt, ...); #define log_user_error(s) log_msg(LogMsgKind_UserError, (s)) #define log_user_errorf(fmt, ...) log_msgf(LogMsgKind_UserError, (fmt), __VA_ARGS__) +#define LogInfoNamedBlock(s) DeferLoop(log_infof("%S:\n{\n", (s)), log_infof("}\n")) +#define LogInfoNamedBlockF(fmt, ...) DeferLoop((log_infof(fmt, __VA_ARGS__), log_infof(":\n{\n")), log_infof("}\n")) + //////////////////////////////// //~ rjf: Log Scopes diff --git a/src/base/base_markup.c b/src/base/base_markup.c index e0ba1b2b..033fb49a 100644 --- a/src/base/base_markup.c +++ b/src/base/base_markup.c @@ -2,20 +2,20 @@ // Licensed under the MIT license (https://opensource.org/license/mit/) internal void -thread_name(String8 string) +set_thread_name(String8 string) { ProfThreadName("%.*s", str8_varg(string)); os_set_thread_name(string); } internal void -thread_namef(char *fmt, ...) +set_thread_namef(char *fmt, ...) { Temp scratch = scratch_begin(0, 0); va_list args; va_start(args, fmt); String8 string = push_str8fv(scratch.arena, fmt, args); - thread_name(string); + set_thread_name(string); va_end(args); scratch_end(scratch); } diff --git a/src/base/base_markup.h b/src/base/base_markup.h index 6696ff29..0f255efc 100644 --- a/src/base/base_markup.h +++ b/src/base/base_markup.h @@ -4,9 +4,9 @@ #ifndef BASE_MARKUP_H #define BASE_MARKUP_H -internal void thread_name(String8 string); -internal void thread_namef(char *fmt, ...); -#define ThreadNameF(...) (ProfThreadName(__VA_ARGS__), thread_namef(__VA_ARGS__)) -#define ThreadName(str) (ProfThreadName("%.*s", str8_varg(str)), thread_name(str)) +internal void set_thread_name(String8 string); +internal void set_thread_namef(char *fmt, ...); +#define ThreadNameF(...) (set_thread_namef(__VA_ARGS__)) +#define ThreadName(str) (set_thread_name(str)) #endif // BASE_MARKUP_H diff --git a/src/base/base_strings.c b/src/base/base_strings.c index 5a4b91fa..355cc62e 100644 --- a/src/base/base_strings.c +++ b/src/base/base_strings.c @@ -1566,7 +1566,45 @@ string_from_elapsed_time(Arena *arena, DateTime dt){ } //////////////////////////////// -//~ rjf: Textual String Wrapping +//~ rjf: Basic Text Indentation + +internal String8 +indented_from_string(Arena *arena, String8 string) +{ + Temp scratch = scratch_begin(&arena, 1); + read_only local_persist U8 indentation_bytes[] = " "; + String8List indented_strings = {0}; + S64 depth = 0; + S64 next_depth = 0; + U64 line_begin_off = 0; + for(U64 off = 0; off <= string.size; off += 1) + { + U8 byte = offmachine_id, dmn_handle_zero()); CTRL_Entity *process = ctrl_entity_alloc(store, machine, CTRL_EntityKind_Process, event->arch, event->machine_id, event->entity, (U64)event->entity_id); + process->vaddr_range = event->vaddr_rng; }break; case CTRL_EventKind_EndProc: { @@ -2887,7 +2888,7 @@ ctrl_thread__entry_point(void *p) { CTRL_Msg *msg = &msg_n->v; { - log_infof("[user -> ctrl %S message]\n", ctrl_string_from_msg_kind(msg->kind)); + log_infof("user2ctrl_msg:{kind:\"%S\"}\n", ctrl_string_from_msg_kind(msg->kind)); } MemoryCopyArray(ctrl_state->exception_code_filters, msg->exception_code_filters); switch(msg->kind) @@ -3401,16 +3402,18 @@ ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg, if(next_event_node != 0) { DMN_Event *ev = &next_event_node->v; - 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); + LogInfoNamedBlockF("dmn_event") + { + 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 @@ -3562,14 +3565,26 @@ ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg, // rjf: run for new events ProfScope("run for new events") { - log_infof("dmn_ctrl_run:\n{\n"); - log_infof(" single_step_thread: [0x%I64x]\n", run_ctrls->single_step_thread); - log_infof(" ignore_previous_exception: %i\n", !!run_ctrls->ignore_previous_exception); - log_infof(" run_entities_are_unfrozen: %i\n", !!run_ctrls->run_entities_are_unfrozen); - log_infof(" run_entities_are_processes: %i\n", !!run_ctrls->run_entities_are_processes); - log_infof(" run_entity_count: %I64u\n", run_ctrls->run_entity_count); - log_infof(" trap_count: %I64u\n", run_ctrls->traps.trap_count); - log_infof("}\n"); + LogInfoNamedBlockF("dmn_ctrl_run") + { + log_infof("single_step_thread: [0x%I64x]\n", run_ctrls->single_step_thread); + log_infof("ignore_previous_exception: %i\n", !!run_ctrls->ignore_previous_exception); + log_infof("run_entities_are_unfrozen: %i\n", !!run_ctrls->run_entities_are_unfrozen); + log_infof("run_entities_are_processes: %i\n", !!run_ctrls->run_entities_are_processes); + log_infof("run_entity_count: %I64u\n", run_ctrls->run_entity_count); + LogInfoNamedBlockF("run_entities") for(U64 idx = 0; idx < run_ctrls->run_entity_count; idx += 1) + { + log_infof("[0x%I64x]\n", run_ctrls->run_entities[idx]); + } + log_infof("trap_count: %I64u\n", run_ctrls->traps.trap_count); + LogInfoNamedBlockF("traps") for(DMN_TrapChunkNode *n = run_ctrls->traps.first; n != 0; n = n->next) + { + for(U64 idx = 0; idx < n->count; idx += 1) + { + log_infof("{process:[0x%I64x], vaddr:0x%I64x, id:0x%I64x}\n", n->v[idx].process.u64[0], n->v[idx].vaddr, n->v[idx].id); + } + } + } DMN_EventList events = dmn_ctrl_run(scratch.arena, ctrl_ctx, run_ctrls); for(DMN_EventNode *src_n = events.first; src_n != 0; src_n = src_n->next) { @@ -3606,7 +3621,7 @@ ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg, void *regs_block = push_array(scratch.arena, U8, regs_block_size_from_architecture(arch)); dmn_thread_read_reg_block(spoof->thread, regs_block); U64 spoof_thread_rip = regs_rip_from_arch_block(arch, regs_block); - if(spoof_thread_rip == spoof->new_ip_value) + if(spoof_thread_rip == spoof->new_ip_value+1) { regs_arch_block_write_rip(arch, regs_block, spoof_old_ip_value); ctrl_thread_write_reg_block(CTRL_MachineID_Local, spoof->thread, regs_block); @@ -3620,6 +3635,12 @@ ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg, default:{}break; case DMN_EventKind_CreateProcess: { + U64 spoof_space_size = KB(4); + U64 spoof_space_vaddr = dmn_process_memory_reserve(event->process, 0, spoof_space_size); + U64 spoof_space_code = 0xcccccccc; + dmn_process_memory_commit(event->process, spoof_space_vaddr, spoof_space_size); + dmn_process_memory_protect(event->process, spoof_space_vaddr, spoof_space_size, OS_AccessFlag_Read|OS_AccessFlag_Write|OS_AccessFlag_Execute); + dmn_process_write(event->process, r1u64(spoof_space_vaddr, spoof_space_vaddr+sizeof(spoof_space_code)), &spoof_space_code); CTRL_Event *out_evt = ctrl_event_list_push(scratch.arena, &evts); out_evt->kind = CTRL_EventKind_NewProc; out_evt->msg_id = msg->msg_id; @@ -3627,6 +3648,7 @@ ctrl_thread__next_dmn_event(Arena *arena, DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg, out_evt->entity = event->process; out_evt->arch = event->arch; out_evt->entity_id = event->code; + out_evt->vaddr_rng = r1u64(spoof_space_vaddr, spoof_space_vaddr+spoof_space_size); ctrl_state->process_counter += 1; }break; case DMN_EventKind_CreateThread: @@ -3992,7 +4014,9 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) CTRL_EventCause stop_cause = CTRL_EventCause_Null; DMN_Handle target_thread = msg->entity; DMN_Handle target_process = msg->parent; - U64 spoof_ip_vaddr = 911; + CTRL_Entity *target_process_entity = ctrl_entity_from_machine_id_handle(ctrl_state->ctrl_thread_entity_store, msg->machine_id, target_process); + U64 spoof_ip_vaddr = target_process_entity->vaddr_range.min; + log_infof("ctrl_thread__run:\n{\n"); ////////////////////////////// //- rjf: gather all initial breakpoints @@ -4027,6 +4051,7 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) // causes e.g. entrance into a function via a call instruction. // U64 sp_check_value = dmn_rsp_from_thread(target_thread); + log_infof("sp_check_value := 0x%I64x\n", sp_check_value); ////////////////////////////// //- rjf: single step "stuck threads" @@ -4116,6 +4141,7 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) U64 thread_post_rip = thread_pre_rip; for(B32 done = 0; !done;) { + log_infof("single_step_stuck_thread([0x%I64x])\n", thread.u64[0]); DMN_RunCtrls run_ctrls = {0}; run_ctrls.run_entities_are_unfrozen = 1; run_ctrls.run_entities = &thread; @@ -4228,8 +4254,9 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) ////////////////////////// //- rjf: get next run-related event // - log_infof(">>> stepping >>> getting next event\n"); + log_infof("get_next_event:\n{\n"); DMN_Event *event = ctrl_thread__next_dmn_event(scratch.arena, ctrl_ctx, msg, &run_ctrls, run_spoof); + log_infof("}\n\n"); ////////////////////////// //- rjf: determine event handling @@ -4244,30 +4271,44 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) case DMN_EventKind_Error: case DMN_EventKind_Halt: case DMN_EventKind_SingleStep: - case DMN_EventKind_Trap: { hard_stop = 1; - log_infof(">>> stepping >>> hard stop\n"); + log_infof("step_rule: unexpected -> hard_stop\n"); + }break; + case DMN_EventKind_Trap: + { + if(event->instruction_pointer == spoof_ip_vaddr) + { + use_stepping_logic = 1; + log_infof("step_rule: spoof trap -> stepping_logic\n"); + } + else + { + hard_stop = 1; + log_infof("step_rule: unexpected trap -> hard_stop\n"); + } }break; case DMN_EventKind_Exception: case DMN_EventKind_Breakpoint: { use_stepping_logic = 1; - log_infof(">>> stepping >>> exception or breakpoint - begin stepping logic\n"); + log_infof("step_rule: exception/breakpoint -> 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_infof(">>> stepping >>> create process -> resolve new BPs\n"); + log_infof("step_rule: create_process -> resolve traps\n"); + log_infof("new_traps:\n{\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_infof(" trap: {process:%I64d, vaddr:0x%I64x}\n", trap->process.u64[0], trap->vaddr); + log_infof("{process:[0x%I64x], vaddr:0x%I64x}\n", trap->process.u64[0], trap->vaddr); } } + log_infof("}\n\n"); 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); }break; @@ -4275,9 +4316,19 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) { DMN_TrapChunkList new_traps = {0}; ctrl_thread__append_resolved_module_user_bp_traps(scratch.arena, CTRL_MachineID_Local, event->process, event->module, &msg->user_bps, &new_traps); + log_infof("step_rule: load_module -> resolve traps\n"); + log_infof("new_traps:\n{\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_infof("{process:[0x%I64x], vaddr:0x%I64x}\n", trap->process.u64[0], trap->vaddr); + } + } + log_infof("}\n\n"); 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_infof(">>> stepping >>> load module -> resolve new BPs\n"); }break; } @@ -4512,35 +4563,36 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) //{ ////////////////////////// - //- rjf: handle if hitting a spoof or baked in trap + //- rjf: handle if hitting an exception + // + B32 exception_stop = 0; + if(!hard_stop && use_stepping_logic && event->kind == DMN_EventKind_Exception) + { + exception_stop = 1; + use_stepping_logic = 0; + } + + ////////////////////////// + //- rjf: handle if hitting a spoof // B32 hit_spoof = 0; - B32 exception_stop = 0; - if(!hard_stop && use_stepping_logic) + if(!hard_stop && use_stepping_logic && event->kind == DMN_EventKind_Trap) { - if(event->kind == DMN_EventKind_Exception) + if(spoof_mode && + dmn_handle_match(target_process, event->process) && + dmn_handle_match(target_thread, event->thread) && + spoof.new_ip_value == event->instruction_pointer) { - // rjf: spoof check - if(spoof_mode && - dmn_handle_match(target_process, event->process) && - dmn_handle_match(target_thread, event->thread) && - spoof.new_ip_value == event->instruction_pointer) - { - hit_spoof = 1; - } - - // rjf: other exceptions cause stop - if(!hit_spoof) - { - exception_stop = 1; - use_stepping_logic = 0; - } + hit_spoof = 1; + log_infof("hit_spoof\n"); } } //- rjf: handle spoof hit if(hit_spoof) { + log_infof("exit_spoof_mode\n"); + // rjf: clear spoof mode spoof_mode = 0; MemoryZeroStruct(&spoof); @@ -4657,13 +4709,13 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) { hit_user_bp = 0; hit_conditional_bp_but_filtered = 1; - log_infof(">>> stepping >>> conditional breakpoint hit, but condition eval'd to 0, and so filtered\n"); + log_infof("conditional_breakpoint_hit: 'condition eval'd to 0, and so filtered'\n"); } else { hit_user_bp = 1; hit_conditional_bp_but_filtered = 0; - log_infof(">>> stepping >>> conditional breakpoint hit\n"); + log_infof("conditional_breakpoint_hit: 'conditional eval'd to nonzero, hit'\n"); break; } } @@ -4687,15 +4739,15 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) } } - 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); + log_infof("user_breakpoint_hit: %i\n", hit_user_bp); + log_infof("entry_point_hit: %i\n", hit_entry); temp_end(temp); } //- rjf: hit conditional user bp but filtered -> single step B32 cond_bp_single_step_stop = 0; CTRL_EventCause cond_bp_single_step_stop_cause = CTRL_EventCause_Null; - if(hit_conditional_bp_but_filtered) + if(hit_conditional_bp_but_filtered) LogInfoNamedBlockF("conditional_bp_hit_single_step") { DMN_Handle thread = event->thread; U64 thread_pre_rip = dmn_rip_from_thread(thread); @@ -4784,9 +4836,8 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) CTRL_EventCause single_step_stop_cause = CTRL_EventCause_Null; if(!hard_stop && use_trap_net_logic) { - if(hit_trap_flags & CTRL_TrapFlag_SingleStepAfterHit) + if(hit_trap_flags & CTRL_TrapFlag_SingleStepAfterHit) LogInfoNamedBlockF("trap_net__single_step_after_hit") { - log_infof(">>> stepping >>> trap net logic: single step after hit\n"); U64 thread_pre_rip = dmn_rip_from_thread(target_thread); U64 thread_post_rip = thread_pre_rip; for(B32 single_step_done = 0; single_step_done == 0;) @@ -4829,10 +4880,9 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) B32 begin_spoof_mode = 0; if(!hard_stop && use_trap_net_logic) { - if(hit_trap_flags & CTRL_TrapFlag_BeginSpoofMode) + if(hit_trap_flags & CTRL_TrapFlag_BeginSpoofMode) LogInfoNamedBlockF("trap_net__begin_spoof_mode") { // rjf: setup spoof mode - log_infof(">>> stepping >>> trap net logic: begin spoof mode\n"); begin_spoof_mode = 1; U64 spoof_sp = dmn_rsp_from_thread(target_thread); spoof_mode = 1; @@ -4840,6 +4890,7 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) spoof.thread = target_thread; spoof.vaddr = spoof_sp; spoof.new_ip_value = spoof_ip_vaddr; + log_infof("spoof:{process:[0x%I64x], thread:[0x%I64x], vaddr:0x%I64x, new_ip_value:0x%I64x}\n", spoof.process.u64[0], spoof.thread.u64[0], spoof.vaddr, spoof.new_ip_value); } } @@ -4849,11 +4900,11 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) { if(hit_trap_flags & CTRL_TrapFlag_SaveStackPointer) { - if(stack_pointer_matches) + if(stack_pointer_matches) LogInfoNamedBlockF("trap_net__save_sp") { save_stack_pointer = 1; sp_check_value = dmn_rsp_from_thread(target_thread); - log_infof(">>> stepping >>> trap net logic: save stack pointer (0x%I64x)\n", sp_check_value); + log_infof("sp_check_value = 0x%I64x\n", sp_check_value); } } } @@ -4862,12 +4913,11 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) B32 trap_net_stop = 0; if(!hard_stop && use_trap_net_logic) { - if(hit_trap_flags & CTRL_TrapFlag_EndStepping) + if(hit_trap_flags & CTRL_TrapFlag_EndStepping) LogInfoNamedBlockF("trap_net__end_step") { if((hit_trap_flags & CTRL_TrapFlag_IgnoreStackPointerCheck) || stack_pointer_matches) { - log_infof(">>> stepping >>> trap net logic: end stepping\n"); trap_net_stop = 1; use_trap_net_logic = 0; } @@ -4882,9 +4932,8 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) //- rjf: handle step past trap net B32 step_past_trap_net_stop = 0; CTRL_EventCause step_past_trap_net_stop_cause = CTRL_EventCause_Null; - if(step_past_trap_net) + if(step_past_trap_net) LogInfoNamedBlockF("trap_net__single_step_past_trap_net") { - log_infof(">>> stepping >>> trap net logic: single-step non-target-thread (%I64x) past trap net\n", event->thread.u64[0]); DMN_Handle thread = event->thread; U64 thread_pre_rip = dmn_rip_from_thread(thread); U64 thread_post_rip = thread_pre_rip; @@ -4955,7 +5004,7 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) { stage_stop_cause = CTRL_EventCause_Finished; } - log_infof(">>> stepping >>> stage stop cause -> %i\n", stage_stop_cause); + log_infof("stop_cause: %i\n", stage_stop_cause); if(stage_stop_cause != CTRL_EventCause_Null) { stop_event = event; @@ -4983,6 +5032,7 @@ ctrl_thread__run(DMN_CtrlCtx *ctrl_ctx, CTRL_Msg *msg) ctrl_c2u_push_events(&evts); } + log_infof("}\n\n"); di_scope_close(di_scope); scratch_end(scratch); ProfEnd(); diff --git a/src/dasm_cache/dasm_cache.c b/src/dasm_cache/dasm_cache.c index 54d89aba..a0f46255 100644 --- a/src/dasm_cache/dasm_cache.c +++ b/src/dasm_cache/dasm_cache.c @@ -240,14 +240,16 @@ dasm_info_from_hash_params(DASM_Scope *scope, U128 hash, DASM_Params *params) } if(node == 0) { - log_infof("[dasm] cache miss, creating node...\n"); - log_infof(" hash: [0x%I64x 0x%I64x]\n", hash.u64[0], hash.u64[1]); - log_infof(" vaddr: 0x%I64x\n", params->vaddr); - log_infof(" arch: %S\n", string_from_architecture(params->arch)); - log_infof(" style_flags: 0x%x\n", params->style_flags); - log_infof(" syntax: %i\n", params->syntax); - log_infof(" base_vaddr: 0x%I64x\n", params->base_vaddr); - log_infof(" dbgi_key: [%S 0x%I64x]\n", params->dbgi_key.path, params->dbgi_key.min_timestamp); + LogInfoNamedBlockF("dasm_new_node") + { + log_infof("hash: [0x%I64x 0x%I64x]\n", hash.u64[0], hash.u64[1]); + log_infof("vaddr: 0x%I64x\n", params->vaddr); + log_infof("arch: %S\n", string_from_architecture(params->arch)); + log_infof("style_flags: 0x%x\n", params->style_flags); + log_infof("syntax: %i\n", params->syntax); + log_infof("base_vaddr: 0x%I64x\n", params->base_vaddr); + log_infof("dbgi_key: [%S 0x%I64x]\n", params->dbgi_key.path, params->dbgi_key.min_timestamp); + } node = stripe->free_node; if(node) { diff --git a/src/dbgi/dbgi.c b/src/dbgi/dbgi.c index 6fa63320..e29085ad 100644 --- a/src/dbgi/dbgi.c +++ b/src/dbgi/dbgi.c @@ -294,7 +294,7 @@ di_open(DI_Key *key) U64 stripe_idx = slot_idx%di_shared->stripes_count; DI_Slot *slot = &di_shared->slots[slot_idx]; DI_Stripe *stripe = &di_shared->stripes[stripe_idx]; - log_infof("opening debug info: %S [0x%I64x]\n", key_normalized.path, key_normalized.min_timestamp); + log_infof("open_debug_info: {\"%S\", 0x%I64x}\n", key_normalized.path, key_normalized.min_timestamp); OS_MutexScopeW(stripe->rw_mutex) { //- rjf: find existing node @@ -350,7 +350,7 @@ di_close(DI_Key *key) U64 stripe_idx = slot_idx%di_shared->stripes_count; DI_Slot *slot = &di_shared->slots[slot_idx]; DI_Stripe *stripe = &di_shared->stripes[stripe_idx]; - log_infof("closing debug info: %S [0x%I64x]\n", key_normalized.path, key_normalized.min_timestamp); + log_infof("close_debug_info: {\"%S\", 0x%I64x}\n", key_normalized.path, key_normalized.min_timestamp); OS_MutexScopeW(stripe->rw_mutex) { //- rjf: find existing node diff --git a/src/demon/demon_core.h b/src/demon/demon_core.h index 53d3ef99..53866179 100644 --- a/src/demon/demon_core.h +++ b/src/demon/demon_core.h @@ -217,6 +217,11 @@ internal void dmn_access_close(void); #define DMN_AccessScope DeferLoopChecked(dmn_access_open(), dmn_access_close()) //- rjf: processes +internal U64 dmn_process_memory_reserve(DMN_Handle process, U64 vaddr, U64 size); +internal void dmn_process_memory_commit(DMN_Handle process, U64 vaddr, U64 size); +internal void dmn_process_memory_decommit(DMN_Handle process, U64 vaddr, U64 size); +internal void dmn_process_memory_release(DMN_Handle process, U64 vaddr, U64 size); +internal void dmn_process_memory_protect(DMN_Handle process, U64 vaddr, U64 size, OS_AccessFlags flags); internal U64 dmn_process_read(DMN_Handle process, Rng1U64 range, void *dst); internal B32 dmn_process_write(DMN_Handle process, Rng1U64 range, void *src); #define dmn_process_read_struct(process, vaddr, ptr) dmn_process_read((process), r1u64((vaddr), (vaddr)+(sizeof(*ptr))), ptr) diff --git a/src/demon/win32/demon_core_win32.c b/src/demon/win32/demon_core_win32.c index 71679442..e1aa23ad 100644 --- a/src/demon/win32/demon_core_win32.c +++ b/src/demon/win32/demon_core_win32.c @@ -2581,6 +2581,73 @@ dmn_access_close(void) //- rjf: processes +internal U64 +dmn_process_memory_reserve(DMN_Handle process, U64 vaddr, U64 size) +{ + U64 result = 0; + DMN_AccessScope + { + DMN_W32_Entity *process_entity = dmn_w32_entity_from_handle(process); + result = (U64)VirtualAllocEx(process_entity->handle, (void *)vaddr, size, MEM_RESERVE, PAGE_READWRITE); + if(result == 0) + { + result = (U64)VirtualAllocEx(process_entity->handle, 0, size, MEM_RESERVE, PAGE_READWRITE); + } + } + return result; +} + +internal void +dmn_process_memory_commit(DMN_Handle process, U64 vaddr, U64 size) +{ + DMN_AccessScope + { + DMN_W32_Entity *process_entity = dmn_w32_entity_from_handle(process); + (U64)VirtualAllocEx(process_entity->handle, (void *)vaddr, size, MEM_COMMIT, PAGE_READWRITE); + } +} + +internal void +dmn_process_memory_decommit(DMN_Handle process, U64 vaddr, U64 size) +{ + DMN_AccessScope + { + DMN_W32_Entity *process_entity = dmn_w32_entity_from_handle(process); + VirtualFreeEx(process_entity->handle, (void *)vaddr, size, MEM_DECOMMIT); + } +} + +internal void +dmn_process_memory_release(DMN_Handle process, U64 vaddr, U64 size) +{ + DMN_AccessScope + { + DMN_W32_Entity *process_entity = dmn_w32_entity_from_handle(process); + VirtualFreeEx(process_entity->handle, (void *)vaddr, 0, MEM_RELEASE); + } +} + +internal void +dmn_process_memory_protect(DMN_Handle process, U64 vaddr, U64 size, OS_AccessFlags flags) +{ + DMN_AccessScope + { + DMN_W32_Entity *process_entity = dmn_w32_entity_from_handle(process); + DWORD old_flags = 0; + DWORD new_flags = PAGE_NOACCESS; + switch(flags) + { + default:{}break; + case OS_AccessFlag_Execute:{new_flags = PAGE_EXECUTE;}break; + case OS_AccessFlag_Execute|OS_AccessFlag_Read:{new_flags = PAGE_EXECUTE_READ;}break; + case OS_AccessFlag_Execute|OS_AccessFlag_Read|OS_AccessFlag_Write:{new_flags = PAGE_EXECUTE_READWRITE;}break; + case OS_AccessFlag_Read:{new_flags = PAGE_READONLY;}break; + case OS_AccessFlag_Read|OS_AccessFlag_Write:{new_flags = PAGE_READWRITE;}break; + } + VirtualProtectEx(process_entity->handle, (void *)vaddr, size, new_flags, &old_flags); + } +} + internal U64 dmn_process_read(DMN_Handle process, Rng1U64 range, void *dst) { diff --git a/src/df/core/df_core.c b/src/df/core/df_core.c index f10e2d1b..92adeccf 100644 --- a/src/df/core/df_core.c +++ b/src/df/core/df_core.c @@ -1814,7 +1814,11 @@ df_entity_alloc(DF_StateDeltaHistory *hist, DF_Entity *parent, DF_EntityKind kin df_entity_notify_mutation(entity); // rjf: log - log_infof("new entity: %S $%I64d\n", df_g_entity_kind_display_string_table[kind], entity->id); + LogInfoNamedBlockF("new_entity") + { + log_infof("kind: \"%S\"\n", df_g_entity_kind_display_string_table[kind]); + log_infof("id: $0x%I64x\n", entity->id); + } return entity; } @@ -1859,7 +1863,13 @@ df_entity_release(DF_StateDeltaHistory *hist, DF_Entity *entity) t->e = child; SLLQueuePush(first_task, last_task, t); } - log_infof("end entity: %S $%I64d\n", df_g_entity_kind_display_string_table[task->e->kind], task->e->id); + LogInfoNamedBlockF("end_entity") + { + String8 name = df_display_string_from_entity(scratch.arena, task->e); + log_infof("kind: \"%S\"\n", df_g_entity_kind_display_string_table[task->e->kind]); + log_infof("id: $0x%I64x\n", task->e->id); + log_infof("display_string: \"%S\"\n", name); + } 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); @@ -2860,8 +2870,8 @@ df_trap_net_from_thread__step_over_line(Arena *arena, DF_Entity *thread) DI_Key dbgi_key = df_dbgi_key_from_module(module); Architecture arch = df_architecture_from_entity(thread); U64 ip_vaddr = ctrl_query_cached_rip_from_thread(df_state->ctrl_entity_store, thread->ctrl_machine_id, thread->ctrl_handle); - log_infof(" ip_vaddr: 0x%I64x\n", ip_vaddr); - log_infof(" dbgi_key: {%S, 0x%I64x}\n", dbgi_key.path, dbgi_key.min_timestamp); + log_infof("ip_vaddr: 0x%I64x\n", ip_vaddr); + log_infof("dbgi_key: {%S, 0x%I64x}\n", dbgi_key.path, dbgi_key.min_timestamp); // rjf: ip => line vaddr range Rng1U64 line_vaddr_rng = {0}; @@ -2873,8 +2883,8 @@ df_trap_net_from_thread__step_over_line(Arena *arena, DF_Entity *thread) { line_vaddr_rng = df_vaddr_range_from_voff_range(module, line_voff_rng); } - log_infof(" line: {%S:%I64i}\n", line_info.file->name, line_info.pt.line); - log_infof(" voff_range: {0x%I64x, 0x%I64x}\n", line_info.voff_range.min, line_info.voff_range.max); + log_infof("line: {%S:%I64i}\n", line_info.file->name, line_info.pt.line); + log_infof("voff_range: {0x%I64x, 0x%I64x}\n", line_info.voff_range.min, line_info.voff_range.max); } // rjf: opl line_vaddr_rng -> 0xf00f00 or 0xfeefee? => include in line vaddr range @@ -2899,25 +2909,22 @@ df_trap_net_from_thread__step_over_line(Arena *arena, DF_Entity *thread) { CTRL_ProcessMemorySlice machine_code_slice = ctrl_query_cached_data_from_process_vaddr_range(scratch.arena, process->ctrl_machine_id, process->ctrl_handle, line_vaddr_rng, os_now_microseconds()+50000); machine_code = machine_code_slice.data; - log_infof(" machine_code_slice:\n {\n"); - log_infof(" stale: %i\n", machine_code_slice.stale); - log_infof(" any_byte_bad: %i\n", machine_code_slice.any_byte_bad); - log_infof(" any_byte_changed: %i\n", machine_code_slice.any_byte_changed); - log_infof(" [\n"); - for(U64 idx = 0; idx < machine_code_slice.data.size; idx += 1) + LogInfoNamedBlockF("machine_code_slice") { - if(idx%16 == 0) + log_infof("stale: %i\n", machine_code_slice.stale); + log_infof("any_byte_bad: %i\n", machine_code_slice.any_byte_bad); + log_infof("any_byte_changed: %i\n", machine_code_slice.any_byte_changed); + log_infof("bytes:\n[\n"); + for(U64 idx = 0; idx < machine_code_slice.data.size; idx += 1) { - log_infof(" "); - } - log_infof("0x%x,", machine_code_slice.data.str[idx]); - if(idx%16 == 15 || idx+1 == machine_code_slice.data.size) - { - log_infof("\n"); + log_infof("0x%x,", machine_code_slice.data.str[idx]); + if(idx%16 == 15 || idx+1 == machine_code_slice.data.size) + { + log_infof("\n"); + } } + log_infof("]\n"); } - log_infof(" ]\n"); - log_infof(" }\n"); } // rjf: machine code => ctrl flow analysis @@ -2933,15 +2940,14 @@ df_trap_net_from_thread__step_over_line(Arena *arena, DF_Entity *thread) arch, line_vaddr_rng.min, machine_code); - log_infof(" ctrl_flow_info:\n {\n"); - log_infof(" flags: %x\n", ctrl_flow_info.flags); - log_infof(" exit_points:\n {\n"); - for(DF_CtrlFlowPointNode *n = ctrl_flow_info.exit_points.first; n != 0; n = n->next) + LogInfoNamedBlockF("ctrl_flow_info") { - log_infof(" {vaddr:0x%I64x, jump_dest_vaddr:0x%I64x, expected_sp_delta:0x%I64x, inst_flags:%x}\n", n->v.vaddr, n->v.jump_dest_vaddr, n->v.expected_sp_delta, n->v.inst_flags); + log_infof("flags: %x\n", ctrl_flow_info.flags); + LogInfoNamedBlockF("exit_points") for(DF_CtrlFlowPointNode *n = ctrl_flow_info.exit_points.first; n != 0; n = n->next) + { + log_infof("{vaddr:0x%I64x, jump_dest_vaddr:0x%I64x, expected_sp_delta:0x%I64x, inst_flags:%x}\n", n->v.vaddr, n->v.jump_dest_vaddr, n->v.expected_sp_delta, n->v.inst_flags); + } } - log_infof(" }\n"); - log_infof(" }\n"); } // rjf: push traps for all exit points @@ -3002,12 +3008,10 @@ df_trap_net_from_thread__step_over_line(Arena *arena, DF_Entity *thread) } // rjf: log - log_infof(" traps:\n {\n"); - for(CTRL_TrapNode *n = result.first; n != 0; n = n->next) + LogInfoNamedBlockF("traps") for(CTRL_TrapNode *n = result.first; n != 0; n = n->next) { - log_infof(" {flags:0x%x, vaddr:0x%I64x}\n", n->v.flags, n->v.vaddr); + log_infof("{flags:0x%x, vaddr:0x%I64x}\n", n->v.flags, n->v.vaddr); } - log_infof(" }\n"); scratch_end(scratch); log_infof("}\n\n"); @@ -6600,8 +6604,9 @@ 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_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]); } + log_infof("df_cmd:\n{\n", spec->info.string); + log_infof("spec: \"%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); @@ -6610,7 +6615,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_infof("| 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) @@ -6619,22 +6624,22 @@ 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_infof("| 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_infof("| 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_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->base_unwind_index != 0) { log_infof("| base_unwind_index: 0x%I64x\n", params->base_unwind_index); } - if(params->inline_unwind_index != 0){ log_infof("| inline_unwind_index: 0x%I64x\n", params->inline_unwind_index); } - if(params->id != 0) { log_infof("| 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->base_unwind_index != 0) { log_infof("base_unwind_index: 0x%I64x\n", params->base_unwind_index); } + if(params->inline_unwind_index != 0){ log_infof("inline_unwind_index: 0x%I64x\n", params->inline_unwind_index); } + if(params->id != 0) { log_infof("id: 0x%I64x\n", params->id); } if(params->os_event != 0) { String8 kind_string = str8_lit(""); @@ -6651,10 +6656,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_infof("| os_event->kind: %S\n", kind_string); + log_infof("os_event->kind: %S\n", kind_string); } #undef HandleParamPrint - log_infof("--------------------------------\n"); + log_infof("}\n\n"); scratch_end(scratch); } df_cmd_list_push(df_state->root_cmd_arena, &df_state->root_cmds, params, spec); @@ -6847,8 +6852,8 @@ df_core_begin_frame(Arena *arena, DF_CmdList *cmds, F32 dt) { CTRL_Event *event = &event_n->v; log_infof("ctrl_event:\n{\n"); - log_infof(" kind: \"%S\"\n", ctrl_string_from_event_kind(event->kind)); - log_infof(" entity_id: %u\n", event->entity_id); + log_infof("kind: \"%S\"\n", ctrl_string_from_event_kind(event->kind)); + log_infof("entity_id: %u\n", event->entity_id); switch(event->kind) { default:{}break; @@ -6884,7 +6889,7 @@ df_core_begin_frame(Arena *arena, DF_CmdList *cmds, F32 dt) // rjf: select & snap to thread causing stop if(should_snap && stop_thread->kind == DF_EntityKind_Thread) { - log_infof(" stop_thread: \"%S\"\n", df_display_string_from_entity(scratch.arena, stop_thread)); + log_infof("stop_thread: \"%S\"\n", df_display_string_from_entity(scratch.arena, stop_thread)); DF_CmdParams params = df_cmd_params_zero(); params.entity = df_handle_from_entity(stop_thread); df_cmd_params_mark_slot(¶ms, DF_CmdParamSlot_Entity); @@ -7207,7 +7212,7 @@ df_core_begin_frame(Arena *arena, DF_CmdList *cmds, F32 dt) case CTRL_EventKind_MemDecommit:{}break; case CTRL_EventKind_MemRelease:{}break; } - log_infof("}\n"); + log_infof("}\n\n"); } //- rjf: clear tls base cache @@ -8999,7 +9004,7 @@ df_core_begin_frame(Arena *arena, DF_CmdList *cmds, F32 dt) //- rjf: developer commands case DF_CoreCmdKind_LogMarker: { - log_infof("\n\n--- #marker ---\n\n"); + log_infof("\"#MARKER\""); }break; } } diff --git a/src/raddbg/raddbg_main.c b/src/raddbg/raddbg_main.c index 9db07fce..212666b1 100644 --- a/src/raddbg/raddbg_main.c +++ b/src/raddbg/raddbg_main.c @@ -338,7 +338,7 @@ entry_point(CmdLine *cmd_line) } if(msg.size != 0) { - log_infof("IPC message received: \"%S\"", msg); + log_infof("ipc_msg: \"%S\"", msg); DF_Window *dst_window = df_gfx_state->first_window; for(DF_Window *window = dst_window; window != 0; window = window->next) {