add a bunch of logging to haku, including vm-trace for tracing what the VM does

crates/haku/Cargo.toml

@@ -6,3 +6,7 @@ edition = "2021"
 [dependencies]
 log.workspace = true
 tiny-skia = { version = "0.11.4", default-features = false, features = ["no-std-float"] }
+
+[features]
+default = []
+vm-trace = []

crates/haku/src/parser.rs

@@ -1,6 +1,7 @@
 use core::{cell::Cell, error::Error, fmt};
 
 use alloc::vec::Vec;
+use log::{error, info};
 
 use crate::{
     ast::{Ast, NodeAllocError, NodeId, NodeKind},
@@ -157,6 +158,7 @@ impl<'a> Parser<'a> {
     pub fn into_ast(self, ast: &mut Ast) -> Result<(NodeId, Vec<Diagnostic>), IntoAstError> {
         // If events are at capacity, that means the pool was exhausted and we return an error.
         if self.events.len() == self.events.capacity() {
+            error!("parser is at capacity");
             return Err(IntoAstError::TooManyEvents);
         }
 
@@ -171,13 +173,16 @@ impl<'a> Parser<'a> {
         }
 
         // Remove the last Close to keep a single node on the stack.
-        assert!(matches!(
+        if !matches!(
             events.pop(),
             Some(Event {
                 kind: EventKind::Close,
                 ..
             })
-        ));
+        ) {
+            error!("parser should have produced a Close event, but didn't");
+            return Err(IntoAstError::UnbalancedEvents);
+        }
 
         for event in events {
             match event.kind {
@@ -209,6 +214,7 @@ impl<'a> Parser<'a> {
 
         if stack.len() != 1 {
             // This means we had too many events emitted and they are no longer balanced.
+            error!("parser produced an unbalanced amount of events");
             return Err(IntoAstError::UnbalancedEvents);
         }
         // assert_eq!(token, self.tokens.len());

crates/haku/src/vm.rs

@@ -5,7 +5,6 @@ use core::{
 };
 
 use alloc::{string::String, vec::Vec};
-use log::info;
 
 use crate::{
     bytecode::{self, Defs, Opcode, CAPTURE_CAPTURE, CAPTURE_LOCAL},
@@ -13,6 +12,15 @@ use crate::{
     value::{BytecodeLoc, Closure, FunctionName, List, Ref, RefId, Rgba, Value, Vec4},
 };
 
+macro_rules! vmtrace {
+    ($($args:expr),* $(,)?) => {
+        #[cfg(feature = "vm-trace")]
+        {
+            log::info!($($args),*);
+        }
+    }
+}
+
 pub struct VmLimits {
     pub stack_capacity: usize,
     pub call_stack_capacity: usize,
@@ -129,6 +137,7 @@ impl Vm {
             ));
         }
         self.stack.push(value);
+        vmtrace!("push {:?}", self.stack);
         Ok(())
     }
 
@@ -147,9 +156,12 @@ impl Vm {
     }
 
     fn pop(&mut self) -> Result<Value, Exception> {
-        self.stack
+        let value = self
+            .stack
             .pop()
-            .ok_or_else(|| self.create_exception("corrupted bytecode (value stack underflow)"))
+            .ok_or_else(|| self.create_exception("corrupted bytecode (value stack underflow)"))?;
+        vmtrace!("pop  {:?} -> {:?}", self.stack, value);
+        Ok(value)
     }
 
     fn push_call(&mut self, frame: CallFrame) -> Result<(), Exception> {
@@ -198,7 +210,9 @@ impl Vm {
                 .checked_sub(1)
                 .ok_or_else(|| self.create_exception("code ran for too long"))?;
 
+            let pc2 = pc;
             let opcode = chunk.read_opcode(&mut pc)?;
+            vmtrace!("{pc2:2} {opcode:?}");
             match opcode {
                 Opcode::Nil => self.push(Value::Nil)?,
                 Opcode::False => self.push(Value::False)?,
@@ -301,7 +315,7 @@ impl Vm {
                         })
                     }
 
-                    let id = self.create_ref(Ref::Closure(Closure {
+                    let closure = Closure {
                         start: BytecodeLoc {
                             chunk_id,
                             offset: body as u16,
@@ -310,7 +324,9 @@ impl Vm {
                         param_count,
                         local_count,
                         captures,
-                    }))?;
+                    };
+                    vmtrace!("{closure:?}");
+                    let id = self.create_ref(Ref::Closure(closure))?;
                     self.push(Value::Ref(id))?;
                 }
 

crates/rkgk/Cargo.toml

@@ -35,3 +35,4 @@ webp = "0.3.0"
 [features]
 default = []
 memory-profiling = ["dep:tracy-client"]
+haku-vm-trace = ["haku/vm-trace"]