aphrody-labs/WSL
1
0 Fork 0
mirror of https://github.com/aphrody-labs/WSL.git synced 2026-10-18 13:15:21 +00:00
Code Issues Actions 1 Packages Projects Releases Wiki Activity

add tracing

Browse Source
This commit is contained in:
Daman Mulye committed 2026-09-15 12:07:30 -07:00
1 parent ff9c777705
commit 260080dbf1
8 files changed
+195 -24
Download Patch File Download Diff File Expand all files Collapse all files

No files matched your search

src/windows/wslopenvmm/CMakeLists.txt
+1 -1
View File
@@ -26,7 +26,7 @@ add_custom_command(
OUTPUT ${WSLOPENVMM_DLL}
COMMAND ${CMAKE_COMMAND} -E env "VM_SERVICE_PROTO=${VM_SERVICE_PROTO}" ${CARGO_EXECUTABLE} build --manifest-path ${CMAKE_CURRENT_LIST_DIR}/Cargo.toml --target ${RUST_TARGET} --target-dir ${CARGO_TARGET_DIR} ${CARGO_BUILD_ARGUMENTS}
COMMAND ${CMAKE_COMMAND} -E copy_if_different ${CARGO_OUTPUT} ${WSLOPENVMM_DLL}
DEPENDS ${VM_SERVICE_PROTO} Cargo.lock Cargo.toml build.rs src/client.rs src/lib.rs src/af_unix.rs src/rpc.rs wslopenvmm.h
DEPENDS ${VM_SERVICE_PROTO} Cargo.lock Cargo.toml build.rs src/client.rs src/lib.rs src/af_unix.rs src/rpc.rs src/diagnostics.rs wslopenvmm.h
WORKING_DIRECTORY ${CMAKE_CURRENT_LIST_DIR}
VERBATIM)
src/windows/wslopenvmm/Cargo.lock
Generated
+38
View File
@@ -362,6 +362,12 @@ version = "1.0.18"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "8f42a60cbdf9a97f5d2305f08a87dc4e09308d1276d28c869c684d7777685682"
[[package]]
name = "lazy_static"
version = "1.5.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe"
[[package]]
name = "libc"
version = "0.2.189"
@@ -744,6 +750,15 @@ dependencies = [
"syn 3.0.4",
]
[[package]]
name = "sharded-slab"
version = "0.1.7"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6"
dependencies = [
"lazy_static",
]
[[package]]
name = "slab"
version = "0.4.12"
@@ -807,6 +822,15 @@ dependencies = [
"windows-sys",
]
[[package]]
name = "thread_local"
version = "1.1.10"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "1ad99c4c6d32803332c548b1af0540b357b3f5fc0be8f6c6bfe8b2e6ae784070"
dependencies = [
"cfg-if",
]
[[package]]
name = "tokio"
version = "1.53.1"
@@ -988,6 +1012,17 @@ dependencies = [
"once_cell",
]
[[package]]
name = "tracing-subscriber"
version = "0.3.23"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "cb7f578e5945fb242538965c2d0b04418d38ec25c79d160cd279bf0731c8d319"
dependencies = [
"sharded-slab",
"thread_local",
"tracing-core",
]
[[package]]
name = "try-lock"
version = "0.2.5"
@@ -1149,6 +1184,7 @@ dependencies = [
"prost",
"prost-types",
"protoc-bin-vendored",
"smallvec",
"socket2",
"tokio",
"tokio-stream",
@@ -1156,6 +1192,8 @@ dependencies = [
"tonic-prost",
"tonic-prost-build",
"tower",
"tracing",
"tracing-subscriber",
"windows",
"windows-sys",
]
src/windows/wslopenvmm/Cargo.toml
+4 -1
View File
@@ -11,6 +11,7 @@ crate-type = ["cdylib"]
[dependencies]
hyper-util = { version = "0.1", features = ["tokio"] }
parking_lot = "0.12"
smallvec = "1"
socket2 = "0.6"
prost = "0.14"
prost-types = "0.14"
@@ -18,8 +19,10 @@ tonic = "0.14"
tonic-prost = "0.14"
tokio = { version = "1", features = ["net", "rt", "time", "macros", "sync"] }
tower = "0.5"
tracing = "0.1"
tracing-subscriber = { version = "0.3", default-features = false, features = ["fmt", "registry"] }
windows = { version = "0.62", features = ["Win32_Foundation"] }
windows-sys = { version = "0.61", features = ["Win32_Networking_WinSock"] }
windows-sys = { version = "0.61", features = ["Win32_Networking_WinSock", "Win32_System_Diagnostics_Debug"] }
[dev-dependencies]
tokio-stream = { version = "0.1", features = ["net"] }
src/windows/wslopenvmm/src/client.rs
+78 -17
View File
@@ -40,6 +40,7 @@ pub struct VmConfigHandle {
impl VmConfigHandle {
pub fn new() -> Self {
crate::diagnostics::ensure_tracing_init();
Self {
builder: Mutex::new(VmConfigBuilder::new()),
}
@@ -51,12 +52,29 @@ impl VmConfigHandle {
pub fn create_vm(&self, socket_path: String, timeout_ms: u32) -> Result<VmHandle, HRESULT> {
if timeout_ms == 0 {
tracing::warn!(target: "wslopenvmm::rpc", "CreateVm requires a nonzero timeout");
return Err(E_INVALIDARG);
}
let timeout = Duration::from_millis(u64::from(timeout_ms));
let deadline = Instant::now() + timeout;
let mut builder = self.builder.try_lock_until(deadline).ok_or(rpc::TIMEOUT)?;
builder.create_vm(socket_path, timeout, deadline)
let started = Instant::now();
let deadline = started + timeout;
tracing::info!(target: "wslopenvmm::rpc", "CreateVm starting with timeout {timeout_ms} ms");
let Some(mut builder) = self.builder.try_lock_until(deadline) else {
tracing::warn!(target: "wslopenvmm::rpc", "CreateVm timed out waiting for the configuration lock; no request sent");
return Err(rpc::TIMEOUT);
};
let result = builder.create_vm(socket_path, timeout, deadline);
match &result {
Ok(_) => {
tracing::info!(target: "wslopenvmm::rpc", "CreateVm completed in {:?}", started.elapsed())
}
Err(error) => tracing::warn!(
target: "wslopenvmm::rpc",
"CreateVm failed with HRESULT {:#010x} after {:?}; configuration status: {:?}",
error.0, started.elapsed(), builder.status
),
}
result
}
}
@@ -94,6 +112,7 @@ impl VmConfigBuilder {
deadline: Instant,
) -> Result<VmHandle, HRESULT> {
if self.status == VmConfigStatus::CreationOutcomeUnknown {
tracing::warn!(target: "wslopenvmm::rpc", "CreateVm rejected: previous creation outcome is unknown");
return Err(rpc::INVALID_STATE);
}
let runtime = match tokio::runtime::Builder::new_current_thread()
@@ -101,17 +120,26 @@ impl VmConfigBuilder {
.build()
{
Ok(runtime) => runtime,
Err(_) => return Err(E_FAIL),
Err(_) => {
tracing::error!(target: "wslopenvmm::rpc", "CreateVm could not initialize the RPC runtime");
return Err(E_FAIL);
}
};
let remaining = deadline.saturating_duration_since(Instant::now());
if remaining.is_zero() {
tracing::warn!(target: "wslopenvmm::rpc", "CreateVm deadline expired before connecting");
return Err(rpc::TIMEOUT);
}
let channel =
match runtime.block_on(af_unix::connect_channel(socket_path.into(), remaining)) {
Ok(channel) => channel,
Err(error) => return Err(rpc::io_error_to_hresult(&error)),
};
let channel = match runtime
.block_on(af_unix::connect_channel(socket_path.into(), remaining))
{
Ok(channel) => channel,
Err(error) => {
let result = rpc::io_error_to_hresult(&error);
tracing::warn!(target: "wslopenvmm::rpc", "CreateVm connection failed with HRESULT {:#010x}; no creation request sent", result.0);
return Err(result);
}
};
let mut client = VmClient::new(channel);
let request = CreateVmRequest {
config: Some(self.config.clone()),
@@ -119,6 +147,7 @@ impl VmConfigBuilder {
};
let remaining = deadline.saturating_duration_since(Instant::now());
if remaining.is_zero() {
tracing::warn!(target: "wslopenvmm::rpc", "CreateVm deadline expired before dispatch");
return Err(rpc::TIMEOUT);
}
match runtime.block_on(rpc::execute(
@@ -130,6 +159,7 @@ impl VmConfigBuilder {
Err(error) => {
if error.uncertain {
self.status = VmConfigStatus::CreationOutcomeUnknown;
tracing::warn!(target: "wslopenvmm::rpc", "CreateVm outcome is unknown; discard the configuration and process before retrying");
}
Err(error.result)
}
@@ -261,23 +291,29 @@ impl VmHandle {
pub fn cancel_requests(&self) -> HRESULT {
self.cancellation.send_replace(true);
tracing::info!(target: "wslopenvmm::rpc", "VM request cancellation signalled");
S_OK
}
fn with_operation(
&self,
name: &'static str,
cleanup: bool,
operation: impl FnOnce(&mut VmHandleInner, Instant, Option<watch::Receiver<bool>>) -> HRESULT,
) -> HRESULT {
let deadline = Instant::now() + self.timeout;
let started = Instant::now();
let deadline = started + self.timeout;
tracing::info!(target: "wslopenvmm::rpc", "{name} starting");
let Some(mut inner) = self.inner.try_lock_until(deadline) else {
// No request was sent, so lock contention alone does not invalidate the VM.
tracing::warn!(target: "wslopenvmm::rpc", "{name} timed out waiting for the VM lock; no request sent");
return rpc::TIMEOUT;
};
if *self.cancellation.borrow() {
inner.status = VmStatus::RecoveryRequired;
}
if !cleanup && inner.status == VmStatus::RecoveryRequired {
tracing::warn!(target: "wslopenvmm::rpc", "{name} rejected: VM requires recovery");
return rpc::INVALID_STATE;
}
let cancellation = if cleanup {
@@ -290,11 +326,24 @@ impl VmHandle {
if *self.cancellation.borrow() {
inner.status = VmStatus::RecoveryRequired;
}
if result.is_err() {
tracing::warn!(
target: "wslopenvmm::rpc",
"{name} failed with HRESULT {:#010x} after {:?}; VM status: {:?}",
result.0, started.elapsed(), inner.status
);
} else {
tracing::info!(
target: "wslopenvmm::rpc",
"{name} completed in {:?}; VM status: {:?}",
started.elapsed(), inner.status
);
}
result
}
pub fn resume_vm(&self) -> HRESULT {
self.with_operation(false, |inner, deadline, cancellation| {
self.with_operation("ResumeVm", false, |inner, deadline, cancellation| {
self.rpc(
inner,
deadline,
@@ -306,7 +355,7 @@ impl VmHandle {
}
pub fn teardown_vm(&self) -> HRESULT {
self.with_operation(true, |inner, deadline, cancellation| {
self.with_operation("TeardownVm", true, |inner, deadline, cancellation| {
let result = self.rpc(
inner,
deadline,
@@ -322,7 +371,7 @@ impl VmHandle {
}
pub fn quit(&self) -> HRESULT {
self.with_operation(true, |inner, deadline, cancellation| {
self.with_operation("Quit", true, |inner, deadline, cancellation| {
self.rpc(
inner,
deadline,
@@ -356,7 +405,7 @@ impl VmHandle {
}
pub fn add_share(&self, tag: String, host_path: String, read_only: bool) -> HRESULT {
self.with_operation(false, |inner, deadline, cancellation| {
self.with_operation("AddShare", false, |inner, deadline, cancellation| {
if inner.shares.contains_key(&tag) {
return HRESULT::from_win32(ERROR_ALREADY_EXISTS.0);
}
@@ -393,7 +442,7 @@ impl VmHandle {
}
pub fn remove_share(&self, tag: &str) -> HRESULT {
self.with_operation(false, |inner, deadline, cancellation| {
self.with_operation("RemoveShare", false, |inner, deadline, cancellation| {
let Some(instance_id) = inner.shares.get(tag) else {
return HRESULT::from_win32(ERROR_NOT_FOUND.0);
};
@@ -428,6 +477,7 @@ impl VmHandle {
{
let remaining = deadline.saturating_duration_since(Instant::now());
if remaining.is_zero() {
tracing::warn!(target: "wslopenvmm::rpc", "RPC deadline expired before dispatch; no request sent");
return rpc::TIMEOUT;
}
let result = inner.runtime.block_on(rpc::execute(
@@ -443,6 +493,7 @@ impl VmHandle {
Err(error) => {
if error.uncertain {
inner.status = VmStatus::RecoveryRequired;
tracing::warn!(target: "wslopenvmm::rpc", "Uncertain RPC outcome; VM requires teardown and recreation");
}
error.result
}
@@ -457,7 +508,12 @@ impl VmHandle {
host_path: String,
read_only: bool,
) -> HRESULT {
self.with_operation(false, |inner, deadline, cancellation| {
let name = if modify_type == ModifyType::Add {
"AttachScsiDisk"
} else {
"DetachScsiDisk"
};
self.with_operation(name, false, |inner, deadline, cancellation| {
let request = ModifyResourceRequest {
r#type: modify_type as i32,
resource: Some(vmservice::modify_resource_request::Resource::ScsiDisk(
@@ -488,7 +544,12 @@ impl VmHandle {
tcp: bool,
family: i32,
) -> HRESULT {
self.with_operation(false, |inner, deadline, cancellation| {
let name = if modify_type == ModifyType::Update {
"BindPort"
} else {
"UnbindPort"
};
self.with_operation(name, false, |inner, deadline, cancellation| {
let host_address = match family {
family if family == i32::from(AF_INET) => "127.0.0.1",
family if family == i32::from(AF_INET6) => "::1",
src/windows/wslopenvmm/src/client/tests.rs
+1 -1
View File
@@ -474,7 +474,7 @@ fn cancellation_racing_success_requires_recovery() {
let fixture = Fixture::new();
let vm = &fixture.vm.as_ref().unwrap().0;
assert_eq!(
vm.with_operation(cleanup, |inner, _, _| {
vm.with_operation("CancellationRace", cleanup, |inner, _, _| {
assert_eq!(inner.status, VmStatus::Active);
assert_eq!(vm.cancel_requests(), S_OK);
S_OK
src/windows/wslopenvmm/src/diagnostics.rs
+57
View File
@@ -0,0 +1,57 @@
// Copyright (C) Microsoft Corporation. All rights reserved.
use smallvec::SmallVec;
use std::io::Write as _;
use windows_sys::Win32::System::Diagnostics::Debug::{IsDebuggerPresent, OutputDebugStringA};
pub fn ensure_tracing_init() {
static INIT: std::sync::Once = std::sync::Once::new();
INIT.call_once(|| {
use tracing_subscriber::Layer as _;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt;
let fmt_layer = tracing_subscriber::fmt::layer()
.with_ansi(false)
.with_writer(DebugOutputWriter::new)
.with_filter(tracing_subscriber::filter::filter_fn(|metadata| {
// Avoid formatting when no debugger is listening.
metadata.target() == "wslopenvmm::rpc"
&& *metadata.level() <= tracing::Level::DEBUG
&& unsafe { IsDebuggerPresent() != 0 }
}));
if let Err(error) = tracing_subscriber::Registry::default()
.with(fmt_layer)
.try_init()
{
let _ = writeln!(
DebugOutputWriter::new(),
"WSL RPC tracing initialization failed: {error}"
);
}
});
}
struct DebugOutputWriter;
impl DebugOutputWriter {
fn new() -> Self {
Self
}
}
impl std::io::Write for DebugOutputWriter {
fn write(&mut self, bytes: &[u8]) -> std::io::Result<usize> {
// Keep typical messages on the stack, spilling to the heap for longer output.
let mut null_terminated: SmallVec<[u8; 1024]> = SmallVec::with_capacity(bytes.len() + 1);
null_terminated.extend_from_slice(bytes);
null_terminated.push(b'\0');
// The buffer is null-terminated and valid for the duration of this call.
unsafe { OutputDebugStringA(null_terminated.as_ptr()) };
Ok(bytes.len())
}
fn flush(&mut self) -> std::io::Result<()> {
Ok(())
}
}
src/windows/wslopenvmm/src/lib.rs
+1
View File
@@ -4,6 +4,7 @@
mod af_unix;
mod client;
mod diagnostics;
mod rpc;
mod vmservice {
src/windows/wslopenvmm/src/rpc.rs
+15 -4
View File
@@ -39,10 +39,14 @@ pub async fn execute<T>(
// This also bounds peers that ignore grpc-timeout.
tokio::select! {
biased;
_ = tokio::time::sleep_until(deadline.into()) =>
Err(RpcFailure { result: TIMEOUT, uncertain: true }),
_ = cancellation =>
Err(RpcFailure { result: E_ABORT, uncertain: true }),
_ = tokio::time::sleep_until(deadline.into()) => {
tracing::warn!(target: "wslopenvmm::rpc", "RPC deadline expired; outcome is uncertain");
Err(RpcFailure { result: TIMEOUT, uncertain: true })
},
_ = cancellation => {
tracing::info!(target: "wslopenvmm::rpc", "RPC cancelled; outcome is uncertain");
Err(RpcFailure { result: E_ABORT, uncertain: true })
},
result = operation => result.map_err(failure_from_status),
}
}
@@ -52,6 +56,7 @@ fn failure_from_status(status: tonic::Status) -> RpcFailure {
while let Some(error) = source {
// Tonic reports its local request timeout with Code::Cancelled.
if error.is::<tonic::TimeoutExpired>() {
tracing::warn!(target: "wslopenvmm::rpc", "Tonic request timed out; outcome is uncertain");
return RpcFailure {
result: TIMEOUT,
uncertain: true,
@@ -59,6 +64,12 @@ fn failure_from_status(status: tonic::Status) -> RpcFailure {
}
source = error.source();
}
tracing::warn!(
target: "wslopenvmm::rpc",
"RPC returned gRPC status {:?}; outcome uncertain: {}",
status.code(),
!is_definite_rejection(status.code())
);
RpcFailure {
result: status_to_hresult(status.code()),
uncertain: !is_definite_rejection(status.code()),