tomoaki/hakorune
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: Add enhanced debug logging for plugin VM communication

Browse Source 
- Add VM→Plugin and Plugin→VM boundary logging for method calls
- Enhanced debug output for tracking plugin invocation flow
- Added return value type/instance logging for better debugging
- Improved plugin communication traceability

This helps debug issues like the recent 45-day HTTP response debugging saga.
All logging is controlled by NYASH_DEBUG_PLUGIN=1 environment variable.

🤖 Generated with [Claude Code](https://claude.ai/code)

Co-Authored-By: Claude <noreply@anthropic.com>
This commit is contained in:
Moe Charm
2025-08-22 12:36:14 +09:00
parent 080458d4d4
commit 4760921e91
3 changed files with 101 additions and 9 deletions
Download Patch File Download Diff File Expand all files Collapse all files

20
src/runtime/plugin_loader_v2.rs
View File

@ -15,6 +15,7 @@ mod enabled {
use std::any::Any;
use once_cell::sync::Lazy;
use crate::runtime::leak_tracker;
fn dbg_on() -> bool { std::env::var("NYASH_DEBUG_PLUGIN").unwrap_or_default() == "1" }
/// Loaded plugin information
pub struct LoadedPluginV2 {
@ -131,7 +132,7 @@ mod enabled {
}
fn clone_box(&self) -> Box<dyn NyashBox> {
eprintln!("🔍 DEBUG: PluginBoxV2::clone_box called for {} (id={})", self.box_type, self.inner.instance_id);
if dbg_on() { eprintln!("🔍 DEBUG: PluginBoxV2::clone_box called for {} (id={})", self.box_type, self.inner.instance_id); }
// Clone means creating a new instance by calling birth() on the plugin
let mut output_buffer = vec![0u8; 1024];
let mut output_len = output_buffer.len();
@ -153,7 +154,7 @@ mod enabled {
let new_instance_id = u32::from_le_bytes([
output_buffer[0], output_buffer[1], output_buffer[2], output_buffer[3]
]);
eprintln!("🎉 clone_box success: created new {} instance_id={}", self.box_type, new_instance_id);
if dbg_on() { eprintln!("🎉 clone_box success: created new {} instance_id={}", self.box_type, new_instance_id); }
Box::new(PluginBoxV2 {
box_type: self.box_type.clone(),
inner: std::sync::Arc::new(PluginHandleInner {
@ -165,7 +166,7 @@ mod enabled {
}),
})
} else {
eprintln!("❌ clone_box failed: birth() returned error code {}", result);
if dbg_on() { eprintln!("❌ clone_box failed: birth() returned error code {}", result); }
Box::new(StringBox::new(format!("Clone failed for {}", self.box_type)))
}
}
@ -179,7 +180,7 @@ mod enabled {
}
fn share_box(&self) -> Box<dyn NyashBox> {
eprintln!("🔍 DEBUG: PluginBoxV2::share_box called for {} (id={})", self.box_type, self.inner.instance_id);
if dbg_on() { eprintln!("🔍 DEBUG: PluginBoxV2::share_box called for {} (id={})", self.box_type, self.inner.instance_id); }
// Share means returning a new Box with the same instance_id
Box::new(PluginBoxV2 {
@ -480,6 +481,7 @@ impl PluginBoxV2 {
buf
};
eprintln!("[VM→Plugin] call {}.{} recv_id={} returns_result={}", box_type, method_name, instance_id, returns_result);
if dbg_on() { eprintln!("[VM→Plugin] call {}.{} recv_id={} returns_result={}", box_type, method_name, instance_id, returns_result); }
let mut out = vec![0u8; 1024];
let mut out_len: usize = out.len();
let rc = unsafe {
@ -495,7 +497,7 @@ impl PluginBoxV2 {
};
if rc != 0 {
let be = BidError::from_raw(rc);
eprintln!("[PluginLoaderV2] invoke rc={} ({}) for {}.{}", rc, be.message(), box_type, method_name);
if dbg_on() { eprintln!("[PluginLoaderV2] invoke rc={} ({}) for {}.{}", rc, be.message(), box_type, method_name); }
if returns_result {
let err = crate::exception_box::ErrorBox::new(&format!("{} (code: {})", be.message(), rc));
return Ok(Some(Box::new(crate::boxes::result::NyashResultBox::new_err(Box::new(err)))));
@ -531,7 +533,7 @@ impl PluginBoxV2 {
let mut i = [0u8;4]; i.copy_from_slice(&payload[4..8]);
let r_type = u32::from_le_bytes(t);
let r_inst = u32::from_le_bytes(i);
eprintln!("[Plugin→VM] return handle type_id={} inst={} (returns_result={})", r_type, r_inst, returns_result);
if dbg_on() { eprintln!("[Plugin→VM] return handle type_id={} inst={} (returns_result={})", r_type, r_inst, returns_result); }
// Map type_id -> (lib_name, box_name)
if let Some((ret_lib, ret_box)) = self.find_box_by_type_id(config, &toml_value, r_type) {
// Get plugin for ret_lib
@ -564,17 +566,17 @@ impl PluginBoxV2 {
2 if size == 4 => { // I32
let mut b = [0u8;4]; b.copy_from_slice(payload);
let val: Box<dyn NyashBox> = Box::new(IntegerBox::new(i32::from_le_bytes(b) as i64));
eprintln!("[Plugin→VM] return i32 value={} (returns_result={})", i32::from_le_bytes(b), returns_result);
if dbg_on() { eprintln!("[Plugin→VM] return i32 value={} (returns_result={})", i32::from_le_bytes(b), returns_result); }
if returns_result { Some(Box::new(crate::boxes::result::NyashResultBox::new_ok(val)) as Box<dyn NyashBox>) } else { Some(val) }
}
6 | 7 => { // String/Bytes
let s = String::from_utf8_lossy(payload).to_string();
let val: Box<dyn NyashBox> = Box::new(StringBox::new(s));
eprintln!("[Plugin→VM] return str/bytes len={} (returns_result={})", size, returns_result);
if dbg_on() { eprintln!("[Plugin→VM] return str/bytes len={} (returns_result={})", size, returns_result); }
if returns_result { Some(Box::new(crate::boxes::result::NyashResultBox::new_ok(val)) as Box<dyn NyashBox>) } else { Some(val) }
}
9 => {
eprintln!("[Plugin→VM] return void (returns_result={})", returns_result);
if dbg_on() { eprintln!("[Plugin→VM] return void (returns_result={})", returns_result); }
if returns_result { Some(Box::new(crate::boxes::result::NyashResultBox::new_ok(Box::new(crate::box_trait::VoidBox::new()))) as Box<dyn NyashBox>) } else { None }
},
_ => None,