diff --git a/CHANGELOG.md b/CHANGELOG.md index ab50656..e072563 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -79,6 +79,18 @@ All notable changes to this project are documented here. The format follows ### Added +- **A command that fails keeps what the engine printed**: `DbgEngError::CommandFailedWithOutput`, + read through `DbgEngError::output()`. `execute_command`, `execute_command_bounded`, + `execute_and_wait`, `settle` and `run_to_address` answer with it where they answered + `CommandFailed`, and the message is unchanged. The code alone said little -- `0x80040205` is the + answer to a mistyped command, to an argument naming nothing, to `g` on a dump and to `||1s` on a + system not yet loaded -- while the engine's own line, which says which, was printed into the + capture and dropped with it. Measured on dbgeng 10.0.29617.1000 and 10.0.26100.1742 (ARM64), the + same on both (`examples/failed_command_output.rs`): `Couldn't resolve error at 'ntdll!Nope'`, + `^ No runnable debuggees error in 'g'`, `^ Illegal debuggee error in '||1s'`, with the output of + any segment that ran before the failing one kept beside it. Not every failure takes this road: + `dt` of a missing type and an extension command that does not exist print their complaint and + return success. Asked for by windbg-mcp `FOLLOWUPS.md` item 126. - **`DebugEngine::reload_symbols_bounded(args, timeout_ms)`** and **`SymbolReload`**: a reload with the crate's watchdog around it, reporting a break by either origin in `cut_short` rather than as the `0xD000013A` it provokes. Measured before it was written, since a watchdog that cannot break diff --git a/CLAUDE.md b/CLAUDE.md index dd68577..2adadbd 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -107,5 +107,6 @@ There is no build script and no assembler step: both left with the exploitation - `examples/stored_event_probe.rs` — the measurements behind `last_event`, `stored_event` and `stack_frames_from`: how the engine says a target has no stored event (`E_UNEXPECTED`, on a live process and a kernel crash dump alike), that a kernel crash dump has none at all so `bug_check` and this do not overlap, and that what makes the two stack walks differ is the **selected thread** and nothing else — `.frame`, `.cxr` and `.ecxr` move neither. Run it after touching the event or stack-walk seam. Its main finding is a trap worth knowing before writing any `GetStoredEventInformation` call: unlike `GetScope` it does **not** refuse a context buffer that is too small, it truncates and returns success, and the damage only surfaces when `GetContextStackTrace` rejects the result. Needs a user-mode fault dump, and a **two-thread** one for the last question — a single-threaded dump agrees with itself in every state it can be put in, which nearly recorded "no difference" as the answer - `examples/breakpoint_status_probe.rs` — the measurements behind `BreakpointAction`: that `Default` stops exactly as no callback does, that `Go` is honoured and `Break` stops at the breakpoint, that the callback can read the engine from inside the hit through `BreakpointHit`'s view — `current_thread_data_offset` matching `@$thread` there, the TEB user-mode and the KTHREAD on a kernel — and what letting a hit through costs four ways (pass count, `Go`, `Go` reading the engine, `.if … gc` text). Its finding: **a hit costs one trap whichever way it passes** — 0.17–0.20 ms user-mode, ~25 ms over 115200-baud serial KD — and reads the stop already carried cost microseconds while memory it did not costs a link round trip (1.05 ms on serial). A breakpoint's own command still runs on a hit the callback lets through. Run it after touching the event-callback seam; `kernel` needs a live target it may hold for minutes, and leaves it running. **Give each user-mode phase its own process** — run on one, the later phases measure a target that has finished its startup burst, which read as a way 2000x slower than it is - `examples/reload_interrupt_probe.rs` — the measurements behind `reload_symbols_bounded`: that `SetInterrupt` reaches a `Reload("")` in progress (it does, within milliseconds, failing it with `0xD000013A`), that a reload cut short leaves a **smaller** inventory than it began with because it rebuilds the list rather than adding to it, and that a break left pending from before a reload empties it while reporting success — on a live kernel, where the drain both reload methods now take is what stops it. Needs a live kernel on a slow link, since only a **cold** reload costs anything: the first after an attach read 181 modules in 3.9s over 115200-baud serial and a repeat took 57ms from the engine's cache, so the probe flushes it (`.cache flushall`) before each trial. Takes `d`, `r` and `s` trials — a deadline, a host request, a stale break — and leaves the target running +- `examples/failed_command_output.rs` — the measurement behind `DbgEngError::CommandFailedWithOutput`: that the engine's own line saying why a command failed is printed into this call's capture, so it was being thrown away with the buffer rather than never arriving. A mistyped command, an argument naming nothing, `g` on a dump and `||1s` on a system not yet loaded all fail `0x80040205`, and only the captured line tells them apart. It also records which failures do **not** come back as errors — `dt` of a missing type and an unknown extension command print and return success — so read it before asserting on either half. Takes one user-mode dump, or two for the `||1s` case - `README.md` — user-facing overview, the `!dbgscope.poolmap` extension, and usage sketches - `.cursor/rules/*.mdc` — Cursor editor rules; they defer to this file for build commands and the module map diff --git a/examples/failed_command_output.rs b/examples/failed_command_output.rs new file mode 100644 index 0000000..8b1762e --- /dev/null +++ b/examples/failed_command_output.rs @@ -0,0 +1,135 @@ +//! Scratch experiment (not part of the public API), and the record behind +//! [`DbgEngError::CommandFailedWithOutput`]. +//! +//! The question: when `Execute` returns a failure, is the engine's own account of why in the +//! output this crate captures for the call, or only on some other client's console? `cdb` prints +//! it — `^ Illegal debuggee error in '||1s'` — and that shows the engine emits the line, not that +//! it lands in a capture made with `DEBUG_OUTCTL_THIS_CLIENT`. Until the variant existed the +//! capture was dropped on the error path, so nothing could have said. +//! +//! **It does land there.** Measured 2026-10-14 on an ARM64 host against a user-mode dump, on +//! dbgeng 10.0.29617.1000 and on 10.0.26100.1742, and the two answered byte for byte alike. Every +//! failure below is `0x80040205`, and the capture is what tells them apart: +//! +//! | command | path | captured | +//! |---|---|---| +//! | `zzzz` | both | `Couldn't resolve error at 'zzz'` | +//! | `? ntdll!Nope`, `u ntdll!Nope`, `dd ntdll!Nope` | bounded | `Couldn't resolve error at 'ntdll!Nope'` | +//! | `.echo before the failure; zzzz` | bounded | `before the failure`, then the line above | +//! | `g` | `execute_and_wait` | `^ No runnable debuggees error in 'g'` | +//! | `||1s`, after `.opendump` of a second dump | bounded | `^ Illegal debuggee error in '||1s'` | +//! +//! Each capture starts with the command's own echo, as a successful one does. The unbounded +//! `zzzz` also carried a symbol warning the bounded one did not, because it ran first and the +//! engine loads the image's symbols on first use: a capture is whatever the call printed, not only +//! the complaint. +//! +//! **And these do not fail at all**, which is the half to know before asserting on a refusal: +//! `dd 0 L4` answers `????????` four times, `dt ntdll!_NOPE` answers `Symbol ntdll!_NOPE not +//! found.`, `!nosuchextension` answers `No export nosuchextension found`, and `x ntdll!Nope` and +//! `lm m nope` answer with no match — every one of them `Ok`. Among the lookups measured, then, an +//! argument the expression evaluator cannot resolve fails, while a command that looked something up +//! and found nothing succeeds and says so. That is a reading of the commands in this file, not a +//! rule the engine documents. +//! +//! ```text +//! cargo run --example failed_command_output -- [] +//! ``` +//! +//! With a second dump it also adds that dump as a second system (`.opendump`) and asks for it +//! before any wait has loaded it, which is the `||1s` case. Any user-mode dump will do for both. +//! +//! **The engine has to be in `target/debug/examples`** — see `breakpoint_probe.rs`. Nothing here +//! depends on symbols, but the answer is a reading of whichever `dbgeng.dll` loaded, so the first +//! thing printed is its version. + +use dbgscope::dbgeng::{DbgEngError, DebugEngine}; + +/// Long enough for the engine to read a dump off a cold disk. A bound, not a measurement. +const WAIT_MS: u32 = 60_000; + +/// What `execute_command_bounded` is given. Nothing here should take more than a moment. +const BOUND_MS: u32 = 10_000; + +fn main() { + let mut args = std::env::args().skip(1); + let Some(first) = args.next() else { + println!("usage: failed_command_output []"); + return; + }; + let second = args.next(); + + let engine = DebugEngine::new(); + if let Err(e) = engine.open_dump(&first) { + println!("could not open {first}: {e}"); + return; + } + if let Err(e) = engine.wait_for_event(WAIT_MS) { + println!("the load wait failed: {e}"); + return; + } + match engine.execute_command("version") { + Ok(text) => text + .lines() + .filter(|line| line.contains("dbgeng") || line.contains("Version")) + .for_each(|line| println!("engine: {}", line.trim())), + Err(e) => println!("engine: `version` failed: {e}"), + } + + // A mistyped command, on both of the paths a caller's text takes. + unbounded(&engine, "zzzz"); + bounded(&engine, "zzzz"); + // Output the command list produced before the segment that failed. + bounded(&engine, ".echo before the failure; zzzz"); + // Which failures come back as an error at all. Each of these names something that is not + // there, and the engine says so in every case; what differs is whether `Execute` also fails. + for command in [ + "dd 0 L4", + "? ntdll!Nope", + "u ntdll!Nope", + "dd ntdll!Nope", + "x ntdll!Nope", + "dt ntdll!_NOPE", + "lm m nope", + "!nosuchextension", + ] { + bounded(&engine, command); + } + // Execution control on a target that cannot run. + match engine.execute_and_wait("g", BOUND_MS) { + Ok(run) => println!("\n== execute_and_wait `g`: Ok\n{}", run.output), + Err(e) => failed("execute_and_wait `g`", &e), + } + + if let Some(second) = second { + bounded(&engine, &format!(".opendump {second}")); + bounded(&engine, "||"); + // Named before any wait has loaded it. + bounded(&engine, "||1s"); + } +} + +fn unbounded(engine: &DebugEngine, command: &str) { + match engine.execute_command(command) { + Ok(text) => println!("\n== execute_command `{command}`: Ok\n{text}"), + Err(e) => failed(&format!("execute_command `{command}`"), &e), + } +} + +fn bounded(engine: &DebugEngine, command: &str) { + match engine.execute_command_bounded(command, BOUND_MS) { + Ok(run) => println!( + "\n== execute_command_bounded `{command}`: Ok (cut short: {:?})\n{}", + run.cut_short, run.output + ), + Err(e) => failed(&format!("execute_command_bounded `{command}`"), &e), + } +} + +fn failed(what: &str, error: &DbgEngError) { + println!("\n== {what}: Err `{error}`"); + match error.output() { + Some(output) => println!("captured {} bytes:\n{output:?}", output.len()), + None => println!("no capture on this error"), + } +} diff --git a/src/dbgeng.rs b/src/dbgeng.rs index cb100e5..0d1a2f5 100644 --- a/src/dbgeng.rs +++ b/src/dbgeng.rs @@ -154,6 +154,32 @@ pub enum DbgEngError { #[error("Debug command failed: {0}")] CommandFailed(windows::core::Error), + /// [`Self::CommandFailed`] with what the engine printed while the command ran. + /// + /// The five calls that capture output — [`DebugEngine::execute_command`], + /// [`DebugEngine::execute_command_bounded`], [`DebugEngine::execute_and_wait`], + /// [`DebugEngine::settle`] and [`DebugEngine::run_to_address`] — answer with this one rather + /// than that one when `Execute` refuses the text or the wait after it fails, because the code + /// alone says very little. `0x80040205` is DbgEng's answer to a mistyped command, to an argument naming + /// nothing, to `g` on a dump and to `||1s` naming a system not yet loaded, while the engine's + /// own line says which: `Couldn't resolve error at 'ntdll!Nope'`, `^ No runnable debuggees + /// error in 'g'`, `^ Illegal debuggee error in '||1s'`. That line is printed into this call's + /// capture, beside whatever earlier segments of the command printed, so it was in hand and + /// thrown away with the buffer. Measured by `examples/failed_command_output.rs`. + /// + /// **Not every failure comes back this way.** Some the engine prints and then returns success + /// for — `dt` of a type that does not exist, an extension command that does not exist — so they + /// arrive as an ordinary `Ok` with the complaint in the text. This is for the ones that return + /// an error. The message is [`Self::CommandFailed`]'s word for word, so a caller rendering + /// errors as text sees no change until it asks for [`Self::output`]. + #[error("Debug command failed: {source}")] + CommandFailedWithOutput { + source: windows::core::Error, + /// Everything the engine printed during the call, the command's echo included. Empty when + /// it printed nothing, which is itself an answer. + output: String, + }, + #[error("Symbol path operation failed: {0}")] SymbolPathFailed(windows::core::Error), @@ -280,6 +306,34 @@ pub enum DbgEngError { ContextFromAnotherTarget, } +impl DbgEngError { + /// What the engine printed during the call that failed, where the failure carries it. + /// + /// `None` is "this failure had no capture", not "the engine printed nothing" — an empty + /// capture is `Some("")`. Only [`Self::CommandFailedWithOutput`] answers `Some`. + pub fn output(&self) -> Option<&str> { + match self { + Self::CommandFailedWithOutput { output, .. } => Some(output), + _ => None, + } + } +} + +/// `error`, carrying what the engine printed during the call that produced it. +/// +/// Only [`DbgEngError::CommandFailed`] is rewritten, because it is the one these paths produce for +/// a failed `Execute` or a failed wait; anything else is already a different statement and is +/// handed back as it came. +fn printed(error: DbgEngError, output: &[u8]) -> DbgEngError { + match error { + DbgEngError::CommandFailed(source) => DbgEngError::CommandFailedWithOutput { + source, + output: String::from_utf8_lossy(output).to_string(), + }, + other => other, + } +} + /// Fallback length of `_EPROCESS::ImageFileName` when the field's own size cannot be read. /// /// 15 bytes on every Windows version this can attach to. Only reached when symbols answer the @@ -5919,7 +5973,7 @@ impl DebugEngine { let _ = self.client.SetOutputCallbacks(None); } - result.map_err(DbgEngError::CommandFailed)?; + result.map_err(|source| printed(DbgEngError::CommandFailed(source), &output_buffer))?; Ok(String::from_utf8_lossy(&output_buffer).to_string()) } @@ -6026,7 +6080,7 @@ impl DebugEngine { // A watchdog-forced interrupt makes `Execute` fail (or return partial output); that is // expected, so only propagate a genuine (non-interrupted) error. if !interrupted { - result.map_err(DbgEngError::CommandFailed)?; + result.map_err(|source| printed(DbgEngError::CommandFailed(source), &output_buffer))?; } Ok(CommandRun { @@ -6321,8 +6375,8 @@ impl DebugEngine { // As there: consume anything the engine did not, so the next operation starts clean. let _ = self.interrupted(); } else if !target_gone { - exec.map_err(DbgEngError::CommandFailed)?; - waited?; + exec.map_err(|source| printed(DbgEngError::CommandFailed(source), &output_buffer))?; + waited.map_err(|error| printed(error, &output_buffer))?; } Ok(CommandRun { @@ -6467,7 +6521,7 @@ impl DebugEngine { if interrupted { let _ = self.interrupted(); } else if !target_gone { - waited?; + waited.map_err(|error| printed(error, &output_buffer))?; } Ok(Some(CommandRun { @@ -6592,8 +6646,8 @@ impl DebugEngine { output, }); } - exec.map_err(DbgEngError::CommandFailed)?; - waited?; + exec.map_err(|source| printed(DbgEngError::CommandFailed(source), output.as_bytes()))?; + waited.map_err(|error| printed(error, output.as_bytes()))?; if expired { // The watchdog has already broken the target in, so the caller is not left with a @@ -14475,6 +14529,55 @@ mod tests { let _ = e.end_session(); } + /// A command the engine refuses comes back with what it printed, on each of the three paths a + /// caller's text takes — and the line saying *why* is in it. + /// + /// `0x80040205` on its own is the same answer for a mistyped command, an argument naming + /// nothing and `||1s` on a system not yet loaded; the engine's line is the only thing that + /// tells them apart (`examples/failed_command_output.rs`). Pinned on an argument naming nothing + /// because that line quotes the caller's own text back, so the assertion does not depend on + /// how a given engine version words its parse errors. The `.echo` ahead of it is the other + /// half: output from a segment that ran before the one that failed survives as well. + #[test] + #[cfg(not(miri))] + fn test_a_refused_command_keeps_what_the_engine_printed() { + let _debuggee = one_debuggee(); + let e = DebugEngine::new(); + e.launch_process("cmd.exe /c ping -n 30 127.0.0.1") + .expect("launch failed"); + + let command = ".echo before the failure; ? nowhere!Nope"; + let paths = [ + ("execute_command", e.execute_command(command).map(|_| ())), + ( + "execute_command_bounded", + e.execute_command_bounded(command, 10_000).map(|_| ()), + ), + ( + "execute_and_wait", + e.execute_and_wait(command, 10_000).map(|_| ()), + ), + ]; + for (path, outcome) in paths { + let error = match outcome { + Ok(()) => panic!("{path}: `{command}` succeeded, so nothing here is under test"), + Err(error) => error, + }; + let printed = error + .output() + .unwrap_or_else(|| panic!("{path}: the failure carried no capture: {error:?}")); + assert!( + printed.contains("before the failure"), + "{path}: what the first segment printed was lost: {printed:?}" + ); + assert!( + printed.contains("Couldn't resolve error at 'nowhere!Nope'"), + "{path}: the engine's reason was not in the capture: {printed:?}" + ); + } + e.end_session().expect("end_session failed"); + } + /// Serializes the tests that build a [`DebugEngine`]. /// /// dbgeng holds **one debuggee session per process** and `DebugEngine::drop` ends it, so