From d27f5265a10a1b43d483031c0441bc725c038a8d Mon Sep 17 00:00:00 2001 From: memN0ps <89628341+memN0ps@users.noreply.github.com> Date: Wed, 24 Jan 2024 19:32:28 +1300 Subject: [PATCH] Edited log statements --- driver/src/hook.rs | 4 +++- driver/src/lib.rs | 26 ++++++++++---------- hypervisor/src/intel/descriptor.rs | 16 ++++++------- hypervisor/src/intel/ept/hooks.rs | 30 +++++++++++------------- hypervisor/src/intel/ept/mtrr.rs | 4 ++-- hypervisor/src/intel/ept/paging.rs | 4 ++-- hypervisor/src/intel/msr_bitmap.rs | 6 ++--- hypervisor/src/intel/shared_data.rs | 4 ++-- hypervisor/src/intel/vcpu.rs | 16 ++++++------- hypervisor/src/intel/vmcs.rs | 24 ++++++++++++++----- hypervisor/src/intel/vmexit/cpuid.rs | 16 ++++++++----- hypervisor/src/intel/vmexit/ept.rs | 16 +++++++++---- hypervisor/src/intel/vmexit/exception.rs | 17 +++++++++----- hypervisor/src/intel/vmexit/invd.rs | 6 ++++- hypervisor/src/intel/vmexit/invept.rs | 4 ++++ hypervisor/src/intel/vmexit/invvpid.rs | 4 ++++ hypervisor/src/intel/vmexit/mod.rs | 30 +++++++++--------------- hypervisor/src/intel/vmexit/msr.rs | 10 +++++--- hypervisor/src/intel/vmexit/rdtsc.rs | 4 ++++ hypervisor/src/intel/vmexit/xsetbv.rs | 6 ++++- hypervisor/src/intel/vmm.rs | 12 +++++----- hypervisor/src/intel/vmstack.rs | 6 ++--- hypervisor/src/intel/vmx.rs | 28 ++++++++++------------ hypervisor/src/intel/vmxon.rs | 15 ++++++------ hypervisor/src/utils/function_hook.rs | 19 ++++++++++----- hypervisor/src/utils/nt.rs | 2 +- hypervisor/src/utils/processor.rs | 8 +++---- 27 files changed, 192 insertions(+), 145 deletions(-) diff --git a/driver/src/hook.rs b/driver/src/hook.rs index a929298..a065d66 100644 --- a/driver/src/hook.rs +++ b/driver/src/hook.rs @@ -36,10 +36,12 @@ type MmIsAddressValidType = extern "C" fn(u64) -> bool; /// The caller must ensure this is the case to avoid undefined behavior. pub extern "C" fn mm_is_address_valid(ptr: u64) -> bool { // Log the address from which `MmIsAddressValid` was called. - log::info!("MmIsAddressValid called from {:#x}", unsafe { + log::trace!("MmIsAddressValid called from {:#x}", unsafe { return_address().read_volatile() // Reads the return address in a volatile manner to prevent optimizations. }); + log::debug!("First Parameter Value: {:x}", ptr); + // Load the original function pointer from the global atomic pointer. let fn_ptr = ORIGINAL.load(Ordering::Relaxed); // Using relaxed ordering for atomic loading. // Transmute the function pointer to the expected function type. diff --git a/driver/src/lib.rs b/driver/src/lib.rs index b260f03..500ec6c 100644 --- a/driver/src/lib.rs +++ b/driver/src/lib.rs @@ -75,19 +75,20 @@ pub unsafe extern "system" fn driver_entry( // This logger writes to the host OS via VMware Workstation. // Initialize the COM2 port logger with level filter set to Info. + com_logger::builder() .base(0x2f8) - .filter(LevelFilter::Trace) + .filter(LevelFilter::Debug) .setup(); - log::info!("Driver Entry called"); + log::debug!("Driver Entry called"); // Remove if manually mapping the kernel driver driver.DriverUnload = Some(driver_unload); with_expanded_stack(|| { - match virtualize() { - Ok(_) => log::info!("Virtualization successful!"), + match virtualize_system() { + Ok(_) => log::info!("Virtualized system successfully!"), Err(err) => { log::error!("Virtualization failed: {:?}", err); return STATUS_UNSUCCESSFUL; @@ -96,7 +97,7 @@ pub unsafe extern "system" fn driver_entry( // Test the hooks // - log::info!("Calling MmIsAddressValid to test EPT hook..."); + log::debug!("Calling MmIsAddressValid to test EPT hook..."); unsafe { MmIsAddressValid(0 as _) }; STATUS_SUCCESS @@ -114,7 +115,7 @@ pub unsafe extern "system" fn driver_entry( /// /// Note: Remove if manually mapping the kernel driver pub extern "C" fn driver_unload(_driver: *mut DRIVER_OBJECT) { - log::info!("Driver unloaded successfully!"); + log::trace!("Driver unloaded successfully!"); if let Some(mut hypervisor) = unsafe { HYPERVISOR.take() } { drop(hypervisor); } @@ -136,7 +137,7 @@ static mut HYPERVISOR: Option = None; /// * `None` if there was an error during virtualization. /// /// Credits: Jess / jessiep_ -fn virtualize() -> Result<(), HypervisorError> { +fn virtualize_system() -> Result<(), HypervisorError> { // Initialize the hook and hook manager // let hook = Hook::hook_function("MmIsAddressValid", hook::mm_is_address_valid as *const ()) @@ -151,16 +152,15 @@ fn virtualize() -> Result<(), HypervisorError> { let mut secondary_ept: Box = unsafe { Box::try_new_zeroed_in(PhysicalAllocator)?.assume_init() }; - log::info!("Creating Primary EPT"); + log::debug!("Creating Primary EPT"); primary_ept.identity_2mb(AccessType::READ_WRITE_EXECUTE)?; - log::info!("Creating Secondary EPT"); + log::debug!("Creating Secondary EPT"); secondary_ept.identity_2mb(AccessType::READ_WRITE_EXECUTE)?; - log::info!("Enabling hooks"); + log::debug!("Enabling hooks"); hook_manager.enable_hooks(&mut primary_ept, &mut secondary_ept)?; - log::info!("Building hypervisor"); let mut hv = match Hypervisor::builder() .primary_ept(primary_ept) .secondary_ept(secondary_ept) @@ -174,8 +174,8 @@ fn virtualize() -> Result<(), HypervisorError> { // Update NTOSKRNL_CR3 to ensure correct CR3 in case of execution within a user-mode process via DPC. update_ntoskrnl_cr3(); - match hv.virtualize_system() { - Ok(_) => log::info!("Successfully virtualized system!"), + match hv.virtualize_core() { + Ok(_) => log::info!("Virtualized cores successfully!"), Err(err) => return Err(err), }; diff --git a/hypervisor/src/intel/descriptor.rs b/hypervisor/src/intel/descriptor.rs index d48a1ff..536dfa3 100644 --- a/hypervisor/src/intel/descriptor.rs +++ b/hypervisor/src/intel/descriptor.rs @@ -37,7 +37,7 @@ impl DescriptorTables { pub fn initialize_for_guest( descriptor_tables: &mut Box, ) -> Result<(), HypervisorError> { - log::info!("Capturing current Global Descriptor Table (GDT) and Interrupt Descriptor Table (IDT) for guest"); + log::trace!("Capturing current Global Descriptor Table (GDT) and Interrupt Descriptor Table (IDT) for guest"); // Capture the current GDT and IDT. descriptor_tables.gdtr = sgdt(); @@ -46,7 +46,7 @@ impl DescriptorTables { // Note: We don't need to create new tables for the guest; // we just capture the current ones. - log::info!("Captured GDT and IDT for guest successfully!"); + log::trace!("Captured GDT and IDT for guest successfully!"); Ok(()) } @@ -55,18 +55,18 @@ impl DescriptorTables { pub fn initialize_for_host( descriptor_tables: &mut Box, ) -> Result<(), HypervisorError> { - log::info!("Initializing descriptor tables for host"); + log::trace!("Initializing descriptor tables for host"); descriptor_tables.copy_current_gdt(); descriptor_tables.copy_current_idt(); - log::info!("Initialized descriptor tables for host"); + log::trace!("Initialized descriptor tables for host"); Ok(()) } /// Copies the current GDT. fn copy_current_gdt(&mut self) { - log::info!("Copying current GDT"); + log::trace!("Copying current GDT"); // Get the current GDTR let current_gdtr = sgdt(); @@ -83,12 +83,12 @@ impl DescriptorTables { // Store the new GDT in the DescriptorTables structure self.global_descriptor_table = new_gdt; self.gdtr = new_gdtr; - log::info!("Copied current GDT"); + log::trace!("Copied current GDT"); } /// Copies the current IDT. fn copy_current_idt(&mut self) { - log::info!("Copying current IDT"); + log::trace!("Copying current IDT"); // Get the current IDTR let current_idtr = sidt(); @@ -105,7 +105,7 @@ impl DescriptorTables { // Store the new IDT in the DescriptorTables structure self.interrupt_descriptor_table = new_idt; self.idtr = new_idtr; // Use the same IDTR as it points to the correct base and limit - log::info!("Copied current IDT"); + log::trace!("Copied current IDT"); } /// Gets the table as a slice from the pointer. diff --git a/hypervisor/src/intel/ept/hooks.rs b/hypervisor/src/intel/ept/hooks.rs index 9142d57..378d1a3 100644 --- a/hypervisor/src/intel/ept/hooks.rs +++ b/hypervisor/src/intel/ept/hooks.rs @@ -125,7 +125,6 @@ impl Hook { /// * `Option` - An instance of `Hook` if successful, or `None` if an error occurred. pub fn hook_function_ptr(function_ptr: u64, handler: *const ()) -> Option { let original_pa = PhysicalAddress::from_va(function_ptr); - log::info!("Obtained physical address: {:#x}", original_pa.as_u64()); // Copy the page where the function resides to prevent modifying the original page. let page = Self::copy_page(function_ptr)?; @@ -136,16 +135,16 @@ impl Hook { let hook_va = Self::address_in_page(page_va, function_ptr); let hook_pa = PhysicalAddress::from_va(hook_va); - log::info!("Handler address: {:#x}", handler as u64); + log::debug!("Handler address: {:#x}", handler as u64); - log::info!("Original virtual address: {:#x}", function_ptr); - log::info!("Original physical address: {:#x}", original_pa.as_u64()); + log::debug!("Original virtual address: {:#x}", function_ptr); + log::debug!("Original physical address: {:#x}", original_pa.as_u64()); - log::info!("Page virtual address: {:#x}", page_va); - log::info!("Page physical address: {:#x}", page_pa.as_u64()); + log::debug!("Page virtual address: {:#x}", page_va); + log::debug!("Page physical address: {:#x}", page_pa.as_u64()); - log::info!("Hook virtual address: {:#x}", hook_va); - log::info!("Hook physical address: {:#x}", hook_pa.as_u64()); + log::debug!("Hook virtual address: {:#x}", hook_va); + log::debug!("Hook physical address: {:#x}", hook_pa.as_u64()); // Create an inline hook at the new address in the copied page. let inline_hook = FunctionHook::new(function_ptr, hook_va, handler)?; @@ -185,8 +184,7 @@ impl Hook { return None; } - log::info!("Found function: {}", function_name); - log::info!("Address of ntoskrnl export: {:p}", address); + log::debug!("Function to be hooked: {} {:p}", function_name, address); // Utilize the previously defined function for hooking by address. Self::hook_function_ptr(address as u64, handler) @@ -284,13 +282,13 @@ impl HookManager { let original_page = hook.original_pa.align_down_to_large_page().as_u64(); let hooked_copy_page = hook.hook_pa.align_down_to_large_page().as_u64(); - log::info!( + log::debug!( "Splitting 2MB page to 4KB pages for Primary EPT: {:#x}", original_page ); primary_ept.split_2mb_to_4kb(original_page, AccessType::READ_WRITE_EXECUTE)?; - log::info!( + log::debug!( "Splitting 2MB page to 4KB pages for Secondary EPT: {:#x}", hooked_copy_page ); @@ -300,7 +298,7 @@ impl HookManager { let original_page = hook.original_pa.align_down_to_base_page().as_u64(); let hooked_copy_page = hook.hook_pa.align_down_to_base_page().as_u64(); - log::info!( + log::debug!( "Changing permissions for page to Read-Write (RW) only: {:#x}", original_page ); @@ -308,15 +306,15 @@ impl HookManager { // Modify the page permission in the primary EPT to ReadWrite. primary_ept.change_page_flags(original_page, AccessType::READ_WRITE)?; - log::info!( + log::debug!( "Changing permissions for hook page to Execute (X) only: {:#x}", hooked_copy_page ); - // Modify the page permission in the secondary EPT to Execute for the hook page. + // Modify the page permission in the secondary EPT to Execute for the original page. secondary_ept.change_page_flags(original_page, AccessType::EXECUTE)?; - log::info!("Mapping Guest Physical Address to Host Physical Address of the hooked page: {:#x} {:#x}", original_page, hooked_copy_page); + log::debug!("Mapping Guest Physical Address to Host Physical Address of the hooked page: {:#x} {:#x}", original_page, hooked_copy_page); secondary_ept.remap_page(original_page, hooked_copy_page, AccessType::EXECUTE)?; } diff --git a/hypervisor/src/intel/ept/mtrr.rs b/hypervisor/src/intel/ept/mtrr.rs index 6d6c8b8..9e6f9a2 100644 --- a/hypervisor/src/intel/ept/mtrr.rs +++ b/hypervisor/src/intel/ept/mtrr.rs @@ -52,7 +52,7 @@ impl Mtrr { }; descriptors.push(descriptor); - log::info!( + log::trace!( "MTRR Range: Base=0x{:x} End=0x{:x} Type={:?}", descriptor.base_address, descriptor.end_address, @@ -61,7 +61,7 @@ impl Mtrr { } } - log::info!("Total MTRR Ranges Committed: {}", descriptors.len()); + log::trace!("Total MTRR Ranges Committed: {}", descriptors.len()); Self { descriptors } } diff --git a/hypervisor/src/intel/ept/paging.rs b/hypervisor/src/intel/ept/paging.rs index b5a7d1c..a91c7a4 100644 --- a/hypervisor/src/intel/ept/paging.rs +++ b/hypervisor/src/intel/ept/paging.rs @@ -77,7 +77,7 @@ impl Ept { /// /// A `Result<(), HypervisorError>` indicating if the operation was successful. pub fn identity_2mb(&mut self, access_type: AccessType) -> Result<(), HypervisorError> { - log::info!("Creating identity map for 2MB pages"); + log::trace!("Creating identity map for 2MB pages"); let mut mtrr = Mtrr::new(); @@ -100,7 +100,7 @@ impl Ept { /// /// A `Result<(), HypervisorError>` indicating if the operation was successful. pub fn identity_4kb(&mut self, access_type: AccessType) -> Result<(), HypervisorError> { - log::info!("Creating identity map for 4KB pages"); + log::trace!("Creating identity map for 4KB pages"); let mut mtrr = Mtrr::new(); diff --git a/hypervisor/src/intel/msr_bitmap.rs b/hypervisor/src/intel/msr_bitmap.rs index 66318e8..bb527a3 100644 --- a/hypervisor/src/intel/msr_bitmap.rs +++ b/hypervisor/src/intel/msr_bitmap.rs @@ -44,7 +44,7 @@ impl MsrBitmap { /// # Returns /// * A `Result` indicating the success or failure of the setup process. pub fn new() -> Box { - log::info!("Setting up MSR Bitmap"); + log::trace!("Setting up MSR Bitmap"); let instance = Self { read_low_msrs: [0; 0x400], @@ -54,11 +54,11 @@ impl MsrBitmap { }; let mut instance = Box::::new_in(instance, PhysicalAllocator); - log::info!("Initializing MSR Bitmap"); + log::trace!("Initializing MSR Bitmap"); Self::initialize_bitmap(instance.as_mut() as *mut _ as _); - log::info!("MSR Bitmap setup successful!"); + log::trace!("MSR Bitmap setup successfully!"); instance } diff --git a/hypervisor/src/intel/shared_data.rs b/hypervisor/src/intel/shared_data.rs index 8203f9f..dab14ee 100644 --- a/hypervisor/src/intel/shared_data.rs +++ b/hypervisor/src/intel/shared_data.rs @@ -59,7 +59,7 @@ impl SharedData { secondary_ept: Box, hook_manager: Box, ) -> Result, HypervisorError> { - log::info!("Initializing shared data"); + log::trace!("Initializing shared data"); let primary_eptp = primary_ept.create_eptp_with_wb_and_4lvl_walk()?; let secondary_eptp = secondary_ept.create_eptp_with_wb_and_4lvl_walk()?; @@ -92,7 +92,7 @@ impl SharedData { primary_ept: Box, hook_manager: Box, ) -> Result>, HypervisorError> { - log::info!("Initializing shared data"); + log::trace!("Initializing shared data"); let primary_eptp = primary_ept.create_eptp_with_wb_and_4lvl_walk()?; diff --git a/hypervisor/src/intel/vcpu.rs b/hypervisor/src/intel/vcpu.rs index f27324e..b037a73 100644 --- a/hypervisor/src/intel/vcpu.rs +++ b/hypervisor/src/intel/vcpu.rs @@ -43,7 +43,7 @@ impl Vcpu { /// /// A `Result` containing the initialized VCPU instance or a `HypervisorError`. pub fn new(index: u32) -> Result { - log::info!("Creating processor {}", index); + log::trace!("Creating processor {}", index); Ok(Self { index, @@ -63,7 +63,7 @@ impl Vcpu { log::info!("Virtualizing processor {}", self.index); // Capture the current processor's context. The Guest will resume from this point since we capture and write this context to the guest state for each vcpu. - log::info!("Capturing context"); + log::trace!("Capturing context"); let mut context: MaybeUninit = MaybeUninit::uninit(); unsafe { RtlCaptureContext(context.as_mut_ptr() as _) }; @@ -73,7 +73,7 @@ impl Vcpu { // Determine if we're operating as the Host (root) or Guest (non-root). Only proceed with system virtualization if operating as the Host. if !is_virtualized() { // If we are here as Guest (non-root) then that will lead to undefined behavior (UB). - log::info!("Preparing for virtualization"); + log::trace!("Preparing for virtualization"); set_virtualized(); self.vmx @@ -86,7 +86,7 @@ impl Vcpu { log::info!("Virtualization complete for processor {}", self.index); - vmx.run(); + vmx.run(self.index); // We should never reach this point as the VM should have been launched. } @@ -111,13 +111,13 @@ impl Vcpu { pub fn devirtualize_cpu(&self) -> Result<(), HypervisorError> { // Determine if the processor is already devirtualized. if !is_virtualized() { - log::info!("Processor {} is already devirtualized", self.index); + log::trace!("Processor {} is already devirtualized", self.index); return Ok(()); } // Attempt to devirtualize the processor using the VMXOFF instruction. support::vmxoff()?; - log::info!("Processor {} has been devirtualized", self.index); + log::trace!("Processor {} has been devirtualized", self.index); Ok(()) } @@ -137,7 +137,7 @@ impl Vcpu { /// instructions. It ensures that any cached translations are consistent with the current state of the virtual /// processor and EPT configurations. pub fn invalidate_contexts() { - log::info!("Invalidating processor contexts"); + log::debug!("Invalidating processor contexts"); // Invalidate all contexts (broad operation, typically used in specific scenarios) // @@ -158,6 +158,6 @@ impl Vcpu { // Reference: 29.4.3.3 Guidelines for Use of the INVVPID Instruction invvpid_all_contexts(); - log::info!("Processor contexts invalidation successful!"); + log::debug!("Processor contexts invalidation successfully!"); } } diff --git a/hypervisor/src/intel/vmcs.rs b/hypervisor/src/intel/vmcs.rs index 9dbb26e..8aaf4a7 100644 --- a/hypervisor/src/intel/vmcs.rs +++ b/hypervisor/src/intel/vmcs.rs @@ -66,7 +66,7 @@ impl Vmcs { /// # Returns /// A result indicating success or an error. pub fn setup(vmcs_region: &mut Box) -> Result<(), HypervisorError> { - log::info!("Setting up VMCS region"); + log::debug!("Setting up VMCS region"); let vmcs_region_physical_address = PhysicalAddress::pa_from_va(vmcs_region.as_ref() as *const _ as _); @@ -75,8 +75,8 @@ impl Vmcs { return Err(HypervisorError::VirtualToPhysicalAddressFailed); } - log::info!("VMCS Region Virtual Address: {:p}", vmcs_region); - log::info!( + log::trace!("VMCS Region Virtual Address: {:p}", vmcs_region); + log::trace!( "VMCS Region Physical Addresss: 0x{:x}", vmcs_region_physical_address ); @@ -86,13 +86,13 @@ impl Vmcs { // Clear the VMCS region. vmclear(vmcs_region_physical_address); - log::info!("VMCLEAR successful!"); + log::trace!("VMCLEAR successful!"); // Load current VMCS pointer. vmptrld(vmcs_region_physical_address); - log::info!("VMPTRLD successful!"); + log::trace!("VMPTRLD successful!"); - log::info!("VMCS setup successful!"); + log::trace!("VMCS setup successfully!"); Ok(()) } @@ -108,6 +108,8 @@ impl Vmcs { /// * `guest_registers` - Guest registers for the guest. #[rustfmt::skip] pub fn setup_guest_registers_state(context: &CONTEXT, guest_descriptor_table: &Box, guest_registers: &mut GuestRegisters) { + log::debug!("Setting up Guest Registers State"); + unsafe { vmwrite(vmcs::guest::CR0, controlregs::cr0().bits() as u64) }; unsafe { vmwrite(vmcs::guest::CR3, controlregs::cr3()) }; vmwrite(vmcs::guest::CR4, Cr4::read_raw()); @@ -204,6 +206,8 @@ impl Vmcs { guest_registers.r13 = context.R13; guest_registers.r14 = context.R14; guest_registers.r15 = context.R15; + + log::debug!("Guest Registers State setup successfully!"); } /// Initialize the host state for the currently loaded VMCS. @@ -216,6 +220,8 @@ impl Vmcs { /// * `host_descriptor_table` - Descriptor tables for the host. #[rustfmt::skip] pub fn setup_host_registers_state(context: &CONTEXT, host_descriptor_table: &Box, host_paging: &Box) -> Result<(), HypervisorError> { + log::debug!("Setting up Host Registers State"); + unsafe { vmwrite(vmcs::host::CR0, controlregs::cr0().bits() as u64) }; // We can use custom page tables later, this is half implemented. @@ -248,6 +254,8 @@ impl Vmcs { vmwrite(vmcs::host::IA32_SYSENTER_EIP, msr::rdmsr(msr::IA32_SYSENTER_EIP)); } + log::debug!("Host Registers State setup successfully!"); + Ok(()) } @@ -263,6 +271,8 @@ impl Vmcs { /// * `shared_data` - Shared data between processors. #[rustfmt::skip] pub fn setup_vmcs_control_fields(shared_data: &mut SharedData) -> Result<(), HypervisorError> { + log::debug!("Setting up VMCS Control Fields"); + const PRIMARY_CTL: u64 = (vmcs::control::PrimaryControls::SECONDARY_CONTROLS.bits() | vmcs::control::PrimaryControls::USE_MSR_BITMAPS.bits()) as u64; const SECONDARY_CTL: u64 = (vmcs::control::SecondaryControls::ENABLE_RDTSCP.bits() | vmcs::control::SecondaryControls::ENABLE_XSAVES_XRSTORS.bits() @@ -292,6 +302,8 @@ impl Vmcs { invept_single_context(shared_data.primary_eptp); invvpid_single_context(VPID_TAG); + log::debug!("VMCS Control Fields setup successfully!"); + Ok(()) } diff --git a/hypervisor/src/intel/vmexit/cpuid.rs b/hypervisor/src/intel/vmexit/cpuid.rs index 6cff622..843fbd5 100644 --- a/hypervisor/src/intel/vmexit/cpuid.rs +++ b/hypervisor/src/intel/vmexit/cpuid.rs @@ -77,18 +77,20 @@ enum FeatureBits { /// Reference: Intel® 64 and IA-32 Architectures Software Developer's Manual, Table C-1. Basic Exit Reasons 10. #[rustfmt::skip] pub fn handle_cpuid(guest_registers: &mut GuestRegisters) -> ExitType { + log::trace!("Handling CPUID VM exit..."); + let leaf = guest_registers.rax as u32; let sub_leaf = guest_registers.rcx as u32; // Execute CPUID instruction on the host and retrieve the result let mut cpuid_result = cpuid!(leaf, sub_leaf); - log::info!("Before modification: CPUID Leaf: {:#x}, EAX: {:#x}, EBX: {:#x}, ECX: {:#x}, EDX: {:#x}", leaf, cpuid_result.eax, cpuid_result.ebx, cpuid_result.ecx, cpuid_result.edx); + log::trace!("Before modification: CPUID Leaf: {:#x}, EAX: {:#x}, EBX: {:#x}, ECX: {:#x}, EDX: {:#x}", leaf, cpuid_result.eax, cpuid_result.ebx, cpuid_result.ecx, cpuid_result.edx); match leaf { // Handle CPUID for standard feature information. leaf if leaf == CpuidLeaf::FeatureInformation as u32 => { - log::info!("CPUID leaf 1 detected (Standard Feature Information)."); + log::trace!("CPUID leaf 1 detected (Standard Feature Information)."); // Hide hypervisor presence by setting the appropriate bit in ECX. cpuid_result.ecx.set_bit(FeatureBits::HypervisorPresentBit as usize, false); @@ -97,7 +99,7 @@ pub fn handle_cpuid(guest_registers: &mut GuestRegisters) -> ExitType { }, // Handle CPUID for hypervisor vendor information. leaf if leaf == CpuidLeaf::HypervisorVendor as u32 => { - log::info!("CPUID leaf 0x40000000 detected (Hypervisor Vendor Information)."); + log::trace!("CPUID leaf 0x40000000 detected (Hypervisor Vendor Information)."); // Set the CPUID response to provide the hypervisor's vendor ID signature. // We use the signature "MatrixVisor" encoded in a little-endian format. // cpuid_result.eax = CpuidLeaf::HypervisorInterface as u32; // Maximum supported CPUID leaf range. @@ -107,7 +109,7 @@ pub fn handle_cpuid(guest_registers: &mut GuestRegisters) -> ExitType { }, // Handle CPUID for hypervisor interface identification. leaf if leaf == CpuidLeaf::HypervisorInterface as u32 => { - log::info!("CPUID leaf 0x40000001 detected (Hypervisor Interface Identification)."); + log::trace!("CPUID leaf 0x40000001 detected (Hypervisor Interface Identification)."); // Return information indicating the hypervisor's interface. // Here, we specify that our hypervisor does not conform to the Microsoft hypervisor interface ("Hv#1"). cpuid_result.eax = 0x00000001; // Interface signature indicating non-conformance to Microsoft interface. @@ -116,12 +118,12 @@ pub fn handle_cpuid(guest_registers: &mut GuestRegisters) -> ExitType { cpuid_result.edx = 0x00000000; // Reserved field set to zero. }, leaf if leaf == CpuidLeaf::ExtendedFeatureInformation as u32 => { - log::info!("CPUID leaf 7 detected (Extended Feature Information)."); + log::trace!("CPUID leaf 7 detected (Extended Feature Information)."); }, _ => { /* Pass through other CPUID leaves unchanged. */ } } - log::info!("After modification: CPUID Leaf: {:#x}, EAX: {:#x}, EBX: {:#x}, ECX: {:#x}, EDX: {:#x}", leaf, cpuid_result.eax, cpuid_result.ebx, cpuid_result.ecx, cpuid_result.edx); + log::trace!("After modification: CPUID Leaf: {:#x}, EAX: {:#x}, EBX: {:#x}, ECX: {:#x}, EDX: {:#x}", leaf, cpuid_result.eax, cpuid_result.ebx, cpuid_result.ecx, cpuid_result.edx); // Update the guest registers guest_registers.rax = cpuid_result.eax as u64; @@ -129,5 +131,7 @@ pub fn handle_cpuid(guest_registers: &mut GuestRegisters) -> ExitType { guest_registers.rcx = cpuid_result.ecx as u64; guest_registers.rdx = cpuid_result.edx as u64; + log::trace!("CPUID VMEXIT handled successfully!"); + ExitType::IncrementRIP } diff --git a/hypervisor/src/intel/vmexit/ept.rs b/hypervisor/src/intel/vmexit/ept.rs index f1e4ae1..f4e95cd 100644 --- a/hypervisor/src/intel/vmexit/ept.rs +++ b/hypervisor/src/intel/vmexit/ept.rs @@ -14,21 +14,23 @@ use { /// Table 28-7. Exit Qualification for EPT Violations #[rustfmt::skip] pub fn handle_ept_violation(_guest_registers: &mut GuestRegisters, vmx: &mut Vmx) -> ExitType { + log::debug!("Handling EPT Violation VM exit..."); + let guest_physical_address = vmread(vmcs::ro::GUEST_PHYSICAL_ADDR_FULL); - log::info!("EPT Violation: Guest Physical Address: {:#x}", guest_physical_address); + log::debug!("EPT Violation: Guest Physical Address: {:#x}", guest_physical_address); // Translate the page from a physical address to virtual so we can read its memory. let va = PhysicalAddress::va_from_pa(guest_physical_address); - log::info!("EPT Violation: Guest Virtual Address: {:#x}", va); + log::debug!("EPT Violation: Guest Virtual Address: {:#x}", va); // Log the detailed information about the EPT violation let exit_qualification_value = vmread(vmcs::ro::EXIT_QUALIFICATION); let ept_violation_qualification = EptViolationExitQualification::from_exit_qualification(exit_qualification_value); - log::info!("Exit Qualification for EPT Violations: {}", ept_violation_qualification); + log::debug!("Exit Qualification for EPT Violations: {}", ept_violation_qualification); // If the page is Read/Write, then we need to swap it to the secondary EPTP if ept_violation_qualification.readable && ept_violation_qualification.writable && !ept_violation_qualification.executable { - log::info!("EPT Violation: Execute acccess attempted on Guest Physical Address: {:#x} / Guest Virtual Address: {:#x}", guest_physical_address, va); + log::trace!("EPT Violation: Execute acccess attempted on Guest Physical Address: {:#x} / Guest Virtual Address: {:#x}", guest_physical_address, va); // Change to the secondary EPTP and invalidate the EPT cache. // The hooked page that is Execute-Only will be executed from the secondary EPTP. // if Read or Write occurs on that page, then a vmexit will occur @@ -51,6 +53,8 @@ pub fn handle_ept_violation(_guest_registers: &mut GuestRegisters, vmx: &mut Vmx //invept_single_context(primary_eptp); } + log::debug!("EPT Violation handled successfully!"); + // Do not increment RIP, since we want it to execute the same instruction again. ExitType::Continue } @@ -74,11 +78,13 @@ pub fn handle_ept_violation(_guest_registers: &mut GuestRegisters, vmx: &mut Vmx /// Reference: 29.3.3.1 EPT Misconfigurations #[rustfmt::skip] pub fn handle_ept_misconfiguration() -> ExitType { + log::debug!("Handling EPT Misconfiguration VM exit..."); + // Retrieve the guest physical address that caused the EPT misconfiguration. let guest_physical_address = vmread(vmcs::ro::GUEST_PHYSICAL_ADDR_FULL); // Log the critical error information. - log::info!("EPT Misconfiguration: Faulting guest address: {:#x}. This is a critical error that cannot be safely ignored.", guest_physical_address); + log::trace!("EPT Misconfiguration: Faulting guest address: {:#x}. This is a critical error that cannot be safely ignored.", guest_physical_address); // Trigger a breakpoint exception to halt execution for debugging. // Continuing after this point is unsafe due to the potential for system instability. diff --git a/hypervisor/src/intel/vmexit/exception.rs b/hypervisor/src/intel/vmexit/exception.rs index e28bdad..7d66ce0 100644 --- a/hypervisor/src/intel/vmexit/exception.rs +++ b/hypervisor/src/intel/vmexit/exception.rs @@ -17,7 +17,7 @@ use { #[rustfmt::skip] pub fn handle_exception(_guest_registers: &mut GuestRegisters, vmx: &mut Vmx) -> ExitType { - log::trace!("Exception Occurred"); + log::debug!("Handling ExceptionOrNmi VM exit..."); let interruption_info_value = vmread(vmcs::ro::VMEXIT_INTERRUPTION_INFO); let interruption_error_code_value = vmread(vmcs::ro::VMEXIT_INTERRUPTION_ERR_CODE); @@ -28,7 +28,7 @@ pub fn handle_exception(_guest_registers: &mut GuestRegisters, vmx: &mut Vmx) -> ExceptionInterrupt::PageFault => { let exit_qualification_value = vmread(vmcs::ro::EXIT_QUALIFICATION); let ept_violation_qualification = EptViolationExitQualification::from_exit_qualification(exit_qualification_value); - log::info!("Exit Qualification for EPT Violations: {}", ept_violation_qualification); + log::trace!("Exit Qualification for EPT Violations: {}", ept_violation_qualification); EventInjection::vmentry_inject_pf(interruption_error_code_value as u32); }, ExceptionInterrupt::GeneralProtectionFault => { @@ -48,11 +48,13 @@ pub fn handle_exception(_guest_registers: &mut GuestRegisters, vmx: &mut Vmx) -> panic!("Invalid VM Exit Interruption Information"); } + log::debug!("Exception Handled successfully!"); + ExitType::Continue } fn handle_breakpoint_exception(guest_registers: &mut GuestRegisters, _vmx: &mut Vmx) { - log::trace!("Breakpoint Exception"); + log::debug!("Breakpoint Exception"); let hook_manager = unsafe { _vmx.shared_data.as_mut().hook_manager.as_mut() }; @@ -66,9 +68,9 @@ fn handle_breakpoint_exception(guest_registers: &mut GuestRegisters, _vmx: &mut hook_manager .find_hook_by_address(guest_registers.rip) .map(|hook| { - log::info!("Found hook for RIP: {:#x}", guest_registers.rip); + log::trace!("Found hook for RIP: {:#x}", guest_registers.rip); if let HookType::Function { inline_hook } = &hook.hook_type { - log::info!("Getting handler address"); + log::trace!("Getting handler address"); Some(inline_hook.handler_address()) } else { None @@ -76,14 +78,17 @@ fn handle_breakpoint_exception(guest_registers: &mut GuestRegisters, _vmx: &mut }) { // Call our hook handle function (it will automatically call trampoline). - log::info!("Transferring execution to handler: {:#x}", handler); + log::trace!("Transferring execution to handler: {:#x}", handler); guest_registers.rip = handler; vmwrite(vmcs::guest::RIP, guest_registers.rip); + log::debug!("Breakpoint (int3) hook handled successfully!"); + ExitType::Continue } else { EventInjection::vmentry_inject_bp(); + log::debug!("Breakpoint exception handled successfully!"); ExitType::Continue }; } diff --git a/hypervisor/src/intel/vmexit/invd.rs b/hypervisor/src/intel/vmexit/invd.rs index 2770fd0..a9c5f33 100644 --- a/hypervisor/src/intel/vmexit/invd.rs +++ b/hypervisor/src/intel/vmexit/invd.rs @@ -13,10 +13,14 @@ use crate::{intel::vmexit::ExitType, utils::capture::GuestRegisters, utils::inst /// /// * `ExitType::IncrementRIP` - To move past the `INVD` instruction in the VM. pub fn handle_invd(_guest_registers: &mut GuestRegisters) -> ExitType { - log::info!("INVD instruction executed by guest VM"); + log::debug!("Handling INVD VM exit..."); + // Perform WBINVD to write back and invalidate the hypervisor's caches. // This ensures that any modified data is written to memory before cache lines are invalidated. wbinvd(); // Advances the guest's instruction pointer to the next instruction to be executed. + + log::debug!("INVD VMEXIT handled successfully!"); + ExitType::IncrementRIP } diff --git a/hypervisor/src/intel/vmexit/invept.rs b/hypervisor/src/intel/vmexit/invept.rs index 237c844..bb5635a 100644 --- a/hypervisor/src/intel/vmexit/invept.rs +++ b/hypervisor/src/intel/vmexit/invept.rs @@ -10,9 +10,13 @@ use crate::intel::{invept::invept_all_contexts, vmexit::ExitType}; /// # Returns /// * `ExitType::IncrementRIP` - To move past the `INVEPT` instruction in the VM. pub fn handle_invept() -> ExitType { + log::debug!("Handling INVEPT VM exit..."); + // Invalidate all EPT contexts to sync guest VM memory accesses with the host. invept_all_contexts(); + log::debug!("INVEPT VM exit handled successfully!"); + // Return instruction to increment the VM's instruction pointer. ExitType::IncrementRIP } diff --git a/hypervisor/src/intel/vmexit/invvpid.rs b/hypervisor/src/intel/vmexit/invvpid.rs index 050b668..b5ada6d 100644 --- a/hypervisor/src/intel/vmexit/invvpid.rs +++ b/hypervisor/src/intel/vmexit/invvpid.rs @@ -10,9 +10,13 @@ use crate::intel::{invvpid::invvpid_all_contexts, vmexit::ExitType}; /// /// * `ExitType::IncrementRIP` - Advances past the `INVVPID` instruction in the VM. pub fn handle_invvpid() -> ExitType { + log::debug!("Handling INVVPID VM exit..."); + // Invalidate all VPID contexts to ensure consistency of TLB entries with the current VM state. invvpid_all_contexts(); + log::debug!("INVVPID VMEXIT handled successfully!"); + // Indicate to increment the VM's instruction pointer post handling. ExitType::IncrementRIP } diff --git a/hypervisor/src/intel/vmexit/mod.rs b/hypervisor/src/intel/vmexit/mod.rs index 0aed2cf..dff697d 100644 --- a/hypervisor/src/intel/vmexit/mod.rs +++ b/hypervisor/src/intel/vmexit/mod.rs @@ -76,31 +76,24 @@ impl VmExit { guest_registers: &mut GuestRegisters, vmx: &mut Vmx, ) -> Result<(), HypervisorError> { + log::debug!("Handling VMEXIT..."); + // Upon VM-exit, transfer the guest register values from VMCS to `self.registers` to ensure it reflects the latest and complete state. guest_registers.rip = vmread(guest::RIP); guest_registers.rsp = vmread(guest::RSP); guest_registers.rflags = vmread(guest::RFLAGS); - log::info!("Guest RIP: {:#x}", guest_registers.rip); - log::info!("Guest RSP: {:#x}", guest_registers.rsp); - log::info!("Guest RFLAGS: {:#x}", guest_registers.rflags); - - log::info!("Vmx: {:#p}", vmx); - let primary_eptp = unsafe { vmx.shared_data.as_mut().primary_eptp }; - log::info!("Primary EPTP: {:#x}", primary_eptp); - let secondary_eptp = unsafe { vmx.shared_data.as_mut().secondary_eptp }; - log::info!("Secondary EPTP: {:#x}", secondary_eptp); - let exit_reason = vmread(ro::EXIT_REASON) as u32; let Some(basic_exit_reason) = VmxBasicExitReason::from_u32(exit_reason) else { - log::info!("Unknown exit reason: {:#x}", exit_reason); + log::error!("Unknown exit reason: {:#x}", exit_reason); return Err(HypervisorError::UnknownVMExitReason); }; - log::info!("Basic Exit Reason: {}", basic_exit_reason); - log::info!( - "Guest registers before handling vmexit: {:#x?}", + log::debug!("Basic Exit Reason: {}", basic_exit_reason); + + log::debug!( + "Guest Registers before handling vmexit: {:#x?}", guest_registers ); @@ -128,12 +121,11 @@ impl VmExit { self.advance_guest_rip(guest_registers); } - log::info!( + log::debug!( "Guest registers after handling vmexit: {:#x?}", guest_registers ); - - log::info!("VMEXIT handled successfully."); + log::debug!("VMEXIT handled successfully."); return Ok(()); } @@ -145,10 +137,10 @@ impl VmExit { /// caused the VM exit, the hypervisor needs to advance the guest's RIP to the next instruction. #[rustfmt::skip] fn advance_guest_rip(&self, guest_registers: &mut GuestRegisters) { - log::info!("Advancing guest RIP..."); + log::trace!("Advancing guest RIP..."); let len = vmread(ro::VMEXIT_INSTRUCTION_LEN); guest_registers.rip += len; vmwrite(guest::RIP, guest_registers.rip); - log::info!("Guest RIP advanced to: {:#x}", vmread(guest::RIP)); + log::trace!("Guest RIP advanced to: {:#x}", vmread(guest::RIP)); } } diff --git a/hypervisor/src/intel/vmexit/msr.rs b/hypervisor/src/intel/vmexit/msr.rs index 707038d..08911b7 100644 --- a/hypervisor/src/intel/vmexit/msr.rs +++ b/hypervisor/src/intel/vmexit/msr.rs @@ -38,6 +38,8 @@ pub fn handle_msr_access( guest_registers: &mut GuestRegisters, access_type: MsrAccessType, ) -> ExitType { + log::debug!("Handling MSR VM exit..."); + /// Constants related to MSR addresses and ranges. const MSR_MASK_LOW: u64 = u32::MAX as u64; const MSR_RANGE_LOW_END: u64 = 0x00001FFF; @@ -53,7 +55,7 @@ pub fn handle_msr_access( // If the MSR address falls within a synthetic or reserved range, inject a general protection fault. /* if (msr_id >= HYPERV_MSR_START) && (msr_id <= HYPERV_MSR_END) { - log::info!("Synthetic MSR access attempted: {:#x}", msr_id); + log::trace!("Synthetic MSR access attempted: {:#x}", msr_id); EventInjection::vmentry_inject_gp(0); return ExitType::Continue; } @@ -65,7 +67,7 @@ pub fn handle_msr_access( || ((msr_id >= MSR_RANGE_HIGH_START) && (msr_id <= MSR_RANGE_HIGH_END)) || (msr_id >= HYPERV_MSR_START) && (msr_id <= HYPERV_MSR_END) { - log::info!("Valid MSR access attempted: {:#x}", msr_id); + log::trace!("Valid MSR access attempted: {:#x}", msr_id); match access_type { MsrAccessType::Read => { let msr_value = unsafe { x86::msr::rdmsr(msr_id as _) }; @@ -79,10 +81,12 @@ pub fn handle_msr_access( } } else { // If the MSR is neither a known valid MSR nor a synthetic MSR, inject a general protection fault. - log::info!("Invalid MSR access attempted: {:#x}", msr_id); + log::trace!("Invalid MSR access attempted: {:#x}", msr_id); EventInjection::vmentry_inject_gp(0); return ExitType::Continue; } + log::debug!("MSR VMEXIT handled successfully."); + ExitType::IncrementRIP } diff --git a/hypervisor/src/intel/vmexit/rdtsc.rs b/hypervisor/src/intel/vmexit/rdtsc.rs index c089d7d..6a34111 100644 --- a/hypervisor/src/intel/vmexit/rdtsc.rs +++ b/hypervisor/src/intel/vmexit/rdtsc.rs @@ -29,6 +29,8 @@ User can add the following later: /// /// Reference: Intel® 64 and IA-32 Architectures Software Developer's Manual, Table C-1. Basic Exit Reasons 10. pub fn handle_rdtsc(guest_registers: &mut GuestRegisters) -> ExitType { + log::debug!("Handling RDTSC VM exit..."); + // Read the time stamp counter. let rdtsc_value: u64 = unsafe { rdtsc() }; @@ -36,5 +38,7 @@ pub fn handle_rdtsc(guest_registers: &mut GuestRegisters) -> ExitType { guest_registers.rax = rdtsc_value & 0xFFFFFFFF; // Low 32 bits guest_registers.rdx = rdtsc_value >> 32; // High 32 bits + log::debug!("RDTSC VMEXIT handled successfully!"); + ExitType::IncrementRIP } diff --git a/hypervisor/src/intel/vmexit/xsetbv.rs b/hypervisor/src/intel/vmexit/xsetbv.rs index edd9a55..b23c5cf 100644 --- a/hypervisor/src/intel/vmexit/xsetbv.rs +++ b/hypervisor/src/intel/vmexit/xsetbv.rs @@ -22,6 +22,8 @@ use { /// /// * `ExitType::IncrementRIP` - To move past the `XSETBV` instruction in the VM. pub fn handle_xsetbv(guest_registers: &mut GuestRegisters) -> ExitType { + log::debug!("Handling XSETBV VM VM exit..."); + // Extract the XCR (extended control register) number from the guest's RCX register. let xcr: u32 = guest_registers.rcx as u32; @@ -31,7 +33,7 @@ pub fn handle_xsetbv(guest_registers: &mut GuestRegisters) -> ExitType { // Attempt to create an Xcr0 structure from the given bits. let value = Xcr0::from_bits_truncate(value); - log::info!("XSETBV executed with xcr: {:#x}, value: {:#x}", xcr, value); + log::trace!("XSETBV executed with xcr: {:#x}, value: {:#x}", xcr, value); // Enable the OS XSAVE feature in CR4 before setting the extended control register value. cr4_write(cr4() | Cr4::CR4_ENABLE_OS_XSAVE); @@ -39,6 +41,8 @@ pub fn handle_xsetbv(guest_registers: &mut GuestRegisters) -> ExitType { // Write the value to the specified XCR (extended control register). xsetbv(value); + log::debug!("XSETBV VM exit handled successfully!"); + // Advance the guest's instruction pointer to the next instruction to be executed. return ExitType::IncrementRIP; } diff --git a/hypervisor/src/intel/vmm.rs b/hypervisor/src/intel/vmm.rs index c4feebc..7685f1f 100644 --- a/hypervisor/src/intel/vmm.rs +++ b/hypervisor/src/intel/vmm.rs @@ -36,7 +36,7 @@ impl HypervisorBuilder { /// /// A `Result` which is `Ok` if hypervisor initialization was successful, or `Err` if there was an error. pub fn build(self) -> Result { - log::info!("Initializing hypervisor"); + log::debug!("Building hypervisor"); Hypervisor::check_supported_cpu()?; @@ -111,8 +111,8 @@ impl Hypervisor { /// # Returns /// /// A `Result` which is `Ok` if the virtualization was successful, or `Err` if there was an error. - pub fn virtualize_system(&mut self) -> Result<(), HypervisorError> { - log::info!("Virtualizing processors"); + pub fn virtualize_core(&mut self) -> Result<(), HypervisorError> { + log::trace!("Virtualizing processors"); for processor in self.processors.iter_mut() { let Some(executor) = ProcessorExecutor::switch_to_processor(processor.id()) else { @@ -133,7 +133,7 @@ impl Hypervisor { /// /// A `Result` which is `Ok` if the devirtualization was successful, or `Err` if there was an error. pub fn devirtualize_system(&mut self) -> Result<(), HypervisorError> { - log::info!("Devirtualizing processors"); + log::trace!("Devirtualizing processors"); for processor in self.processors.iter_mut() { let Some(executor) = ProcessorExecutor::switch_to_processor(processor.id()) else { @@ -220,8 +220,8 @@ impl Drop for Hypervisor { /// this method attempts to devirtualize the system and logs the result. fn drop(&mut self) { match self.devirtualize_system() { - Ok(_) => log::info!("Devirtualized successfully!"), - Err(err) => log::info!("Failed to devirtualize {}", err), + Ok(_) => log::trace!("Devirtualized successfully!"), + Err(err) => log::trace!("Failed to devirtualize {}", err), } } } diff --git a/hypervisor/src/intel/vmstack.rs b/hypervisor/src/intel/vmstack.rs index 4cdf7f6..2928c67 100644 --- a/hypervisor/src/intel/vmstack.rs +++ b/hypervisor/src/intel/vmstack.rs @@ -51,8 +51,8 @@ impl VmStack { /// /// A `Result` indicating the success or failure of the setup process. pub fn setup(vmstack: &mut Box) -> Result<(), HypervisorError> { - log::info!("Setting up VMCS_HOST_RSP region"); - log::info!("VMCS_HOST_RSP Virtual Address: {:p}", vmstack); + log::debug!("Setting up VMCS_HOST_RSP region"); + log::trace!("VMCS_HOST_RSP Virtual Address: {:p}", vmstack); // Initialize the VM stack contents and reserved space. vmstack.stack_contents = [0u8; STACK_CONTENTS_SIZE]; @@ -63,7 +63,7 @@ impl VmStack { vmstack.padding_2 = u64::MAX; vmstack.padding_1 = u64::MAX; - log::info!("VMCS_HOST_RSP setup successful!"); + log::debug!("VMCS_HOST_RSP setup successfully!"); Ok(()) } diff --git a/hypervisor/src/intel/vmx.rs b/hypervisor/src/intel/vmx.rs index 378ffc4..77e7f7c 100644 --- a/hypervisor/src/intel/vmx.rs +++ b/hypervisor/src/intel/vmx.rs @@ -78,7 +78,7 @@ impl Vmx { /// Returns a `Result` with a boxed `Vmx` instance or an `HypervisorError`. #[rustfmt::skip] pub fn new(shared_data: &mut SharedData, context: &CONTEXT) -> Result, HypervisorError> { - log::info!("Setting up VMX"); + log::debug!("Setting up VMX"); // Allocate memory for the hypervisor's needs let vmxon_region = unsafe { Box::try_new_zeroed_in(PhysicalAllocator)?.assume_init() }; @@ -96,7 +96,7 @@ impl Vmx { host_paging.build_identity(); - log::info!("Creating Vmx instance"); + log::trace!("Creating Vmx instance"); let instance = Self { vmxon_region, @@ -115,10 +115,10 @@ impl Vmx { instance.setup_virtualization(shared_data, context)?; - log::info!("Dumping VMCS: {:#x?}", instance.vmcs_region); - CONTEXT::dump_context(&context); + log::debug!("Dumping VMCS: {:#x?}", instance.vmcs_region); + log::debug!("Dumping CONTEXT: {:#x?}", &context); - log::info!("VMX setup successful!"); + log::debug!("VMX setup successfully!"); Ok(instance) } @@ -138,7 +138,7 @@ impl Vmx { shared_data: &mut SharedData, context: &CONTEXT, ) -> Result<(), HypervisorError> { - log::info!("Virtualization setup"); + log::debug!("Setting up virtualization"); Vmxon::setup(&mut self.vmxon_region)?; Vcpu::invalidate_contexts(); @@ -147,18 +147,14 @@ impl Vmx { VmStack::setup(&mut self.vmstack)?; /* Intel® 64 and IA-32 Architectures Software Developer's Manual: 25.4 GUEST-STATE AREA */ - log::info!("Setting up Guest Registers State"); Vmcs::setup_guest_registers_state( &context, &self.guest_descriptor_table, &mut self.guest_registers, ); - log::info!("Guest Registers State successful!"); /* Intel® 64 and IA-32 Architectures Software Developer's Manual: 25.5 HOST-STATE AREA */ - log::info!("Setting up Host Registers State"); Vmcs::setup_host_registers_state(&context, &self.host_descriptor_table, &self.host_paging)?; - log::info!("Host Registers State successful!"); /* * VMX controls: @@ -167,11 +163,10 @@ impl Vmx { * - 25.7 VM-EXIT CONTROL FIELDS * - 25.8 VM-ENTRY CONTROL FIELDS */ - log::info!("Setting up VMCS Control Fields"); Vmcs::setup_vmcs_control_fields(shared_data)?; - log::info!("VMCS Control Fields successful!"); - log::info!("Virtualization setup successful!"); + log::debug!("Virtualization setup successfully!"); + Ok(()) } @@ -180,14 +175,15 @@ impl Vmx { /// This method will continuously execute the VM until a VM-exit event occurs. Upon VM-exit, /// it updates the VM state, interprets the VM-exit reason, and handles it appropriately. /// The loop continues until an unhandled or error-causing VM-exit is encountered. - pub fn run(&mut self) { - log::info!("Executing VMLAUNCH to run the guest until a VM-exit event occurs"); + pub fn run(&mut self, cpu_index: u32) { + log::trace!("Executing VMLAUNCH to run the guest until a VM-exit event occurs"); let stack_contents_ptr = self.vmstack.stack_contents.as_mut_ptr(); let vmcs_host_rsp = unsafe { stack_contents_ptr.offset(STACK_CONTENTS_SIZE as isize) }; - log::info!("Vmx: {:#p}", self.vmstack.vmx); + log::trace!("Vmx: {:#p}", self.vmstack.vmx); + log::info!("Launching VM for processor {}", cpu_index); unsafe { launch_vm(&mut self.guest_registers, vmcs_host_rsp as *mut u64) }; } diff --git a/hypervisor/src/intel/vmxon.rs b/hypervisor/src/intel/vmxon.rs index 73b0864..3e46321 100644 --- a/hypervisor/src/intel/vmxon.rs +++ b/hypervisor/src/intel/vmxon.rs @@ -38,10 +38,10 @@ impl Vmxon { /// # Returns /// A result indicating success or an error. pub fn setup(vmxon_region: &mut Box) -> Result<(), HypervisorError> { - log::info!("Setting up VMXON region"); + log::debug!("Setting up VMXON region"); /* Intel® 64 and IA-32 Architectures Software Developer's Manual: 24.7 ENABLING AND ENTERING VMX OPERATION */ - log::info!("Enabling Virtual Machine Extensions (VMX)"); + log::trace!("Enabling Virtual Machine Extensions (VMX)"); Self::enable_vmx_operation()?; let vmxon_region_physical_address = @@ -51,8 +51,8 @@ impl Vmxon { return Err(HypervisorError::VirtualToPhysicalAddressFailed); } - log::info!("VMXON Region Virtual Address: {:p}", vmxon_region); - log::info!( + log::trace!("VMXON Region Virtual Address: {:p}", vmxon_region); + log::trace!( "VMXON Region Physical Addresss: 0x{:x}", vmxon_region_physical_address ); @@ -62,7 +62,8 @@ impl Vmxon { // Enable VMX operation. vmxon(vmxon_region_physical_address); - log::info!("VMXON setup successful!"); + + log::debug!("VMXON setup successfully!"); Ok(()) } @@ -75,11 +76,11 @@ impl Vmxon { unsafe { Cr4::write_raw(cr4) }; /* Intel® 64 and IA-32 Architectures Software Developer's Manual: 24.7 ENABLING AND ENTERING VMX OPERATION */ - log::info!("Setting Lock Bit set via IA32_FEATURE_CONTROL"); + log::trace!("Setting Lock Bit set via IA32_FEATURE_CONTROL"); Self::set_lock_bit()?; /* Intel® 64 and IA-32 Architectures Software Developer's Manual: 24.8 RESTRICTIONS ON VMX OPERATION */ - log::info!("Adjusting Control Registers"); + log::trace!("Adjusting Control Registers"); Self::adjust_control_registers(); Ok(()) diff --git a/hypervisor/src/utils/function_hook.rs b/hypervisor/src/utils/function_hook.rs index 5342df8..98a6e28 100644 --- a/hypervisor/src/utils/function_hook.rs +++ b/hypervisor/src/utils/function_hook.rs @@ -65,6 +65,8 @@ impl FunctionHook { /// ## Safety /// This function allocates memory and manipulates page table entries. Incorrect use may lead to system instability. pub fn new(original_address: u64, hook_address: u64, handler: *const ()) -> Option { + log::debug!("Setting up hooks"); + // Create the different trampolines. There's a few different ones available: // - 1 Byte: CC shellcode // - 14 Bytes: JMP shellcode @@ -140,12 +142,13 @@ impl FunctionHook { /// ## Safety /// This function modifies the instruction at the hook address. Ensure that this doesn't corrupt the program flow or overlap with critical instructions. pub fn enable(&self) { + log::debug!("Enabling hook"); let jmp_to_handler = match self.hook_type { HookType::Jmp => Self::jmp_shellcode(self.handler).to_vec(), HookType::Breakpoint => vec![0xCC_u8], // 0xCC is the opcode for INT3, a common breakpoint instruction. }; - log::info!( + log::trace!( "Writing the shellcode {:x?} to {:p}", jmp_to_handler, self.trampoline_address(), @@ -161,6 +164,8 @@ impl FunctionHook { ); } + log::debug!("Hook enabled!"); + // Invalidate all processor caches to ensure the new instructions are used. (Will use invept instead of this later) //unsafe { KeInvalidateAllCaches() }; } @@ -191,7 +196,7 @@ impl FunctionHook { /// registers to store the jmp address**. And because of that, we don't /// have to fear overwriting some register values. fn jmp_shellcode(target_address: u64) -> [u8; 14] { - log::info!( + log::debug!( "Creating the jmp shellcode for address: {:#x}", target_address ); @@ -204,7 +209,7 @@ impl FunctionHook { unsafe { (shellcode.as_mut_ptr().add(6) as *mut u64).write_volatile(target_address) }; - log::info!("Jmp shellcode: {:x?}", shellcode); + log::trace!("Jmp shellcode: {:x?}", shellcode); shellcode } @@ -229,7 +234,7 @@ impl FunctionHook { address: u64, required_size: usize, ) -> Result, HypervisorError> { - log::info!("Creating the trampoline for function: {:#x}", address); + log::debug!("Creating a trampoline"); // Read bytes from function and decode them. Read 2 times the amount needed, in // case there are bigger instructions that take more space. If there's @@ -291,7 +296,7 @@ impl FunctionHook { // Allocate new memory for the trampoline and encode the instructions. // let mut memory = Box::new_uninit_slice(total_bytes + JMP_SHELLCODE_LEN); - log::info!("Allocated trampoline memory at {:p}", memory.as_ptr()); + log::debug!("Allocated trampoline memory at {:p}", memory.as_ptr()); let block = InstructionBlock::new(&trampoline, memory.as_mut_ptr() as _); @@ -299,7 +304,7 @@ impl FunctionHook { .map(|b| b.code_buffer) .map_err(|_| HypervisorError::EncodingFailed)?; - log::info!("Encoded trampoline: {:x?}", encoded); + log::trace!("Encoded trampoline: {:x?}", encoded); // Add jmp to the original function at the end. We can't use `address` for this, // because the page will probably contain rip-relative instructions. And @@ -320,6 +325,8 @@ impl FunctionHook { ) }; + log::debug!("Trampoline setup successfully!"); + Ok(unsafe { memory.assume_init() }) } diff --git a/hypervisor/src/utils/nt.rs b/hypervisor/src/utils/nt.rs index bc4f805..f4569c6 100644 --- a/hypervisor/src/utils/nt.rs +++ b/hypervisor/src/utils/nt.rs @@ -98,7 +98,7 @@ pub fn update_ntoskrnl_cr3() { NTOSKRNL_CR3 = x86::controlregs::cr3(); } - log::info!("NTOSKRNL_CR3: {:#x}", unsafe { NTOSKRNL_CR3 }); + log::trace!("NTOSKRNL_CR3: {:#x}", unsafe { NTOSKRNL_CR3 }); // Detach from the system process's stack safely. // `KeUnstackDetachProcess` is unsafe as it restores the previous thread execution context. diff --git a/hypervisor/src/utils/processor.rs b/hypervisor/src/utils/processor.rs index 7fa8edb..b9f770b 100644 --- a/hypervisor/src/utils/processor.rs +++ b/hypervisor/src/utils/processor.rs @@ -90,7 +90,7 @@ impl ProcessorExecutor { /// An `Option` containing the `ProcessorExecutor` if the switch was successful, or `None` if not. pub fn switch_to_processor(i: u32) -> Option { if i > processor_count() { - log::info!("Invalid processor index: {}", i); + log::trace!("Invalid processor index: {}", i); return None; } @@ -105,10 +105,10 @@ impl ProcessorExecutor { affinity.Reserved[1] = 0; affinity.Reserved[2] = 0; - log::info!("Switching execution to processor {}", i); + log::trace!("Switching execution to processor {}", i); unsafe { KeSetSystemGroupAffinityThread(&mut affinity, old_affinity.as_mut_ptr()) }; - log::info!("Yielding execution"); + log::trace!("Yielding execution"); if !NT_SUCCESS(unsafe { ZwYieldExecution() }) { return None; } @@ -120,7 +120,7 @@ impl ProcessorExecutor { impl Drop for ProcessorExecutor { /// Restores the group affinity of the calling thread to its original value when the `ProcessorExecutor` is dropped. fn drop(&mut self) { - log::info!("Switching execution back to previous processor"); + log::trace!("Switching execution back to previous processor"); unsafe { KeRevertToUserGroupAffinityThread(self.old_affinity.as_mut_ptr()); }