Skip to content

Commit 0cc6be5

Browse files
simongdaviessimongdavies
committed
more logging
Signed-off-by: Simon Davies <[email protected]>
1 parent bc5e374 commit 0cc6be5

File tree

4 files changed

+41
-21
lines changed

4 files changed

+41
-21
lines changed

‎src/hyperlight_host/Cargo.toml‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,7 @@ strum = { version = "0.27", features = ["derive"] }
4848
tempfile = { version = "3.17", optional = true }
4949
serde_yaml = "0.9"
5050
anyhow = "1.0"
51+
uuid = { version = "1.13.2", features = ["v4"] }
5152

5253
[target.'cfg(windows)'.dependencies]
5354
windows = { version = "0.59", features = [

‎src/hyperlight_host/benches/benchmarks.rs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -134,6 +134,7 @@ fn sandbox_benchmark(c: &mut Criterion) {
134134

135135
// Benchmarks the time to create a new sandbox, create a new call context, and drop the call context.
136136
group.bench_function("create_sandbox_and_call_context_and_drop", |b| {
137+
let _ = env_logger::builder().parse_filters("debug").try_init();
137138
b.iter(|| create_multiuse_sandbox().new_call_context());
138139
});
139140

‎src/hyperlight_host/src/hypervisor/hypervisor_handler.rs‎

Lines changed: 31 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -73,6 +73,7 @@ pub(crate) struct HypervisorHandler {
7373
communication_channels: HvHandlerCommChannels,
7474
configuration: HvHandlerConfig,
7575
execution_variables: HvHandlerExecVars,
76+
id: String,
7677
}
7778

7879
impl HypervisorHandler {
@@ -226,6 +227,7 @@ impl HypervisorHandler {
226227
communication_channels,
227228
configuration,
228229
execution_variables,
230+
id: uuid::Uuid::new_v4().to_string(),
229231
}
230232
}
231233

@@ -289,6 +291,8 @@ impl HypervisorHandler {
289291
#[cfg(target_os = "linux")]
290292
setup_signal_handlers()?;
291293

294+
let id = self.id.clone();
295+
292296
let join_handle = {
293297
thread::Builder::new()
294298
.name("Hypervisor Handler".to_string())
@@ -324,7 +328,7 @@ impl HypervisorHandler {
324328
#[cfg(target_os = "linux")]
325329
execution_variables.run_cancelled.store(false);
326330

327-
log::info!("Initialising Hypervisor Handler");
331+
log::info!("Initialising Hypervisor Handler id: {}", id);
328332

329333
let mut evar_lock_guard =
330334
execution_variables.shm.try_lock().map_err(|e| {
@@ -367,7 +371,7 @@ impl HypervisorHandler {
367371

368372
match res {
369373
Ok(_) => {
370-
log::info!("Initialised Hypervisor Handler");
374+
log::info!("Initialised Hypervisor Handler id: {}", id);
371375
from_handler_tx
372376
.send(HandlerMsg::FinishedHypervisorHandlerAction)
373377
.map_err(|_| {
@@ -376,8 +380,8 @@ impl HypervisorHandler {
376380
}
377381
Err(e) => {
378382
log::info!(
379-
"Error initialising Hypervisor Handler: {:?}",
380-
e
383+
"Error initialising Hypervisor Handler: {:?} id: {}",
384+
e, id
381385
);
382386
from_handler_tx.send(HandlerMsg::Error(e)).map_err(|_| {
383387
HyperlightError::HypervisorHandlerCommunicationFailure()
@@ -394,7 +398,7 @@ impl HypervisorHandler {
394398
#[cfg(target_os = "linux")]
395399
execution_variables.run_cancelled.store(false);
396400

397-
info!("Dispatching call from host: {}", function_name);
401+
info!("Dispatching call from host: {} id: {}", function_name, id);
398402

399403
let dispatch_function_addr = configuration
400404
.dispatch_function_addr
@@ -473,8 +477,10 @@ impl HypervisorHandler {
473477
match res {
474478
Ok(_) => {
475479
log::info!(
476-
"Finished dispatching call from host: {}",
477-
function_name
480+
"Finished dispatching call from host: {} id: {}",
481+
function_name,
482+
id
483+
478484
);
479485
from_handler_tx
480486
.send(HandlerMsg::FinishedHypervisorHandlerAction)
@@ -484,9 +490,10 @@ impl HypervisorHandler {
484490
}
485491
Err(e) => {
486492
log::info!(
487-
"Error dispatching call from host: {}: {:?}",
493+
"Error dispatching call from host: {}: {:?} id: {}",
488494
function_name,
489-
e
495+
e,
496+
id
490497
);
491498
from_handler_tx.send(HandlerMsg::Error(e)).map_err(|_| {
492499
HyperlightError::HypervisorHandlerCommunicationFailure()
@@ -495,21 +502,22 @@ impl HypervisorHandler {
495502
}
496503
}
497504
HypervisorHandlerAction::TerminateHandlerThread => {
498-
info!("Terminating Hypervisor Handler Thread");
505+
info!("Terminating Hypervisor Handler Thread id: {}", id);
499506
break;
500507
}
501508
}
502509
}
503-
504510
// If we make it here, it means the main thread issued a `TerminateHandlerThread` action,
505511
// and we are now exiting the handler thread.
506512
{
513+
log::info!("Handler thread sending exit message, id: {}", id);
507514
from_handler_tx
508515
.send(HandlerMsg::FinishedHypervisorHandlerAction)
509516
.map_err(|_| {
510517
HyperlightError::HypervisorHandlerCommunicationFailure()
511-
})?;
518+
}).inspect_err(|e| log::error!("Failed to send finish message on termination: {:?} id :{}", e, id))?;
512519
}
520+
log::info!("Handler thread exiting, id: {}", id);
513521

514522
Ok(())
515523
})
@@ -561,7 +569,7 @@ impl HypervisorHandler {
561569
/// Tries to kill the Hypervisor Handler Thread.
562570
#[instrument(err(Debug), skip_all, parent = Span::current(), level = "Trace")]
563571
pub(crate) fn kill_hypervisor_handler_thread(&mut self) -> Result<()> {
564-
log::debug!("Killing Hypervisor Handler Thread");
572+
log::debug!("Killing Hypervisor Handler Thread Id {:?}", self.id);
565573
self.execute_hypervisor_handler_action(HypervisorHandlerAction::TerminateHandlerThread)?;
566574

567575
self.try_join_hypervisor_handler_thread()
@@ -576,8 +584,9 @@ impl HypervisorHandler {
576584
hypervisor_handler_action: HypervisorHandlerAction,
577585
) -> Result<()> {
578586
log::debug!(
579-
"Sending Hypervisor Handler Action: {:?}",
580-
hypervisor_handler_action
587+
"Sending Hypervisor Handler Action: {:?} id: {}",
588+
hypervisor_handler_action,
589+
self.id
581590
);
582591

583592
match hypervisor_handler_action {
@@ -600,7 +609,7 @@ impl HypervisorHandler {
600609
.send(hypervisor_handler_action)
601610
.map_err(|_| HyperlightError::HypervisorHandlerCommunicationFailure())?;
602611

603-
log::debug!("Waiting for Hypervisor Handler Response");
612+
log::debug!("Waiting for Hypervisor Handler Response id: {}", self.id);
604613

605614
self.try_receive_handler_msg()
606615
}
@@ -626,6 +635,8 @@ impl HypervisorHandler {
626635
.from_handler_rx
627636
.recv_timeout(self.execution_variables.get_timeout()?);
628637

638+
let id = self.id.clone();
639+
629640
match response {
630641
Ok(msg) => match msg {
631642
HandlerMsg::Error(e) => Err(e),
@@ -649,8 +660,9 @@ impl HypervisorHandler {
649660
if res.as_ref().is_ok_and(|inner_res| inner_res.is_err()) {
650661
let err = res.unwrap().unwrap_err();
651662
log::debug!(
652-
"Handler thread finished with error: {:?} before sending message",
653-
err
663+
"Handler thread finished with error: {:?} before sending message id: {}",
664+
err,
665+
id,
654666
);
655667
return Err(err);
656668
}
@@ -729,7 +741,7 @@ impl HypervisorHandler {
729741
// Re-initialise the vCPU.
730742
// This is 100% needed because, otherwise, all it takes to cause a DoS is for a
731743
// function to timeout as the vCPU will be in a bad state without re-init.
732-
log::debug!("Re-initialising vCPU");
744+
log::debug!("Re-initialising vCPU id {}", self.id);
733745
self.execute_hypervisor_handler_action(HypervisorHandlerAction::Initialise)?;
734746

735747
res

‎src/hyperlight_host/src/sandbox/initialized_multi_use.rs‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -56,8 +56,11 @@ pub struct MultiUseSandbox {
5656
// `create_1000_sandboxes`.
5757
impl Drop for MultiUseSandbox {
5858
fn drop(&mut self) {
59+
log::debug!("Killing hypervisor handler thread in multiusesandbox drop");
5960
match self.hv_handler.kill_hypervisor_handler_thread() {
60-
Ok(_) => {}
61+
Ok(_) => {
62+
log::debug!("Killed hypervisor handler thread in multiusesandbox drop");
63+
}
6164
Err(e) => {
6265
log::error!("[POTENTIAL THREAD LEAK] Potentially failed to kill hypervisor handler thread when dropping MultiUseSandbox: {:?}", e);
6366
}
@@ -152,7 +155,10 @@ impl MultiUseSandbox {
152155
/// ```
153156
#[instrument(skip_all, parent = Span::current())]
154157
pub fn new_call_context(self) -> MultiUseGuestCallContext {
155-
MultiUseGuestCallContext::start(self)
158+
log::debug!("Creating new MultiUseGuestCallContext");
159+
let c = MultiUseGuestCallContext::start(self);
160+
log::debug!("Created new MultiUseGuestCallContext");
161+
c
156162
}
157163

158164
/// Call a guest function by name, with the given return type and arguments.

0 commit comments

Comments
 (0)