From 7198e7cf83435d2667c86ffcd6ee4356a3984e66 Mon Sep 17 00:00:00 2001 From: Sven Groot Date: Fri, 10 Oct 2025 12:52:10 -0700 Subject: [PATCH 1/5] Add key to vmbus_server logs --- vm/devices/vmbus/vmbus_channel/src/bus.rs | 2 +- vm/devices/vmbus/vmbus_server/src/channels.rs | 84 ++++++++++--------- vm/devices/vmbus/vmbus_server/src/lib.rs | 8 +- 3 files changed, 51 insertions(+), 43 deletions(-) diff --git a/vm/devices/vmbus/vmbus_channel/src/bus.rs b/vm/devices/vmbus/vmbus_channel/src/bus.rs index 80d49b61bf..2ee8cd34d4 100644 --- a/vm/devices/vmbus/vmbus_channel/src/bus.rs +++ b/vm/devices/vmbus/vmbus_channel/src/bus.rs @@ -230,7 +230,7 @@ impl OpenRequest { } } -#[derive(Debug, Copy, Clone, Hash, Eq, PartialEq, Ord, PartialOrd, Protobuf)] +#[derive(Debug, Default, Copy, Clone, Hash, Eq, PartialEq, Ord, PartialOrd, Protobuf)] /// The identifying IDs for a channel offer. #[mesh(package = "vmbus")] pub struct OfferKey { diff --git a/vm/devices/vmbus/vmbus_server/src/channels.rs b/vm/devices/vmbus/vmbus_server/src/channels.rs index 34c5c3666b..a9d96b56c8 100644 --- a/vm/devices/vmbus/vmbus_server/src/channels.rs +++ b/vm/devices/vmbus/vmbus_server/src/channels.rs @@ -1880,9 +1880,9 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { /// Completes an open operation with `result`. pub fn open_complete(&mut self, offer_id: OfferId, result: i32) { - tracing::debug!(offer_id = offer_id.0, result, "open complete"); - let channel = &mut self.inner.channels[offer_id]; + tracing::debug!(offer_id = offer_id.0, key = %channel.offer.key(), result, "open complete"); + match channel.state { ChannelState::Opening { request, @@ -1893,6 +1893,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { tracelimit::info_ratelimited!( offer_id = offer_id.0, channel_id = channel_id.0, + key = %channel.offer.key(), result, "opened channel" ); @@ -1901,6 +1902,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { tracelimit::error_ratelimited!( offer_id = offer_id.0, channel_id = channel_id.0, + key = %channel.offer.key(), result, "failed to open channel" ); @@ -1928,6 +1930,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { ChannelState::OpeningClientRelease => { tracing::info!( offer_id = offer_id.0, + key = %channel.offer.key(), result, "opened channel (client released)" ); @@ -1949,7 +1952,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { | ChannelState::Revoked | ChannelState::Reoffered | ChannelState::ClosingClientRelease => { - tracing::error!(?offer_id, state = ?channel.state, "invalid open complete") + tracing::error!(?offer_id, key = %channel.offer.key(), state = ?channel.state, "invalid open complete") } } } @@ -2024,7 +2027,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { /// Completes a channel close operation. pub fn close_complete(&mut self, offer_id: OfferId) { let channel = &mut self.inner.channels[offer_id]; - tracing::info!(offer_id = offer_id.0, "closed channel"); + tracing::info!(offer_id = offer_id.0, key = %channel.offer.key(), "closed channel"); match channel.state { ChannelState::Closing { reserved_state: Some(reserved_state), @@ -2075,7 +2078,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { | ChannelState::Revoked | ChannelState::Reoffered | ChannelState::OpeningClientRelease => { - tracing::error!(?offer_id, state = ?channel.state, "invalid close complete") + tracing::error!(?offer_id, key = %channel.offer.key(), state = ?channel.state, "invalid close complete") } } } @@ -2204,10 +2207,10 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { if request.target_sint != SINT { tracelimit::warn_ratelimited!( - "unsupported multiclient request for VTL {} SINT {}, version {:#x}", - request.target_vtl, - request.target_sint, - request.version_requested, + target_vtl = request.target_vtl, + target_sint = request.target_sint, + version = request.version_requested, + "unsupported multiclient request", ); // Send an unsupported response to the requested SINT. @@ -2784,6 +2787,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { tracelimit::warn_ratelimited!( err = &err as &dyn std::error::Error, channel_id = ?input.channel_id, + key = %self.inner.channels.get_by_channel_id(&self.inner.assigned_channels, input.channel_id).map(|(_, c)| c.offer.key()).unwrap_or_default(), gpadl_id = ?input.gpadl_id, "error handling gpadl header" ); @@ -2846,6 +2850,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { tracelimit::warn_ratelimited!( err = &err as &dyn std::error::Error, channel_id = channel_id.0, + key = %channel.offer.key(), gpadl_id = input.gpadl_id.0, "error handling gpadl body" ); @@ -2865,17 +2870,18 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { &mut self, input: &protocol::GpadlTeardown, ) -> Result<(), ChannelError> { + let (offer_id, channel) = self + .inner + .channels + .get_by_channel_id_mut(&self.inner.assigned_channels, input.channel_id)?; + tracing::debug!( channel_id = input.channel_id.0, + key = %channel.offer.key(), gpadl_id = input.gpadl_id.0, "Received GPADL teardown request" ); - let (offer_id, channel) = self - .inner - .channels - .get_by_channel_id_mut(&self.inner.assigned_channels, input.channel_id)?; - let gpadl = self .inner .gpadls @@ -2904,6 +2910,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { if channel.state.is_revoked() { tracing::trace!( channel_id = input.channel_id.0, + key = %channel.offer.key(), gpadl_id = input.gpadl_id.0, "Gpadl teardown for revoked channel" ); @@ -3032,6 +3039,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { } => { if modify_state.is_modifying() { tracelimit::warn_ratelimited!( + key = %channel.offer.key(), ?modify_state, "Client is closing the channel with a modify in progress" ) @@ -3362,6 +3370,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { // On Iron or later, the client isn't allowed to send a ModifyChannel // request while another one is still in progress. tracelimit::warn_ratelimited!( + key = %channel.offer.key(), "Client sent new ModifyChannel before receiving ModifyChannelResponse." ); } else { @@ -3410,6 +3419,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { // Send the ModifyChannelResponse message if the protocol supports it. let channel_id = channel.info.as_ref().expect("assigned").channel_id; + let key = channel.offer.key(); self.send_modify_channel_response(channel_id, status); // Handle a pending ModifyChannel request if there is one. @@ -3420,7 +3430,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { }; if let Err(error) = self.handle_modify_channel(&request) { - tracelimit::warn_ratelimited!(?error, "Pending ModifyChannel request failed.") + tracelimit::warn_ratelimited!(?error, %key, "Pending ModifyChannel request failed.") } } } @@ -3621,24 +3631,15 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { Ok(()) } - fn get_gpadl( - gpadls: &mut GpadlMap, - offer_id: OfferId, - gpadl_id: GpadlId, - ) -> Option<&mut Gpadl> { - let gpadl = gpadls.get_mut(&(gpadl_id, offer_id)); - if gpadl.is_none() { - tracelimit::error_ratelimited!(?offer_id, ?gpadl_id, "invalid gpadl ID for channel"); - } - gpadl - } - /// Completes a GPADL creation, accepting it if `status >= 0`, rejecting it otherwise. pub fn gpadl_create_complete(&mut self, offer_id: OfferId, gpadl_id: GpadlId, status: i32) { - let gpadl = if let Some(gpadl) = Self::get_gpadl(&mut self.inner.gpadls, offer_id, gpadl_id) - { - gpadl - } else { + let Some(gpadl) = self.inner.gpadls.get_mut(&(gpadl_id, offer_id)) else { + tracelimit::error_ratelimited!( + ?offer_id, + key = %self.inner.channels[offer_id].offer.key(), + ?gpadl_id, + "invalid gpadl ID for channel" + ); return; }; let retain = match gpadl.state { @@ -3692,25 +3693,28 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { /// Releases a GPADL that is being torn down. pub fn gpadl_teardown_complete(&mut self, offer_id: OfferId, gpadl_id: GpadlId) { + let channel = &mut self.inner.channels[offer_id]; + let Some(gpadl) = self.inner.gpadls.get_mut(&(gpadl_id, offer_id)) else { + tracelimit::error_ratelimited!( + ?offer_id, + key = %channel.offer.key(), + ?gpadl_id, + "invalid gpadl ID for channel" + ); + return; + }; tracing::debug!( offer_id = offer_id.0, + key = %channel.offer.key(), gpadl_id = gpadl_id.0, "Gpadl teardown complete" ); - - let gpadl = if let Some(gpadl) = Self::get_gpadl(&mut self.inner.gpadls, offer_id, gpadl_id) - { - gpadl - } else { - return; - }; - let channel = &mut self.inner.channels[offer_id]; match gpadl.state { GpadlState::InProgress | GpadlState::Offered | GpadlState::OfferedTearingDown | GpadlState::Accepted => { - tracelimit::error_ratelimited!(?offer_id, ?gpadl_id, ?gpadl, "invalid gpadl state"); + tracelimit::error_ratelimited!(?offer_id, key = %channel.offer.key(), ?gpadl_id, ?gpadl, "invalid gpadl state"); } GpadlState::TearingDown => { if !channel.state.is_released() { diff --git a/vm/devices/vmbus/vmbus_server/src/lib.rs b/vm/devices/vmbus/vmbus_server/src/lib.rs index c54123797b..93bf9e059e 100644 --- a/vm/devices/vmbus/vmbus_server/src/lib.rs +++ b/vm/devices/vmbus/vmbus_server/src/lib.rs @@ -866,7 +866,7 @@ impl ServerTask { // revoked before being dropped. if let Some(channel) = self.inner.channels.get(&id.offer_id) { if channel.seq == id.seq { - tracing::info!(?id.offer_id, "revoking channel"); + tracing::info!(?id.offer_id, key = %channel.key, "revoking channel"); self.inner.channels.remove(&id.offer_id); self.server .with_notifier(&mut self.inner) @@ -963,7 +963,7 @@ impl ServerTask { .close_complete(offer_id); } _ => { - tracing::error!(?offer_id, "invalid close channel response"); + tracing::error!(?offer_id, key = %channel.key, "invalid close channel response"); } }; } @@ -1507,6 +1507,7 @@ impl Notifier for ServerTaskInner { let response = match action { channels::Action::Open(open_params, version) => { let seq = channel.seq; + let key = channel.key; match self.open_channel(offer_id, &open_params) { Ok((channel, interrupt)) => handle( offer_id, @@ -1524,6 +1525,7 @@ impl Notifier for ServerTaskInner { tracelimit::error_ratelimited!( err = err.as_ref() as &dyn std::error::Error, ?offer_id, + %key, "could not open channel", ); @@ -1946,6 +1948,7 @@ impl ServerTaskInner { .new_guest_message_port(self.redirect_vtl, new_target.vp, new_target.sint) .inspect_err(|err| { tracing::error!( + key = %channel.key, ?err, ?self.redirect_vtl, ?new_target, @@ -1963,6 +1966,7 @@ impl ServerTaskInner { // ignore it and just send to the old vp. if let Err(err) = message_port.set_target_vp(new_target.vp) { tracing::error!( + key = %channel.key, ?err, ?self.redirect_vtl, ?new_target, From e3fa0091896840a305df7b736c9a888220450b71 Mon Sep 17 00:00:00 2001 From: Sven Groot Date: Fri, 10 Oct 2025 13:20:41 -0700 Subject: [PATCH 2/5] Add key to vmbus_relay logs --- vm/devices/vmbus/vmbus_channel/src/bus.rs | 2 +- vm/devices/vmbus/vmbus_relay/src/lib.rs | 23 ++++++++++++++++++++--- 2 files changed, 21 insertions(+), 4 deletions(-) diff --git a/vm/devices/vmbus/vmbus_channel/src/bus.rs b/vm/devices/vmbus/vmbus_channel/src/bus.rs index 2ee8cd34d4..951d549de3 100644 --- a/vm/devices/vmbus/vmbus_channel/src/bus.rs +++ b/vm/devices/vmbus/vmbus_channel/src/bus.rs @@ -230,7 +230,7 @@ impl OpenRequest { } } -#[derive(Debug, Default, Copy, Clone, Hash, Eq, PartialEq, Ord, PartialOrd, Protobuf)] +#[derive(Debug, Default, Copy, Clone, Hash, Eq, PartialEq, Ord, PartialOrd, Protobuf, Inspect)] /// The identifying IDs for a channel offer. #[mesh(package = "vmbus")] pub struct OfferKey { diff --git a/vm/devices/vmbus/vmbus_relay/src/lib.rs b/vm/devices/vmbus/vmbus_relay/src/lib.rs index b04687c8f0..9612f388e6 100644 --- a/vm/devices/vmbus/vmbus_relay/src/lib.rs +++ b/vm/devices/vmbus/vmbus_relay/src/lib.rs @@ -47,6 +47,7 @@ use vmbus_channel::bus::ChannelRequest; use vmbus_channel::bus::ChannelServerRequest; use vmbus_channel::bus::GpadlRequest; use vmbus_channel::bus::ModifyRequest; +use vmbus_channel::bus::OfferKey; use vmbus_channel::bus::OpenRequest; use vmbus_client as client; use vmbus_core::HvsockConnectRequest; @@ -230,6 +231,8 @@ impl RelayChannelInfo { struct RelayChannel { /// The Channel Id given to us by the client channel_id: ChannelId, + /// The identifying key for this channel. + key: OfferKey, /// Receives requests from the relay. #[inspect(skip)] relay_request_recv: mesh::Receiver, @@ -331,7 +334,7 @@ impl RelayChannelTask { fn handle_gpadl_teardown(&mut self, rpc: Rpc) { let (gpadl_id, rpc) = rpc.split(); - tracing::trace!(gpadl_id = gpadl_id.0, "Tearing down GPADL"); + tracing::trace!(gpadl_id = gpadl_id.0, key = %self.channel.key, "Tearing down GPADL"); let call = self .channel @@ -342,9 +345,11 @@ impl RelayChannelTask { // message immediately, for example if the channel is still open and the host device still // has the gpadl mapped. We should not block further requests while waiting for the // response. + let key = self.channel.key; self.channel.gpadls_tearing_down.push(Box::pin(async move { if let Err(err) = call.await { tracing::warn!( + %key, error = &err as &dyn std::error::Error, "failed to send gpadl teardown" ); @@ -365,7 +370,7 @@ impl RelayChannelTask { /// Dispatch requests sent by VTL0 async fn handle_server_request(&mut self, request: ChannelRequest) -> Result<()> { - tracing::trace!(request = ?request, "received channel request"); + tracing::trace!(key = %self.channel.key, request = ?request, "received channel request"); match request { ChannelRequest::Open(rpc) => { rpc.handle(async |open_request| { @@ -374,6 +379,7 @@ impl RelayChannelTask { .inspect_err(|err| { tracelimit::error_ratelimited!( err = err.as_ref() as &dyn std::error::Error, + key = %self.channel.key, channel_id = self.channel.channel_id.0, "failed to open channel" ); @@ -390,6 +396,7 @@ impl RelayChannelTask { .inspect_err(|err| { tracelimit::error_ratelimited!( err = err.as_ref() as &dyn std::error::Error, + key = %self.channel.key, channel_id = self.channel.channel_id.0, gpadl_id = id.0, "failed to create gpadl" @@ -418,6 +425,7 @@ impl RelayChannelTask { async fn handle_relay_request(&mut self, request: RelayChannelRequest) { tracing::trace!( channel_id = self.channel.channel_id.0, + key = %self.channel.key, ?request, "received relay request" ); @@ -493,7 +501,11 @@ impl RelayChannelTask { // that the channel has been revoked. while let Some(()) = self.channel.gpadls_tearing_down.next().await {} - tracing::debug!(channel_id = %self.channel.channel_id.0, "dropped channel"); + tracing::debug!( + channel_id = %self.channel.channel_id.0, + key = %self.channel.key, + "dropped channel" + ); // Dropping the channel would revoke it, but since that's not synchronized there's a chance // we reoffer the channel before the server receives the revoke. Using the request ensures @@ -506,6 +518,7 @@ impl RelayChannelTask { { tracing::warn!( channel_id = self.channel.channel_id.0, + key = %self.channel.key, err = &err as &dyn std::error::Error, "failed to send revoke request" ); @@ -706,6 +719,7 @@ impl RelayTask { driver: Arc::clone(&self.spawner), channel: RelayChannel { channel_id: ChannelId(channel_id), + key, relay_request_recv, request_send: offer.request_send, revoke_recv: offer.revoke_recv, @@ -808,6 +822,7 @@ impl RelayTask { Err(err) => { tracing::error!( error = err.as_ref() as &dyn std::error::Error, + ?request, "failed add hvsock offer" ); false @@ -822,9 +837,11 @@ impl RelayTask { } async fn handle_offer_request(&mut self, request: client::OfferInfo) -> Result<()> { + let offer = request.offer; if let Err(err) = self.handle_offer(request).await { tracing::error!( error = err.as_ref() as &dyn std::error::Error, + ?offer, "failed to hot add offer" ); } From 09061ec4e743c561f9fa3e6bd28c8e24777d3b3c Mon Sep 17 00:00:00 2001 From: Sven Groot Date: Fri, 10 Oct 2025 13:37:41 -0700 Subject: [PATCH 3/5] Add key to vmbus_client logs. --- vm/devices/vmbus/vmbus_channel/src/bus.rs | 10 +++++ vm/devices/vmbus/vmbus_client/src/lib.rs | 47 ++++++++++++++++++----- 2 files changed, 47 insertions(+), 10 deletions(-) diff --git a/vm/devices/vmbus/vmbus_channel/src/bus.rs b/vm/devices/vmbus/vmbus_channel/src/bus.rs index 951d549de3..a5d0f5383d 100644 --- a/vm/devices/vmbus/vmbus_channel/src/bus.rs +++ b/vm/devices/vmbus/vmbus_channel/src/bus.rs @@ -255,6 +255,16 @@ impl Display for OfferKey { } } +impl From<&protocol::OfferChannel> for OfferKey { + fn from(offer: &protocol::OfferChannel) -> Self { + Self { + interface_id: offer.interface_id, + instance_id: offer.instance_id, + subchannel_index: offer.subchannel_index, + } + } +} + /// Channel offer parameters. #[derive(Debug, Clone, Default, mesh::MeshPayload)] pub struct OfferParams { diff --git a/vm/devices/vmbus/vmbus_client/src/lib.rs b/vm/devices/vmbus/vmbus_client/src/lib.rs index c8809a4e57..5c95cc6523 100644 --- a/vm/devices/vmbus/vmbus_client/src/lib.rs +++ b/vm/devices/vmbus/vmbus_client/src/lib.rs @@ -46,6 +46,7 @@ use vmbus_async::async_dgram::AsyncRecv; use vmbus_async::async_dgram::AsyncRecvExt; use vmbus_channel::bus::GpadlRequest; use vmbus_channel::bus::ModifyRequest; +use vmbus_channel::bus::OfferKey; use vmbus_channel::bus::OpenData; use vmbus_channel::gpadl::GpadlId; use vmbus_core::HvsockConnectRequest; @@ -810,9 +811,13 @@ impl ClientTask { } fn handle_rescind(&mut self, rescind: protocol::RescindChannelOffer) -> TriedRelease { - tracing::info!(state = %self.state, channel_id = rescind.channel_id.0, "received rescind"); - let mut channel = self.channels.get_mut(rescind.channel_id); + tracing::info!( + state = %self.state, + channel_id = rescind.channel_id.0, + key = %OfferKey::from(&channel.offer), + "received rescind" + ); let event_flag = match std::mem::replace(&mut channel.state, ChannelState::Revoked) { ChannelState::Offered => None, ChannelState::Opening { @@ -898,14 +903,14 @@ impl ClientTask { } fn handle_open_result(&mut self, result: protocol::OpenResult) { + let mut channel = self.channels.get_mut(result.channel_id); tracing::debug!( channel_id = result.channel_id.0, + key = %OfferKey::from(&channel.offer), result = result.status, "received open result" ); - let mut channel = self.channels.get_mut(result.channel_id); - let channel_opened = result.status == protocol::STATUS_SUCCESS as u32; let old_state = std::mem::replace(&mut channel.state, ChannelState::Offered); let ChannelState::Opening { @@ -915,6 +920,7 @@ impl ClientTask { } = old_state else { tracing::warn!( + key = %OfferKey::from(&channel.offer), old_state = ?channel.state, channel_opened, "invalid state for open result" @@ -946,13 +952,14 @@ impl ClientTask { panic!("gpadl {:#x} not in teardown list", request.gpadl_id.0); }; + let mut channel = self.channels.get_mut(channel_id); tracing::debug!( gpadl_id = request.gpadl_id.0, channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), "Received GpadlTorndown" ); - let mut channel = self.channels.get_mut(channel_id); let gpadl_state = channel .gpadls .remove(&request.gpadl_id) @@ -1108,7 +1115,12 @@ impl ClientTask { } } - tracing::info!(channel_id = channel_id.0, "opening channel on host"); + tracing::info!( + channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), + "opening channel on host" + ); + let (request, rpc) = rpc.split(); let open_data = &request.open_data; @@ -1241,6 +1253,7 @@ impl ClientTask { tracing::trace!( channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), gpadl_id = request.id.0, count = request.count, len = request.buf.len(), @@ -1286,6 +1299,7 @@ impl ClientTask { tracing::warn!( gpadl_id = gpadl_id.0, channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), "Gpadl teardown for unknown gpadl or revoked channel" ); return; @@ -1296,6 +1310,7 @@ impl ClientTask { tracing::warn!( gpadl_id = gpadl_id.0, channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), "gpadl teardown for offered gpadl" ); } @@ -1388,6 +1403,7 @@ impl ClientTask { if let ChannelState::Opened { .. } = channel.state { tracing::warn!( channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), "Channel dropped without closing first" ); self.inner.close_channel(channel_id, &mut channel); @@ -1576,13 +1592,19 @@ impl ClientTaskInner { if let Some(flag) = redirected_event_flag { self.synic.free_event_flag(flag); } - tracing::info!(channel_id = channel_id.0, "closing channel on host"); + tracing::info!( + channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), + "closing channel on host" + ); + self.messages.send(&protocol::CloseChannel { channel_id }); channel.state = ChannelState::Offered; channel.connection_id.store(0, Ordering::Release); } else { tracing::warn!( - id = %channel_id.0, + channel_id = channel_id.0, + key = %OfferKey::from(&channel.offer), channel_state = %channel.state, "invalid channel state for close channel" ); @@ -1744,7 +1766,7 @@ struct TriedRelease(()); impl ChannelRef<'_> { /// If the channel has been fully released (revoked, released by the client, - /// no pending requests), notifes the server and removes this channel from + /// no pending requests), notifies the server and removes this channel from /// the map. fn try_release(self, messages: &mut OutgoingMessages) -> TriedRelease { if self.is_client_released @@ -1752,7 +1774,12 @@ impl ChannelRef<'_> { && self.pending_request().is_none() { let channel_id = *self.0.key(); - tracelimit::info_ratelimited!(channel_id = channel_id.0, "releasing channel"); + tracelimit::info_ratelimited!( + channel_id = channel_id.0, + key = %OfferKey::from(&self.offer), + "releasing channel" + ); + messages.send(&protocol::RelIdReleased { channel_id }); self.0.remove(); } From 2256d5c94d36065d59855773fa3e6d8f19b2f21f Mon Sep 17 00:00:00 2001 From: Sven Groot Date: Fri, 10 Oct 2025 13:47:19 -0700 Subject: [PATCH 4/5] Additional logs for close and release --- vm/devices/vmbus/vmbus_server/src/channels.rs | 1 + vm/devices/vmbus/vmbus_server/src/lib.rs | 1 + 2 files changed, 2 insertions(+) diff --git a/vm/devices/vmbus/vmbus_server/src/channels.rs b/vm/devices/vmbus/vmbus_server/src/channels.rs index a9d96b56c8..80f41be051 100644 --- a/vm/devices/vmbus/vmbus_server/src/channels.rs +++ b/vm/devices/vmbus/vmbus_server/src/channels.rs @@ -3180,6 +3180,7 @@ impl<'a, N: 'a + Notifier> ServerWithNotifier<'a, N> { assigned_monitors: &mut AssignedMonitors, info: Option<&ConnectionInfo>, ) -> bool { + tracelimit::info_ratelimited!(?offer_id, key = %channel.offer.key(), "client released channel"); // Release any GPADLs that remain for this channel. gpadls.retain(|&(gpadl_id, gpadl_offer_id), gpadl| { if gpadl_offer_id != offer_id { diff --git a/vm/devices/vmbus/vmbus_server/src/lib.rs b/vm/devices/vmbus/vmbus_server/src/lib.rs index 93bf9e059e..0b267c1c6b 100644 --- a/vm/devices/vmbus/vmbus_server/src/lib.rs +++ b/vm/devices/vmbus/vmbus_server/src/lib.rs @@ -957,6 +957,7 @@ impl ServerTask { match &mut channel.state { ChannelState::Closing => { + tracing::debug!(?offer_id, key = %channel.key, "closing channel"); channel.state = ChannelState::Closed; self.server .with_notifier(&mut self.inner) From 5d91569653276f4bd93c2934690233d0d90b3d9f Mon Sep 17 00:00:00 2001 From: Sven Groot Date: Fri, 10 Oct 2025 14:13:10 -0700 Subject: [PATCH 5/5] Additional hvsock logs --- vm/devices/vmbus/vmbus_server/src/hvsock.rs | 16 +++++++++++++++- vm/devices/vmbus/vmbus_server/src/lib.rs | 2 ++ 2 files changed, 17 insertions(+), 1 deletion(-) diff --git a/vm/devices/vmbus/vmbus_server/src/hvsock.rs b/vm/devices/vmbus/vmbus_server/src/hvsock.rs index e30b19b95d..7e121e96dd 100644 --- a/vm/devices/vmbus/vmbus_server/src/hvsock.rs +++ b/vm/devices/vmbus/vmbus_server/src/hvsock.rs @@ -234,6 +234,8 @@ impl ListenerWorker { error = &err as &dyn std::error::Error, "connection relay failed" ); + } else { + tracing::debug!(%service_id, "connection relay finished"); } }); @@ -440,13 +442,25 @@ impl RelayInner { .await .context("failed to offer channel")?; + tracing::debug!(?request, "connected guest to host"); + let service_id = request.service_id; + // Now that the channel is offered, report that the connection operation is // done. pending.done(true); let channel = offer.accept(self.driver.as_ref()).await?.channel; let channel = BytePipe::new(channel)?; - relay_connected(channel, socket).await?; + if let Err(err) = relay_connected(channel, socket).await { + tracing::error!( + %service_id, + error = &err as &dyn std::error::Error, + "guest to host connection relay failed" + ); + } else { + tracing::debug!(%service_id, "guest to host connection relay finished"); + } + // N.B. offer needs to stay alive until here to avoid revoking the channel // before the relay is done. drop(offer); diff --git a/vm/devices/vmbus/vmbus_server/src/lib.rs b/vm/devices/vmbus/vmbus_server/src/lib.rs index 0b267c1c6b..e6e0d71cf0 100644 --- a/vm/devices/vmbus/vmbus_server/src/lib.rs +++ b/vm/devices/vmbus/vmbus_server/src/lib.rs @@ -1156,6 +1156,7 @@ impl ServerTask { } fn handle_tl_connect_result(&mut self, result: HvsockConnectResult) { + tracing::debug!(?result, "hvsock connect result"); assert_ne!(self.inner.hvsock_requests, 0); self.inner.hvsock_requests -= 1; @@ -1725,6 +1726,7 @@ impl Notifier for ServerTaskInner { } fn notify_hvsock(&mut self, request: &HvsockConnectRequest) { + tracing::debug!(?request, "received hvsock connect request"); self.hvsock_requests += 1; self.hvsock_send.send(*request); }