Skip to content

Commit b81da69

Browse files
novafacingnovafacing
committed
Fix some logging and debug issues
1 parent f6603b6 commit b81da69

File tree

6 files changed

+64
-46
lines changed

6 files changed

+64
-46
lines changed

‎src/haps/mod.rs‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,7 @@ impl Tsffs {
5757
self.save_initial_snapshot()?;
5858
// Collect windows coverage info if enabled
5959
if self.windows && self.symbolic_coverage {
60+
info!(self.as_conf_object(), "Collecting initial coverage info");
6061
self.windows_os_info.collect(
6162
start_processor_raw,
6263
&self.debuginfo_download_directory,
@@ -216,6 +217,7 @@ impl Tsffs {
216217

217218
// Collect windows coverage info if enabled
218219
if self.windows && self.symbolic_coverage {
220+
info!(self.as_conf_object(), "Collecting initial coverage info");
219221
self.windows_os_info.collect(
220222
processor,
221223
&self.debuginfo_download_directory,
@@ -258,6 +260,7 @@ impl Tsffs {
258260

259261
// Collect windows coverage info if enabled
260262
if self.windows && self.symbolic_coverage {
263+
info!(self.as_conf_object(), "Collecting initial coverage info");
261264
self.windows_os_info.collect(
262265
processor,
263266
&self.debuginfo_download_directory,

‎src/lib.rs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -515,6 +515,7 @@ pub(crate) struct Tsffs {
515515
solutions: usize,
516516

517517
windows_os_info: WindowsOsInfo,
518+
cr3_cache: HashMap<i32, i64>,
518519
}
519520

520521
impl ClassObjectsFinalize for Tsffs {
@@ -707,7 +708,7 @@ impl Tsffs {
707708
}
708709

709710
// Disable VMP if it is enabled
710-
info!("Disabling VMP");
711+
info!(self.as_conf_object(), "Disabling VMP");
711712
if let Err(e) = run_command("disable-vmp") {
712713
warn!(self.as_conf_object(), "Failed to disable VMP: {}", e);
713714
}
@@ -968,7 +969,7 @@ fn init() {
968969
)
969970
"#})
970971
.map_err(|e| {
971-
error!("{e}");
972+
error!(tsffs, "{e}");
972973
e
973974
})
974975
.expect("Failed to run python");

‎src/os/windows/debug_info.rs‎

Lines changed: 19 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,7 @@ use std::{
1111
};
1212

1313
use lending_iterator::{windows_mut, LendingIterator};
14-
use simics::{debug, info, ConfObject};
14+
use simics::{debug, get_object, info, ConfObject};
1515
use windows::Win32::System::{
1616
Diagnostics::Debug::{
1717
IMAGE_DEBUG_DIRECTORY, IMAGE_DEBUG_TYPE_CODEVIEW, IMAGE_DIRECTORY_ENTRY_DEBUG,
@@ -46,7 +46,10 @@ impl<'a> DebugInfo<'a> {
4646
P: AsRef<Path>,
4747
{
4848
if let Some(info) = user_debug_info.get(name) {
49-
debug!("Have user-provided debug info for {name}");
49+
debug!(
50+
get_object("tsffs")?,
51+
"Have user-provided debug info for {name}"
52+
);
5053
let exe_path = info[0].clone();
5154
let pdb_path = info[1].clone();
5255

@@ -115,7 +118,7 @@ impl<'a> DebugInfo<'a> {
115118
.join(format!("{}.exe", &exe_guid));
116119

117120
if !exe_path.exists() && !not_found_full_name_cache.contains(name) {
118-
info!("Downloading PE file from {}", exe_url);
121+
info!(get_object("tsffs")?, "Downloading PE file from {}", exe_url);
119122
match get(&exe_url)?.error_for_status() {
120123
Ok(response) => {
121124
let mut file = File::create(&exe_path)?;
@@ -135,7 +138,10 @@ impl<'a> DebugInfo<'a> {
135138

136139
if !pdb_path.exists() && !not_found_full_name_cache.contains(cv_info_pdb70.file_name())
137140
{
138-
info!("Downloading PDB file from {}", pdb_url);
141+
info!(
142+
get_object("tsffs")?,
143+
"Downloading PDB file from {}", pdb_url
144+
);
139145
match get(&pdb_url)?.error_for_status() {
140146
Ok(response) => {
141147
let mut file = File::create(&pdb_path)?;
@@ -177,7 +183,10 @@ impl<'a> DebugInfo<'a> {
177183
P: AsRef<Path>,
178184
{
179185
if let Some(info) = user_debug_info.get(name) {
180-
debug!("Have user-provided debug info for {name}");
186+
debug!(
187+
get_object("tsffs")?,
188+
"Have user-provided debug info for {name}"
189+
);
181190
let exe_path = info[0].clone();
182191
let pdb_path = info[1].clone();
183192

@@ -257,7 +266,7 @@ impl<'a> DebugInfo<'a> {
257266
.join(format!("{}.exe", &exe_guid));
258267

259268
if !exe_path.exists() && !not_found_full_name_cache.contains(name) {
260-
info!("Downloading PE file from {}", exe_url);
269+
info!(get_object("tsffs")?, "Downloading PE file from {}", exe_url);
261270
match get(&exe_url)?.error_for_status() {
262271
Ok(response) => {
263272
let mut file = File::create(&exe_path)?;
@@ -279,7 +288,10 @@ impl<'a> DebugInfo<'a> {
279288

280289
if !pdb_path.exists() && !not_found_full_name_cache.contains(cv_info_pdb70.file_name())
281290
{
282-
info!("Downloading PDB file from {}", pdb_url);
291+
info!(
292+
get_object("tsffs")?,
293+
"Downloading PDB file from {}", pdb_url
294+
);
283295
match get(&pdb_url)?.error_for_status() {
284296
Ok(response) => {
285297
let mut file = File::create(&pdb_path)?;

‎src/os/windows/kernel.rs‎

Lines changed: 13 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ use std::{
55

66
use anyhow::{anyhow, bail, Result};
77
use pdb::{FallibleIterator, SymbolData};
8-
use simics::{debug, get_attribute, ConfObject};
8+
use simics::{debug, get_attribute, get_object, ConfObject};
99
use vergilius::bindings::*;
1010
use windows::Win32::System::{
1111
Diagnostics::Debug::{IMAGE_DIRECTORY_ENTRY_EXPORT, IMAGE_NT_HEADERS64},
@@ -55,7 +55,7 @@ pub fn page_is_kernel(processor: *mut ConfObject, address: u64) -> Result<bool>
5555
);
5656

5757
if nt_header.FileHeader.SizeOfOptionalHeader == 0 {
58-
debug!("Optional header size was 0");
58+
debug!(get_object("tsffs")?, "Optional header size was 0");
5959
return Ok(false);
6060
}
6161

@@ -74,7 +74,7 @@ pub fn page_is_kernel(processor: *mut ConfObject, address: u64) -> Result<bool>
7474

7575
let image_size = nt_header.OptionalHeader.SizeOfImage as u64;
7676

77-
debug!("Image size is {:#x}", image_size);
77+
debug!(get_object("tsffs")?, "Image size is {:#x}", image_size);
7878

7979
let export_header_offset = nt_header.OptionalHeader.DataDirectory
8080
[IMAGE_DIRECTORY_ENTRY_EXPORT.0 as usize]
@@ -108,7 +108,7 @@ pub fn page_is_kernel(processor: *mut ConfObject, address: u64) -> Result<bool>
108108

109109
let name = read_nul_terminated_string(processor, address + export_directory.Name as u64)?;
110110

111-
debug!("Read image name {}", name);
111+
debug!(get_object("tsffs")?, "Read image name {}", name);
112112

113113
if name == "ntoskrnl.exe" {
114114
return Ok(true);
@@ -147,11 +147,14 @@ pub fn find_kernel_with_idt(processor: *mut ConfObject, build: u32) -> Result<u6
147147
sim_idtr_base + (i * std::mem::size_of::<IdtEntry64>() as u64),
148148
)?;
149149
if !idtr_entry0.present() {
150-
debug!("Entry {} not present, skipping", i);
150+
debug!(get_object("tsffs")?, "Entry {} not present, skipping", i);
151151
continue;
152152
}
153153
let idtr_entry0_offset = idtr_entry0.offset();
154-
debug!("Got valid IDT entry with offset {:#x}", idtr_entry0_offset);
154+
debug!(
155+
get_object("tsffs")?,
156+
"Got valid IDT entry with offset {:#x}", idtr_entry0_offset
157+
);
155158
return find_kernel(
156159
processor,
157160
idtr_entry0_offset,
@@ -261,7 +264,10 @@ impl KernelInfo {
261264
P: AsRef<Path>,
262265
{
263266
let list_address = self.find_ps_loaded_module_list_address()?;
264-
debug!("PsLoadedModuleList: {:#x}", list_address);
267+
debug!(
268+
get_object("tsffs")?,
269+
"PsLoadedModuleList: {:#x}", list_address
270+
);
265271
let list = read_virtual::<LIST_ENTRY>(processor, list_address)?;
266272
let mut modules = Vec::new();
267273

‎src/os/windows/mod.rs‎

Lines changed: 25 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@ use intervaltree::IntervalTree;
55
use kernel::{find_kernel_with_idt, KernelInfo};
66
use raw_cstr::AsRawCstr;
77
use simics::{
8-
get_interface, get_processor_number, sys::cpu_cb_handle_t, ConfObject,
8+
get_interface, get_object, get_processor_number, info, sys::cpu_cb_handle_t, ConfObject,
99
CpuInstrumentationSubscribeInterface, IntRegisterInterface, ProcessorInfoV2Interface,
1010
};
1111
use std::{
@@ -73,10 +73,12 @@ impl WindowsOsInfo {
7373
where
7474
P: AsRef<Path>,
7575
{
76+
info!(get_object("tsffs")?, "Collecting Windows OS information");
7677
let processor_nr = get_processor_number(processor)?;
7778
let mut processor_info_v2: ProcessorInfoV2Interface = get_interface(processor)?;
7879

7980
if self.kernel_info.is_none() {
81+
info!(get_object("tsffs")?, "Collecting kernel information");
8082
// Make sure we're running 64-bit Windows
8183
ensure!(
8284
processor_info_v2.get_logical_address_width()? == 64,
@@ -100,6 +102,8 @@ impl WindowsOsInfo {
100102
let _ = WindowsKpcr::new(processor, maj, min, build)?;
101103
let kernel_base = find_kernel_with_idt(processor, build)?;
102104

105+
info!(get_object("tsffs")?, "Found kernel base {kernel_base:#x}");
106+
103107
self.kernel_info = Some(KernelInfo::new(
104108
processor,
105109
"ntoskrnl.exe",
@@ -110,6 +114,8 @@ impl WindowsOsInfo {
110114
)?);
111115
}
112116

117+
info!(get_object("tsffs")?, "Collecting process list");
118+
113119
self.processes.insert(
114120
processor_nr,
115121
self.kernel_info
@@ -123,6 +129,8 @@ impl WindowsOsInfo {
123129
)?,
124130
);
125131

132+
info!(get_object("tsffs")?, "Collecting module list");
133+
126134
self.modules.insert(
127135
processor_nr,
128136
self.kernel_info
@@ -179,41 +187,39 @@ impl WindowsOsInfo {
179187
}
180188
}
181189

182-
#[ffi(expect, self_ty = "*mut std::ffi::c_void")]
183-
impl Tsffs {
184-
#[ffi(arg(rest), arg(self))]
185-
pub fn on_instruction_before_symcov(
186-
&mut self,
187-
_obj: *mut ConfObject,
188-
cpu: *mut ConfObject,
189-
_handle: *mut simics::sys::instruction_handle_t,
190-
) -> Result<()> {
191-
let cpu_nr = get_processor_number(cpu)?;
192-
193-
Ok(())
194-
}
195-
}
196-
197190
impl Tsffs {
198191
pub fn on_control_register_write_windows_symcov(
199192
&mut self,
200193
trigger_obj: *mut ConfObject,
201194
register_nr: i64,
202-
_value: i64,
195+
value: i64,
203196
) -> Result<()> {
204197
let mut int_register: IntRegisterInterface = get_interface(trigger_obj)?;
198+
let processor_nr = get_processor_number(trigger_obj)?;
205199

206-
// Check if the register was CR3
207-
if self.windows
200+
if self.processors.contains_key(&processor_nr)
201+
&& self.coverage_enabled
202+
&& self.windows
208203
&& self.symbolic_coverage
209204
&& register_nr == int_register.get_number("cr3".as_raw_cstr()?)? as i64
205+
&& self
206+
.cr3_cache
207+
.get(&processor_nr)
208+
.is_some_and(|v| *v != value)
210209
{
210+
info!(
211+
get_object("tsffs")?,
212+
"Got write {value:#x} to CR3 for processor {processor_nr}, refreshing kernel & process mappings"
213+
);
214+
211215
self.windows_os_info.collect(
212216
trigger_obj,
213217
&self.debuginfo_download_directory,
214218
self.guess_pdb_function_size,
215219
&self.debug_info,
216220
)?;
221+
222+
self.cr3_cache.insert(processor_nr, value);
217223
}
218224

219225
Ok(())

‎src/os/windows/structs.rs‎

Lines changed: 1 addition & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@ use std::{
66

77
use anyhow::{anyhow, bail, ensure, Result};
88
use raw_cstr::AsRawCstr;
9-
use simics::{debug, get_attribute, get_interface, ConfObject, IntRegisterInterface};
9+
use simics::{debug, get_attribute, get_interface, get_object, ConfObject, IntRegisterInterface};
1010
use vergilius::bindings::*;
1111
use windows::Win32::{Foundation::UNICODE_STRING, System::Kernel::LIST_ENTRY};
1212

@@ -68,12 +68,8 @@ impl WindowsKpcr {
6868
let ia32_kernel_gs_base = int_register.read(ia32_kernel_gs_base_nr)?;
6969
let ia32_gs_base = int_register.read(ia32_gs_base_nr)?;
7070
let sim_idtr_base: u64 = get_attribute(processor, "idtr_base")?.try_into()?;
71-
debug!("Got SIM IDTR Base {:#x}", sim_idtr_base);
7271

7372
let kpcr_address = max(ia32_gs_base, ia32_kernel_gs_base);
74-
debug!("Got KPCR address {:#x}", kpcr_address);
75-
76-
debug!("Initializing KPCR for Windows {}.{}.{}", maj, min, build);
7773

7874
match (maj, min, build) {
7975
(10, 0, 10240) => {
@@ -370,8 +366,6 @@ impl WindowsKprcb {
370366
build: u32,
371367
kpcrb_address: u64,
372368
) -> Result<Self> {
373-
debug!("Initializing KPRCB for Windows {}.{}.{}", maj, min, build);
374-
375369
match (maj, min, build) {
376370
(10, 0, 10240) => {
377371
let kprcb =
@@ -2326,7 +2320,6 @@ impl WindowsTeb {
23262320
WindowsTeb::Windows10_0_22621_382 { teb } => teb.ProcessEnvironmentBlock as u64,
23272321
WindowsTeb::Windows10_0_22631_2428 { teb } => teb.ProcessEnvironmentBlock as u64,
23282322
};
2329-
debug!("peb_address: {:#x}", peb_address);
23302323
WindowsPeb::new(processor, major, minor, build, peb_address)
23312324
}
23322325
}
@@ -2762,7 +2755,6 @@ impl WindowsEProcess {
27622755
WindowsEProcess::Windows10_0_22621_382 { eprocess } => eprocess.Pcb.DirectoryTableBase,
27632756
WindowsEProcess::Windows10_0_22631_2428 { eprocess } => eprocess.Pcb.DirectoryTableBase,
27642757
};
2765-
debug!("Using directory table base {:#x}", directory_table_base);
27662758

27672759
if directory_table_base == 0 {
27682760
directory_table_base = match self {
@@ -2806,12 +2798,10 @@ impl WindowsEProcess {
28062798
eprocess.Pcb.UserDirectoryTableBase
28072799
}
28082800
};
2809-
debug!("Invalid DTB, using user DTB: {:#x}", directory_table_base);
28102801
}
28112802

28122803
let mut modules = Vec::new();
28132804

2814-
debug!("PEB ADDRESS: {:x}", peb_address);
28152805
if peb_address != 0 {
28162806
let peb = WindowsPeb::new_dtb(
28172807
processor,

0 commit comments

Comments
 (0)