Call Tracing and Bounded Logs

Keyboard shortcuts

×

?

Open this guide

Alt + B

Show or hide the lesson list

Alt + O

Show or fold the lesson outline

Alt + N

Open or close notes

Alt + H

Toggle semantic colours

Alt + D

Toggle page brightness

Alt + C

Toggle code brightness

← →

Move through a focused code trace

Home End

First or final step in a focused trace

Escape

Close this guide or an open panel

Reader shortcuts pause while you type in a text field.

Cheatsheet for Lesson 14.2Key ideas, reference and questions

A one-page summary of “Call Tracing and Bounded Logs” you can keep beside your notes. Plain Markdown.

Lesson 14.2 — Call Tracing and Bounded Logs: cheatsheet

• Remember: A useful trace answers one bounded question; collecting everything can bury the behavior you wanted to understand.
• Also useful: Treat restore and re-arm as two separate stops: the original call needs a brief clear path before the breakpoint can watch it again.

Key terms

• NearBranch32: NearBranch16 and NearBranch32 are the direct relative call forms used in this 32-bit target.
• AttachGuard: The AttachGuard is the last line of cleanup.

Formulas and patterns

• # gha-call-log v1; # target_sha256=...; # module=wesnoth.exe; time_us,thread,call_site,target,stack_pointer; 15234,4108,0x1400012A0,0x140003500,0x000000BEEF...

Review

• Q: Why should a call logger use a fixed-size or capped buffer? A: A hot call site could otherwise eat memory and disturb the program being measured
• Q: Why is limiting a call logger to one code range and one moment more than a performance setting? A: It makes the log a repeatable statement, such as which calls ran there in one action

Download cheatsheet (.md)

Download cheatsheet (.md)

Define the question

A call logger should not mean “break on every call in the whole process.” That would be noisy and slow.

Choose:

• one module;
• one executable section;
• one known caller range or target function;
• one small time window;
• a maximum number of events.

This scope is not just a performance setting. It gives the log a meaning. “These calls happened while one turn ended inside this verified module range” is a result you can reproduce. “The process called thousands of things” is mostly noise.

TL;DR: A useful trace answers one bounded question; collecting everything can bury the behavior you wanted to understand.

What a call instruction really does

A function call has two jobs:

1. remember the address of the instruction that should run afterward;
2. move the instruction pointer to the called function.

On 32-bit x86, a common direct call begins with opcode E8 followed by a signed 32-bit relative displacement. The CPU adds that displacement to the address immediately after the call. A disassembler performs this calculation and exposes the final target.

Predict first

At 0x00401000 the five bytes are E8 4B 00 00 00: the opcode E8, then the displacement 0x0000004B stored lowest byte first.

Which address does this call go to?

Answer: 0x00401050. The next instruction is at 0x00401000 + 5 = 0x00401005, and 0x00401005 + 0x4B = 0x00401050. The call also pushes 0x00401005, so ret comes back there.

Where a five-byte call goesE8 is followed by a signed 32-bit displacement, lowest byte first. Change the call’s address or the displacement.

Bytes, then the CPU’s arithmetic

The five bytes at 0x00401000

Opcode, then displacement

0x004010000x00401004

E8call

4B×1

00×256

00×256²

00×256³

What the CPU computes

Next instruction

0x00401000 + 5 = 0x00401005

Displacement

0x0000004B = +75 (0x4B)top bit clear: zero or positive

Target

0x00401005 + 0x4B = 0x00401050

Return address pushed

0x00401005ret resumes here

The CPU measures from the end of the call, 0x00401005, not from 0x00401000. Adding +75 (0x4B) gives 0x00401050, and 0x00401005 is pushed so ret can come back.

An indirect call such as call eax or call [ecx+8] gets its destination from a register or memory at runtime. Static bytes alone do not reveal one final target, so the first course logger deliberately records only direct calls.

A relative call starts measuring after itself. This step-by-step trace needs JavaScript. Here is the code and where the run ends.

call_site = 0x1000; length = 5
next_ip = call_site + length
target = next_ip + signed_displacement
push next_ip as the return address
instruction_pointer = target
ret later resumes at saved next_ip

Result: call enters 0x100F and a matching return resumes at 0x1005. The saved return is independent of the signed displacement.

Final values: displacement = 10; next_ip = 0x1005; target = 0x100F; saved_return = 0x1005; instruction_pointer = 0x1005.

Read every step of the lesson’s example

1. Step 1, line 1. Start with the selected inputs. Follow the highlighted operation and the changing state below.

   displacement = 10.

2. Step 2, line 2. The instruction immediately after the call is at 0x1005.

   displacement = 10; next_ip = 0x1005.

3. Step 3, line 3. Add 10 to the end address, not the call’s beginning.

   displacement = 10; next_ip = 0x1005; target = 0x100F.

4. Step 4, line 4. Save 0x1005 so the called function knows where to return.

   displacement = 10; next_ip = 0x1005; target = 0x100F; saved_return = 0x1005.

5. Step 5, line 5. Execution enters the computed destination.

   displacement = 10; next_ip = 0x1005; target = 0x100F; saved_return = 0x1005; instruction_pointer = 0x100F.

6. Step 6, line 6. Result: call enters 0x100F and a matching return resumes at 0x1005. The saved return is independent of the signed displacement.

   displacement = 10; next_ip = 0x1005; target = 0x100F; saved_return = 0x1005; instruction_pointer = 0x1005.

Static discovery and live observation are different jobs

The logger does not place a breakpoint on every byte equal to E8. That byte may appear inside an immediate value or data. Instead, iced-x86 walks complete instructions and reports their flow-control kind.

Find calls with the decoder

Use iced-x86 on the copied .text bytes and select direct near calls:

use iced_x86::{Decoder, DecoderOptions, FlowControl};

#[derive(Clone, Copy, Debug)]
struct CallSite {
    address: u64,
    target: u64,
}

fn direct_calls(bytes: &[u8], bitness: u32, start_ip: u64) -> Vec<CallSite> {
    let mut decoder = Decoder::with_ip(
        bitness,
        bytes,
        start_ip,
        DecoderOptions::NONE,
    );
    let mut calls = Vec::new();

    while decoder.can_decode() {
        let instruction = decoder.decode();
        if instruction.flow_control() == FlowControl::Call
            && matches!(
                instruction.op0_kind(),
                iced_x86::OpKind::NearBranch16
                    | iced_x86::OpKind::NearBranch32
            )
        {
            calls.push(CallSite {
                address: instruction.ip(),
                target: instruction.near_branch_target(),
            });
        }
    }
    calls
}

NearBranch16 and NearBranch32 are the direct relative call forms used in this 32-bit target. Indirect calls need runtime register or memory values and are a separate feature.

Decoder::with_ip needs both the bytes and their live starting address. The address lets each Instruction report a correct ip() and resolve a relative target. decoder.can_decode() stops at the end of the bounded slice. flow_control() == FlowControl::Call identifies call-like control flow, while the operand-kind check narrows that set to direct near branches.

The lesson uses decode() for readability. The complete binary reuses one Instruction with decode_out, which avoids constructing a new value on every loop iteration. That optimization does not change the algorithm.

Bound the software breakpoints

Options include:

• one breakpoint on a specific call site;
• one breakpoint at a target function entry;
• a small rotating set;
• an in-process instrumentation hook for a practice program.

Start with one entry breakpoint while learning the state machine. The completed course tool expands to verified direct calls in readable executable regions, excludes known noisy sites, deduplicates addresses, and applies a hard 2,000-breakpoint cap. More instrumentation multiplies state and performance cost.

A software breakpoint changes the first byte of an instruction to 0xCC, the one-byte int3 instruction. When the CPU executes it, Windows pauses the thread and reports EXCEPTION_BREAKPOINT to the debugger. The original E8 must be remembered so the real call can still execute and can later be restored.

0x00401000CC

0x004010014B

0x0040100200

0x0040100300

0x0040100400

The same 5 bytes with the software breakpoint installed. Only the first byte changes, from E8 to CC (int3). The saved original E8 is what lets the logger restore the real call before it executes.

The two-event breakpoint cycle

One breakpoint hit is not enough. If the debugger immediately writes 0xCC back at the same address and continues, the thread hits it forever. The logger temporarily restores the call and single-steps exactly one instruction:

Alternative: Treat restore and re-arm as two separate stops: the original call needs a brief clear path before the breakpoint can watch it again.

At the breakpoint event, Windows reports the address of int3. The logger:

1. confirms the address belongs to its breakpoint map;
2. restores the original E8 byte;
3. opens the event thread and reads its CONTEXT;
4. rewinds EIP to the call address;
5. sets bit 8 of EFlags, the trap flag;
6. records that this thread is stepping this call;
7. continues the event.

The CPU now executes the real call. Because the trap flag is set, Windows pauses after that one instruction with EXCEPTION_SINGLE_STEP. At this moment EIP contains the call destination. The logger clears the flag, reinstalls 0xCC at the call site, removes the thread from the stepping map, and prints the source and destination.

The stepping map is keyed by thread ID because several game threads can hit different breakpoints. A single global “currently stepping” variable would mix their state.

Capture a compact event

When the single-step pause reveals a call’s destination, copy only the facts needed to answer “who called where, on which thread, and when?” The writer can format this small owned record after the target is running again:

#[derive(Debug)]
struct CallEvent {
    timestamp_micros: u128,
    thread_id: u32,
    call_site: usize,
    target: usize,
    stack_pointer: usize,
}

Do not automatically dump the entire stack or arbitrary pointed-to memory. Record only what the current experiment requires.

The event is a snapshot of facts already available while the thread is paused. call_site and target explain control flow; thread_id separates timelines; stack_pointer helps compare call contexts without copying unknown stack contents.

Use a bounded channel

The debug loop and the log writer run at different speeds. A bounded channel holds at most 1,024 copied events; when it fills, the debugger can count a dropped event instead of leaving the game paused while disk output catches up:

use std::sync::mpsc::{self, SyncSender};

fn logger_channel() -> (SyncSender<CallEvent>, mpsc::Receiver<CallEvent>) {
    mpsc::sync_channel(1_024)
}

The debugger thread uses try_send, which fails at once when the channel is full. A bounded channel creates backpressure: it gives the producer a fixed amount of space instead of allowing logs to consume memory forever. Losing a counted event is better than holding every target thread suspended while a disk writer catches up. Lesson 14.6 compares other overload policies for the same bounded queue.

Narration: When the writer falls behind, a visible dropped-event count tells you the log has gaps instead of making the paused game wait for disk.

Resolve addresses after capture

Keep time-sensitive handling short:

Symbols can be slow or unavailable. A module-relative address is still useful:

wesnoth.exe + 0x1B4D00

Address resolution is delayed because the debug-event loop has a deadline: every target thread remains stopped until ContinueDebugEvent. Expensive formatting, symbol lookup, and file I/O belong on a background worker after the minimal register facts have been copied.

Log a versioned format

The paused thread supplied the addresses; the background writer now records them with a target fingerprint and explicit column names. In this example, one row says that thread 4108 reached a call site at time 15,234 microseconds and the call resolved to the listed target:

# gha-call-log v1
# target_sha256=...
# module=wesnoth.exe
time_us,thread,call_site,target,stack_pointer
15234,4108,0x1400012A0,0x140003500,0x000000BEEF...

The version header says how to parse the columns, and the target hash binds the log to one binary so later analysis does not mix runs from different builds. Hexadecimal addresses keep the debugger’s notation. Lesson 14.6 extends the same versioned schema with sequence numbers and correlation IDs that join the events of one action.

Protect the target

Stop logging when:

• the event cap is reached;
• the time window expires;
• the target exits;
• event drops exceed a threshold;
• the user requests stop;
• a breakpoint cannot be restored.

These conditions form the logger’s safety envelope. The event cap bounds memory and terminal output. The time cap bounds disruption. The drop threshold detects a writer that cannot keep up. A restoration failure stops the experiment because continuing would leave the target executing altered code whose ownership is uncertain.

Divide responsibility with explicit types

The complete executable uses two maps:

// 🔁 Address → displaced byte: everything needed to restore target code.
let mut breakpoints: BTreeMap<usize, u8> = BTreeMap::new();
// 👣 Thread → call site: which original instruction is between restore/re-arm.
let mut stepping: HashMap<u32, usize> = HashMap::new();

breakpoints maps each call address to its original byte. A BTreeMap also restores in deterministic address order, which makes diagnostics repeatable. stepping maps a thread ID to the call it is temporarily executing. A HashMap gives direct keyed lookup when the single-step event arrives.

The types prevent two different facts from being blurred together: “this address is patched” and “this thread is between restore and re-arm.”

The Windows debug-event contract

WaitForDebugEvent returns one pending event. Until the debugger calls ContinueDebugEvent, target threads remain stopped. Therefore every successful wait must lead to exactly one continue, including error paths.

Some event variants transfer handles to the debugger. The logger closes process, thread, and image-file handles after reading the active union member selected by dwDebugEventCode. It does not guess which union field is valid.

The AttachGuard is the last line of cleanup. If ordinary error propagation leaves the event loop, Drop attempts to detach. Breakpoint restoration still happens explicitly first because detaching a process whose code still contains course 0xCC bytes would be unsafe.

The capstone project

This tool combines the whole section:

• the pattern scanner locates a range or anchor;
• the memory wrapper copies bytes;
• iced-x86 identifies calls;
• the debugger owns breakpoint state;
• the logger moves events off the hot path;
• RAII — resource acquisition is initialization, the habit of tying cleanup to a value’s lifetime — restores bytes and closes handles.

First prove the logger against a small test target whose source is available. Then run the real capstone against one narrow course target: in Wesnoth 1.14.9, log calls around 0x009B4D00 while ending one turn. The optional build reference lists an AssaultCube and an Urban Terror target for the same logger.

Set a limit such as 1,000 events or five seconds. The output should show real module-relative callers and targets from the selected game. Compare the log with x64dbg, then detach and verify every breakpoint byte was restored.

Run the complete Wesnoth logger

Windows VM

The compiled course tool chooses the Wesnoth main module, asks VirtualQueryEx for readable executable regions, decodes them as x86 with iced-x86, and installs at most 2,000 verified E8 call breakpoints. It excludes two known noisy call sites from the historical lab. When a call fires, it restores E8, rewinds EIP, sets the trap flag, executes the real call once, records the destination EIP, reinserts 0xCC, and continues.

.\target\i686-pc-windows-msvc\release\call_logger.exe

Exercise a small Wesnoth path, then press End. The tool restores every installed call byte before detaching. The full code is call_logger.rs; shared memory and region enumeration are in process.rs. The optional build reference gives an order for reading the full source.

call_logger.rs

windows-labs/src/bin/ · Rust, 320 lines

View on GitHub ↗

Show the codeHide the code

#[cfg(all(windows, target_arch = "x86"))]
mod app {
    use std::collections::{BTreeMap, HashMap};

    use anyhow::{Context as _, Result};
    use gha_windows_labs::{OwnedHandle, Process};
    use iced_x86::{Decoder, DecoderOptions, FlowControl, Instruction, OpKind};
    use windows::Win32::{
        Foundation::{
            CloseHandle, DBG_CONTINUE, DBG_EXCEPTION_NOT_HANDLED, ERROR_SEM_TIMEOUT,
            EXCEPTION_BREAKPOINT, EXCEPTION_SINGLE_STEP, HANDLE, NTSTATUS,
        },
        System::{
            Diagnostics::Debug::{
                CONTEXT, CONTEXT_FULL_X86, CREATE_PROCESS_DEBUG_EVENT, CREATE_THREAD_DEBUG_EVENT,
                ContinueDebugEvent, DEBUG_EVENT, DebugActiveProcess, DebugActiveProcessStop,
                EXCEPTION_DEBUG_EVENT, EXIT_PROCESS_DEBUG_EVENT, GetThreadContext,
                LOAD_DLL_DEBUG_EVENT, SetThreadContext, WaitForDebugEvent,
            },
            Threading::{
                OpenThread, THREAD_GET_CONTEXT, THREAD_QUERY_INFORMATION, THREAD_SET_CONTEXT,
            },
        },
        UI::Input::KeyboardAndMouse::{GetAsyncKeyState, VK_END},
    };

    const MAX_BREAKPOINTS: usize = 2_000;
    const TRAP_FLAG: u32 = 1 << 8;
    const NOISY_CALLS: [usize; 2] = [0x0040_E3D8, 0x0040_E3EA];

    struct AttachGuard {
        pid: u32,
        active: bool,
    }

    impl Drop for AttachGuard {
        fn drop(&mut self) {
            if self.active {
                // SAFETY: best-effort pair for this tool's successful attach.
                let _ = unsafe { DebugActiveProcessStop(self.pid) };
            }
        }
    }

    fn close_event_handle(handle: HANDLE) {
        if !handle.is_invalid() {
            // SAFETY: debug events transfer these handles to the debugger.
            let _ = unsafe { CloseHandle(handle) };
        }
    }

    fn dispose_event_handles(event: &DEBUG_EVENT) {
        // SAFETY: the event code selects the active union field.
        unsafe {
            match event.dwDebugEventCode {
                CREATE_PROCESS_DEBUG_EVENT => {
                    let info = event.u.CreateProcessInfo;
                    close_event_handle(info.hFile);
                    close_event_handle(info.hProcess);
                    close_event_handle(info.hThread);
                }
                CREATE_THREAD_DEBUG_EVENT => close_event_handle(event.u.CreateThread.hThread),
                LOAD_DLL_DEBUG_EVENT => close_event_handle(event.u.LoadDll.hFile),
                _ => {}
            }
        }
    }

    fn open_thread(thread_id: u32) -> Result<OwnedHandle> {
        let access = THREAD_GET_CONTEXT | THREAD_SET_CONTEXT | THREAD_QUERY_INFORMATION;
        // SAFETY: thread id came from the current debug event.
        let raw = unsafe { OpenThread(access, false, thread_id) }?;
        Ok(OwnedHandle::from_raw(raw)?)
    }

    fn context(thread: &OwnedHandle) -> Result<CONTEXT> {
        let mut value = CONTEXT {
            ContextFlags: CONTEXT_FULL_X86,
            ..Default::default()
        };
        // SAFETY: the event thread is suspended and this output is writable.
        unsafe { GetThreadContext(thread.raw(), &mut value) }?;
        Ok(value)
    }

    fn set_context(thread: &OwnedHandle, value: &CONTEXT) -> Result<()> {
        // SAFETY: this context belongs to the suspended event thread.
        unsafe { SetThreadContext(thread.raw(), value) }?;
        Ok(())
    }

    fn direct_calls(process: &Process, base: usize, size: usize) -> Result<Vec<usize>> {
        let end = base.checked_add(size).context("module range overflowed")?;
        let mut calls = Vec::new();
        for region in process.regions(base, end)? {
            if !region.readable || !region.executable {
                continue;
            }
            let start = region.base.max(base);
            let region_end = region.base.saturating_add(region.size).min(end);
            if start >= region_end {
                continue;
            }
            let Ok(bytes) = process.read_bytes(start, region_end - start) else {
                continue;
            };
            let mut decoder = Decoder::with_ip(32, &bytes, start as u64, DecoderOptions::NONE);
            let mut instruction = Instruction::default();
            while decoder.can_decode() && calls.len() < MAX_BREAKPOINTS {
                decoder.decode_out(&mut instruction);
                if instruction.is_invalid()
                    || instruction.flow_control() != FlowControl::Call
                    || !matches!(
                        instruction.op0_kind(),
                        OpKind::NearBranch16 | OpKind::NearBranch32
                    )
                {
                    continue;
                }
                let source = instruction.ip() as usize;
                let target = instruction.near_branch_target() as usize;
                if (base..end).contains(&target) && !NOISY_CALLS.contains(&source) {
                    calls.push(source);
                }
            }
        }
        calls.sort_unstable();
        calls.dedup();
        calls.truncate(MAX_BREAKPOINTS);
        Ok(calls)
    }

    fn install_breakpoints(process: &Process, addresses: &[usize]) -> Result<BTreeMap<usize, u8>> {
        let mut installed = BTreeMap::new();
        for &address in addresses {
            let original = process.read_bytes(address, 1)?[0];
            if original != 0xE8 {
                continue;
            }
            if let Err(error) = process.write_code(address, &[0xCC]) {
                for (&installed_address, &byte) in &installed {
                    let _ = process.write_code(installed_address, &[byte]);
                }
                return Err(error);
            }
            installed.insert(address, original);
        }
        Ok(installed)
    }

    fn restore_all(process: &Process, breakpoints: &BTreeMap<usize, u8>) {
        for (&address, &original) in breakpoints {
            if process
                .read_bytes(address, 1)
                .is_ok_and(|bytes| bytes == [0xCC])
            {
                let _ = process.write_code(address, &[original]);
            }
        }
    }

    fn end_pressed() -> bool {
        // SAFETY: VK_END is a valid virtual-key code.
        unsafe { GetAsyncKeyState(VK_END.0.into()) & 1 != 0 }
    }

    fn handle_exception(
        process: &Process,
        event: &DEBUG_EVENT,
        breakpoints: &BTreeMap<usize, u8>,
        stepping: &mut HashMap<u32, usize>,
        initial_break_seen: &mut bool,
    ) -> Result<NTSTATUS> {
        // SAFETY: the caller checked EXCEPTION_DEBUG_EVENT.
        let exception = unsafe { event.u.Exception.ExceptionRecord };
        let code = exception.ExceptionCode;
        let address = exception.ExceptionAddress as usize;

        if code == EXCEPTION_BREAKPOINT {
            if let Some(&original) = breakpoints.get(&address) {
                process.write_code(address, &[original])?;
                let thread = open_thread(event.dwThreadId)?;
                let mut registers = context(&thread)?;
                registers.Eip = u32::try_from(address)?;
                registers.EFlags |= TRAP_FLAG;
                set_context(&thread, &registers)?;
                stepping.insert(event.dwThreadId, address);
                return Ok(DBG_CONTINUE);
            }
            if !*initial_break_seen {
                *initial_break_seen = true;
                return Ok(DBG_CONTINUE);
            }
        }

        if code == EXCEPTION_SINGLE_STEP {
            let Some(call_address) = stepping.remove(&event.dwThreadId) else {
                return Ok(DBG_EXCEPTION_NOT_HANDLED);
            };
            let thread = open_thread(event.dwThreadId)?;
            let mut registers = context(&thread)?;
            registers.EFlags &= !TRAP_FLAG;
            let destination = registers.Eip;
            set_context(&thread, &registers)?;
            process.write_code(call_address, &[0xCC])?;
            println!("{call_address:#010x}: call {destination:#010x}");
            return Ok(DBG_CONTINUE);
        }
        Ok(DBG_EXCEPTION_NOT_HANDLED)
    }

    pub fn run() -> Result<()> {
        let entry = Process::find("wesnoth.exe")?;
        let process = Process::open(entry.clone(), true)?;
        anyhow::ensure!(process.is_32_bit()?, "call logger requires 32-bit Wesnoth");
        let (base, size) = process.module("wesnoth.exe")?;
        let calls = direct_calls(&process, base, size)?;
        anyhow::ensure!(
            !calls.is_empty(),
            "no direct calls found in executable regions"
        );

        // SAFETY: the PID is the exact process found by ToolHelp.
        unsafe { DebugActiveProcess(entry.id) }?;
        let mut attach = AttachGuard {
            pid: entry.id,
            active: true,
        };
        let mut breakpoints = BTreeMap::new();
        let mut stepping = HashMap::new();
        let mut initial_break_seen = false;
        println!("Waiting for Windows' initial attach breakpoint...");

        loop {
            if !breakpoints.is_empty() && stepping.is_empty() && end_pressed() {
                restore_all(&process, &breakpoints);
                // SAFETY: no debug event is pending between loop iterations.
                unsafe { DebugActiveProcessStop(entry.id) }?;
                attach.active = false;
                println!("Restored {} call bytes and detached.", breakpoints.len());
                break;
            }

            let mut event = DEBUG_EVENT::default();
            // SAFETY: event is a valid writable DEBUG_EVENT.
            match unsafe { WaitForDebugEvent(&mut event, 100) } {
                Ok(()) => {}
                Err(error) if error.code() == ERROR_SEM_TIMEOUT.to_hresult() => continue,
                Err(error) => return Err(error.into()),
            }

            let result = if event.dwDebugEventCode == EXCEPTION_DEBUG_EVENT {
                // Install while every target thread is stopped at the attach event.
                if !initial_break_seen && breakpoints.is_empty() {
                    match install_breakpoints(&process, &calls) {
                        Ok(installed) => {
                            breakpoints = installed;
                            println!("Installed {} verified call breakpoints.", breakpoints.len());
                        }
                        Err(error) => {
                            // Continue this pending attach event before returning.
                            // SAFETY: this exactly matches the event above.
                            let _ = unsafe {
                                ContinueDebugEvent(
                                    event.dwProcessId,
                                    event.dwThreadId,
                                    DBG_EXCEPTION_NOT_HANDLED,
                                )
                            };
                            return Err(error);
                        }
                    }
                }
                handle_exception(
                    &process,
                    &event,
                    &breakpoints,
                    &mut stepping,
                    &mut initial_break_seen,
                )
            } else {
                Ok(DBG_CONTINUE)
            };
            dispose_event_handles(&event);
            let status = match result {
                Ok(status) => status,
                Err(error) => {
                    // SAFETY: this exactly matches the pending event.
                    let _ = unsafe {
                        ContinueDebugEvent(
                            event.dwProcessId,
                            event.dwThreadId,
                            DBG_EXCEPTION_NOT_HANDLED,
                        )
                    };
                    restore_all(&process, &breakpoints);
                    return Err(error);
                }
            };
            // SAFETY: every returned event is continued exactly once.
            unsafe { ContinueDebugEvent(event.dwProcessId, event.dwThreadId, status) }?;

            if event.dwDebugEventCode == EXIT_PROCESS_DEBUG_EVENT {
                attach.active = false;
                break;
            }
        }
        Ok(())
    }
}

#[cfg(all(windows, target_arch = "x86"))]
fn main() -> anyhow::Result<()> {
    app::run()
}

#[cfg(not(all(windows, target_arch = "x86")))]
fn main() {
    eprintln!("Build this call logger for i686-pc-windows-msvc.");
}

process.rs

windows-labs/src/windows_impl/ · Rust, 350 lines

View on GitHub ↗

Show the codeHide the code

use std::{ffi::c_void, mem::size_of};

use anyhow::{Context, Result};
use windows::Win32::{
    Foundation::ERROR_NO_MORE_FILES,
    System::{
        Diagnostics::{
            Debug::{FlushInstructionCache, ReadProcessMemory, WriteProcessMemory},
            ToolHelp::{
                CreateToolhelp32Snapshot, MODULEENTRY32W, Module32FirstW, Module32NextW,
                PROCESSENTRY32W, Process32FirstW, Process32NextW, TH32CS_SNAPMODULE,
                TH32CS_SNAPMODULE32, TH32CS_SNAPPROCESS,
            },
        },
        Memory::{
            MEM_COMMIT, MEMORY_BASIC_INFORMATION, PAGE_EXECUTE, PAGE_EXECUTE_READ,
            PAGE_EXECUTE_READWRITE, PAGE_EXECUTE_WRITECOPY, PAGE_GUARD, PAGE_NOACCESS,
            PAGE_PROTECTION_FLAGS, PAGE_READONLY, PAGE_READWRITE, PAGE_WRITECOPY, VirtualProtectEx,
            VirtualQueryEx,
        },
        SystemInformation::{
            IMAGE_FILE_MACHINE, IMAGE_FILE_MACHINE_I386, IMAGE_FILE_MACHINE_UNKNOWN,
        },
        Threading::{
            IsWow64Process2, OpenProcess, PROCESS_ACCESS_RIGHTS, PROCESS_QUERY_INFORMATION,
            PROCESS_VM_OPERATION, PROCESS_VM_READ, PROCESS_VM_WRITE,
        },
    },
};

use super::OwnedHandle;

#[derive(Clone, Debug)]
pub struct ProcessEntry {
    pub id: u32,
    pub name: String,
}

#[derive(Clone, Copy, Debug)]
pub struct MemoryRegion {
    pub base: usize,
    pub size: usize,
    pub readable: bool,
    pub writable: bool,
    pub executable: bool,
}

#[derive(Debug)]
pub struct Process {
    handle: OwnedHandle,
    id: u32,
    name: String,
}

fn wide_text(buffer: &[u16]) -> String {
    let end = buffer
        .iter()
        .position(|unit| *unit == 0)
        .unwrap_or(buffer.len());
    String::from_utf16_lossy(&buffer[..end])
}

fn no_more_files(error: &windows::core::Error) -> bool {
    error.code() == ERROR_NO_MORE_FILES.to_hresult()
}

impl Process {
    /// Lists every running process with ToolHelp.
    pub fn list() -> Result<Vec<ProcessEntry>> {
        // SAFETY: no borrowed pointers are passed; the returned snapshot is owned below.
        let snapshot = unsafe { CreateToolhelp32Snapshot(TH32CS_SNAPPROCESS, 0) }?;
        let snapshot = OwnedHandle::from_raw(snapshot)?;

        let mut raw = PROCESSENTRY32W {
            dwSize: size_of::<PROCESSENTRY32W>() as u32,
            ..Default::default()
        };

        // SAFETY: `raw` is correctly sized and writable for the duration of the call.
        unsafe { Process32FirstW(snapshot.raw(), &mut raw) }?;

        let mut processes = Vec::new();
        loop {
            processes.push(ProcessEntry {
                id: raw.th32ProcessID,
                name: wide_text(&raw.szExeFile),
            });

            // SAFETY: `raw` remains a valid PROCESSENTRY32W output buffer.
            match unsafe { Process32NextW(snapshot.raw(), &mut raw) } {
                Ok(()) => {}
                Err(error) if no_more_files(&error) => break,
                Err(error) => return Err(error.into()),
            }
        }
        Ok(processes)
    }

    pub fn find(name: &str) -> Result<ProcessEntry> {
        Self::list()?
            .into_iter()
            .find(|entry| entry.name.eq_ignore_ascii_case(name))
            .with_context(|| format!("process {name:?} is not running"))
    }

    pub fn open_by_name(name: &str, allow_write: bool) -> Result<Self> {
        let entry = Self::find(name)?;
        Self::open(entry, allow_write)
    }

    pub fn open(entry: ProcessEntry, allow_write: bool) -> Result<Self> {
        let mut access: PROCESS_ACCESS_RIGHTS = PROCESS_QUERY_INFORMATION | PROCESS_VM_READ;
        if allow_write {
            access |= PROCESS_VM_OPERATION | PROCESS_VM_WRITE;
        }

        Self::open_with_access(entry, access)
    }

    pub fn open_with_access(entry: ProcessEntry, access: PROCESS_ACCESS_RIGHTS) -> Result<Self> {
        // SAFETY: the PID is a value; inheritance is disabled; `OwnedHandle` owns the result.
        let handle = unsafe { OpenProcess(access, false, entry.id) }?;
        Ok(Self {
            handle: OwnedHandle::from_raw(handle)?,
            id: entry.id,
            name: entry.name,
        })
    }

    pub fn is_32_bit(&self) -> Result<bool> {
        let mut process_machine = IMAGE_FILE_MACHINE::default();
        let mut native_machine = IMAGE_FILE_MACHINE::default();
        // SAFETY: both output pointers remain valid for the call.
        unsafe {
            IsWow64Process2(
                self.handle.raw(),
                &mut process_machine,
                Some(&mut native_machine),
            )?;
        }
        Ok(process_machine == IMAGE_FILE_MACHINE_I386
            || (process_machine == IMAGE_FILE_MACHINE_UNKNOWN
                && native_machine == IMAGE_FILE_MACHINE_I386))
    }

    pub fn id(&self) -> u32 {
        self.id
    }

    pub fn name(&self) -> &str {
        &self.name
    }

    pub fn raw_handle(&self) -> windows::Win32::Foundation::HANDLE {
        self.handle.raw()
    }

    pub fn read_exact(&self, address: usize, output: &mut [u8]) -> Result<()> {
        let mut bytes_read = 0_usize;
        // SAFETY: `output` is writable for its length. Windows validates the remote range.
        unsafe {
            ReadProcessMemory(
                self.handle.raw(),
                address as *const c_void,
                output.as_mut_ptr().cast(),
                output.len(),
                Some(&mut bytes_read),
            )?;
        }
        anyhow::ensure!(bytes_read == output.len(), "short read at {address:#x}");
        Ok(())
    }

    pub fn read_bytes(&self, address: usize, count: usize) -> Result<Vec<u8>> {
        let mut bytes = vec![0_u8; count];
        self.read_exact(address, &mut bytes)?;
        Ok(bytes)
    }

    pub fn read_u32(&self, address: usize) -> Result<u32> {
        let bytes: [u8; 4] = self
            .read_bytes(address, 4)?
            .try_into()
            .expect("the read length is exactly four");
        Ok(u32::from_le_bytes(bytes))
    }

    pub fn read_f32(&self, address: usize) -> Result<f32> {
        Ok(f32::from_bits(self.read_u32(address)?))
    }

    pub fn write_exact(&self, address: usize, bytes: &[u8]) -> Result<()> {
        let mut bytes_written = 0_usize;
        // SAFETY: `bytes` is readable for its length. Windows validates the remote range.
        unsafe {
            WriteProcessMemory(
                self.handle.raw(),
                address as *const c_void,
                bytes.as_ptr().cast(),
                bytes.len(),
                Some(&mut bytes_written),
            )?;
        }
        anyhow::ensure!(bytes_written == bytes.len(), "short write at {address:#x}");
        Ok(())
    }

    pub fn write_u32(&self, address: usize, value: u32) -> Result<()> {
        self.write_exact(address, &value.to_le_bytes())
    }

    /// Writes machine code, flushes the CPU instruction cache, and restores protection.
    pub fn write_code(&self, address: usize, bytes: &[u8]) -> Result<()> {
        let mut old = PAGE_PROTECTION_FLAGS::default();
        // SAFETY: Windows validates the target range and writes `old` before returning.
        unsafe {
            VirtualProtectEx(
                self.handle.raw(),
                address as *const c_void,
                bytes.len(),
                PAGE_EXECUTE_READWRITE,
                &mut old,
            )?;
        }

        let write_result = self.write_exact(address, bytes);
        if write_result.is_ok() {
            // SAFETY: the process handle is live and the written range is the one above.
            unsafe {
                FlushInstructionCache(
                    self.handle.raw(),
                    Some(address as *const c_void),
                    bytes.len(),
                )?;
            }
        }

        let mut ignored = PAGE_PROTECTION_FLAGS::default();
        // SAFETY: this restores the protection returned by the first call.
        let restore_result = unsafe {
            VirtualProtectEx(
                self.handle.raw(),
                address as *const c_void,
                bytes.len(),
                old,
                &mut ignored,
            )
        };

        write_result?;
        restore_result?;
        Ok(())
    }

    pub fn module(&self, wanted_name: &str) -> Result<(usize, usize)> {
        // Include SNAPMODULE32 so a 64-bit tool can list a 32-bit game module.
        // SAFETY: the PID is valid and the returned snapshot is owned below.
        let snapshot =
            unsafe { CreateToolhelp32Snapshot(TH32CS_SNAPMODULE | TH32CS_SNAPMODULE32, self.id) }?;
        let snapshot = OwnedHandle::from_raw(snapshot)?;
        let mut raw = MODULEENTRY32W {
            dwSize: size_of::<MODULEENTRY32W>() as u32,
            ..Default::default()
        };

        // SAFETY: `raw` is correctly sized and writable.
        unsafe { Module32FirstW(snapshot.raw(), &mut raw) }?;
        loop {
            if wide_text(&raw.szModule).eq_ignore_ascii_case(wanted_name) {
                return Ok((raw.modBaseAddr as usize, raw.modBaseSize as usize));
            }
            // SAFETY: `raw` remains a valid output buffer.
            match unsafe { Module32NextW(snapshot.raw(), &mut raw) } {
                Ok(()) => {}
                Err(error) if no_more_files(&error) => break,
                Err(error) => return Err(error.into()),
            }
        }
        anyhow::bail!("module {wanted_name:?} was not found in {}", self.name)
    }

    pub fn regions(&self, start: usize, end: usize) -> Result<Vec<MemoryRegion>> {
        let mut current = start;
        let mut regions = Vec::new();

        while current < end {
            let mut raw = MEMORY_BASIC_INFORMATION::default();
            // SAFETY: `raw` is a valid output structure; Windows validates the address.
            let returned = unsafe {
                VirtualQueryEx(
                    self.handle.raw(),
                    Some(current as *const c_void),
                    &mut raw,
                    size_of::<MEMORY_BASIC_INFORMATION>(),
                )
            };
            if returned == 0 {
                break;
            }

            let protection = raw.Protect;
            let blocked = protection.contains(PAGE_GUARD) || protection.contains(PAGE_NOACCESS);
            let readable = !blocked
                && raw.State == MEM_COMMIT
                && [
                    PAGE_READONLY,
                    PAGE_READWRITE,
                    PAGE_WRITECOPY,
                    PAGE_EXECUTE_READ,
                    PAGE_EXECUTE_READWRITE,
                    PAGE_EXECUTE_WRITECOPY,
                ]
                .iter()
                .any(|flag| protection.contains(*flag));
            let writable = readable
                && [
                    PAGE_READWRITE,
                    PAGE_WRITECOPY,
                    PAGE_EXECUTE_READWRITE,
                    PAGE_EXECUTE_WRITECOPY,
                ]
                .iter()
                .any(|flag| protection.contains(*flag));
            let executable = !blocked
                && [
                    PAGE_EXECUTE,
                    PAGE_EXECUTE_READ,
                    PAGE_EXECUTE_READWRITE,
                    PAGE_EXECUTE_WRITECOPY,
                ]
                .iter()
                .any(|flag| protection.contains(*flag));

            let base = raw.BaseAddress as usize;
            let size = raw.RegionSize;
            regions.push(MemoryRegion {
                base,
                size,
                readable,
                writable,
                executable,
            });

            let next = base.checked_add(size).context("memory map overflowed")?;
            anyhow::ensure!(next > current, "memory map did not advance");
            current = next;
        }
        Ok(regions)
    }
}

This first complete version writes compact lines directly to the console. The bounded-channel design above is the next performance step when you add file output; it is not required to run or reproduce the actual call logger.

Executed calls appearing in a Wesnoth traceSilent demonstration · 15 seconds

The original call-logger recording shows the running game producing trace output. Each observed call requires a breakpoint hit, execution of the saved call, a single-step event, and re-arming; bytes discovered in a static scan have not necessarily executed.

Download Executed calls appearing in a Wesnoth trace video

Compare a trace with a run that changed nothing

One trace lists what ran while it recorded, but not which calls the action caused: most of them belong to drawing, input and timers that run anyway. To separate the two, fix the scenario first (the build, the save, the logging window and the event cap) and record it twice without changing anything. Then record it once more with a single change, such as recruiting one unit before ending the turn.

The two unchanged runs show how far the counts move on their own. A function the game calls once per frame runs as many times as frames fit in the window, and that depends on timing, so even identical runs disagree. A count in the changed run points at the change only when it falls outside the range the unchanged runs produced.

Predict first

Two runs that only end the turn called wesnoth.exe+0x0E7710 212 and 219 times. A third run that first recruits one unit called it 215 times.

Does recruiting change how often +0x0E7710 runs?

Answer: The counts cannot tell: 215 lies inside the 212 to 219 of the identical runs. A count points at the change only when it falls outside what unchanged runs produce. 215 is inside, so this function may or may not take part in recruiting, and these counts cannot separate the two.

Two unchanged runs, then one changeCall counts for four logged targets in wesnoth.exe. Runs A and A′ repeat the same scenario; run B adds one recruit.

1. 1 Fix the scenario before any run

   The same for every run

   Build

   wesnoth.exe, its SHA-256 in the log header

   Start

   the same save: turn 3, four units on the map

   Window

   5 seconds from the first click, at most 1,000 events

   The action

   Runs A and A′

   end the turn

   Run B

   recruit one unit, then end the turn

   Every run uses the same build, the same save and the same logging window. Only the action differs, and only in run B.

2. 2 Two unchanged runs give the spread

   Calls per target in runs A and A′

   wesnoth.exe+0x0E7710

   212A

   219A′

   212 to 219spread

   wesnoth.exe+0x1F0C80

   4A

   4A′

   4spread

   wesnoth.exe+0x2A1C30

   1A

   1A′

   1spread

   wesnoth.exe+0x3C5E40

   0A

   0A′

   0spread

   Runs A and A′ did the same thing, yet +0x0E7710 ran 212 and then 219 times: 219 − 212 = 7 calls of difference from timing alone, because the number of frames that fit in 5 seconds varies.

3. 3 Read run B against the spread

   Run B compared with the spread

   wesnoth.exe+0x0E7710

   212 to 219A and A′

   215B

   inside: no evidence

   wesnoth.exe+0x1F0C80

   4A and A′

   5B

   outside: a candidate

   wesnoth.exe+0x2A1C30

   1A and A′

   1B

   inside: no evidence

   wesnoth.exe+0x3C5E40

   0A and A′

   1B

   outside: a candidate

   Only two targets leave the spread: +0x1F0C80 ran 5 times against 4, and +0x3C5E40 ran once against never. Those are the two places to break during the next recruit.

4. 4 One guess to test next

   +0x1F0C80

   Counts

   4 calls with 4 units

   5 calls with 5 units

   Guess

   called once for each unit when a turn ends

   Test

   break on it in the next run: each hit should receive a different unit

   The save had four units and run B had five, and +0x1F0C80 ran 4 and then 5 times. Once per unit at the end of a turn fits, but it stays a guess until a breakpoint shows each call handling a different unit.

Call counts for four logged targets in wesnoth.exe. Runs A and A′ repeat the same scenario; run B adds one recruit.

Diagnose by the last completed state

Troubleshooting by the last completed state

Symptom	Likely boundary
No call sites discovered	Wrong bitness, module range, region permissions, or decoder input
Breakpoints install but never fire	The chosen action did not execute those sites, or the scope is wrong
Repeated hit at one address	EIP was not rewound or the call was re-armed too early
Unhandled single-step event	The thread ID was absent from the stepping map
Target stays paused	A WaitForDebugEvent result did not reach one matching continue
Target crashes after detach	Original bytes were not completely restored

This table is why the state machine is explained explicitly: the symptom tells you which transition to inspect instead of encouraging random breakpoint changes.

Optional build reference

These notes help when you reproduce the logger on another course game or read its complete source. The breakpoint cycle and bounded record above do not depend on them.

Optional build reference: other capstone targets

• AssaultCube 1.2.0.2: log entries to the internal print function at 0x00419880 while names are drawn;
• Urban Terror 4.3.4: log the render path around the memory-wall hook at 0x0052D2FD for one local frame window.

Optional build reference: read the complete source in six passes

The full call_logger.rs is longer than the scanner because it owns a live state machine. Read it in this order:

1. Constants and guards — caps, trap flag, known exclusions, detach cleanup.
2. Thread context helpers — open only the event thread and get or set its suspended register state.
3. Static discovery — copy executable regions and let iced-x86 return verified call instructions.
4. Breakpoint transaction — save E8, install 0xCC, and roll back already-installed sites on partial failure.
5. Exception state machine — pair each breakpoint event with a later per-thread single-step event.
6. Event loop and shutdown — continue every event once, close transferred handles, restore bytes, and detach.

Do not begin at main and dive into every Windows name. First locate these six responsibilities; then read the helper used by the phase you are studying.

🧩

Knowledge check

Keep logging bounded

Why should a call logger use a fixed-size or capped buffer?

1A hot call site could otherwise eat memory and disturb the program being measured2A cap makes every call unique, so the log never has to store the same call twice3A buffer with a limit stops game threads from running while the log is being written4Logging code needs executable memory, which is only available in fixed-size blocks

Check answer

Finished Lesson 14.2?

Mark it done and the lesson list shows a ✓ beside it. A chapter whose lessons are all done is marked done too. Progress is saved in this browser only.

Mark lesson doneLesson done. Mark it not done

Chapter 14: 10 lessons

📝 Notes