svm: integrate logger into syscalls (#578)

src/svm/main.zig

@@ -21,6 +21,9 @@ pub fn main() !void {
     else
         std.heap.c_allocator;
 
+    var std_logger = sig.trace.DirectPrintLogger.init(allocator, .debug);
+    const logger = std_logger.logger();
+
     var input_path: ?[]const u8 = null;
     var assemble: bool = false;
     var version: sbpf.Version = .v3;
@@ -106,7 +109,14 @@ pub fn main() !void {
         memory.Region.init(.mutable, &.{}, memory.INPUT_START),
     }, executable.version);
 
-    var vm = try Vm.init(allocator, &executable, m, &loader, stack_memory.len);
+    var vm = try Vm.init(
+        allocator,
+        &executable,
+        m,
+        &loader,
+        logger,
+        stack_memory.len,
+    );
     defer vm.deinit();
     const result = try vm.run();
 

src/svm/syscalls.zig

@@ -31,7 +31,7 @@ pub fn log(vm: *Vm) Error!void {
     const len = vm.registers.get(.r2);
     const host_addr = try vm.memory_map.vmap(.constant, vm_addr, len);
     const string = std.mem.sliceTo(host_addr, 0);
-    if (!builtin.is_test) std.debug.print("{d}\n", .{string});
+    vm.logger.logf(.info, "{s}", .{string});
 }
 
 pub fn log64(vm: *Vm) Error!void {
@@ -41,8 +41,9 @@ pub fn log64(vm: *Vm) Error!void {
     const arg4 = vm.registers.get(.r4);
     const arg5 = vm.registers.get(.r5);
 
-    std.debug.print(
-        "log: 0x{x} 0x{x} 0x{x} 0x{x} 0x{x}\n",
+    vm.logger.logf(
+        .info,
+        "log: 0x{x} 0x{x} 0x{x} 0x{x} 0x{x}",
         .{ arg1, arg2, arg3, arg4, arg5 },
     );
 }
@@ -51,11 +52,11 @@ pub fn logPubkey(vm: *Vm) Error!void {
     const pubkey_addr = vm.registers.get(.r1);
     const pubkey_bytes = try vm.memory_map.vmap(.constant, pubkey_addr, @sizeOf(Pubkey));
     const pubkey: Pubkey = @bitCast(pubkey_bytes[0..@sizeOf(Pubkey)].*);
-    std.debug.print("log: {}\n", .{pubkey});
+    vm.logger.logf(.info, "log: {}", .{pubkey});
 }
 
-pub fn logComputeUnits(_: *Vm) Error!void {
-    std.debug.print("TODO: compute budget calculations\n", .{});
+pub fn logComputeUnits(vm: *Vm) Error!void {
+    vm.logger.log(.warn, "TODO: compute budget calculations");
 }
 
 // memory operators
@@ -151,8 +152,7 @@ pub fn panic(vm: *Vm) Error!void {
     // const column = vm.registers.get(.r4);
 
     const message = try vm.memory_map.vmap(.constant, file, len);
-    if (!builtin.is_test)
-        std.debug.print("panic: {s}\n", .{message});
+    vm.logger.logf(.err, "panic: {s}", .{message});
     return error.SyscallAbort;
 }
 

src/svm/tests.zig

@@ -43,7 +43,14 @@ fn testAsmWithMemory(
     }, .v0);
 
     var loader: BuiltinProgram = .{};
-    var vm = try Vm.init(allocator, &executable, m, &loader, stack_memory.len);
+    var vm = try Vm.init(
+        allocator,
+        &executable,
+        m,
+        &loader,
+        .noop,
+        stack_memory.len,
+    );
     defer vm.deinit();
 
     const result = vm.run();
@@ -1904,7 +1911,14 @@ test "pqr" {
         var loader: BuiltinProgram = .{};
         const map = try MemoryMap.init(&.{}, .v2);
 
-        var vm = try Vm.init(allocator, &executable, map, &loader, 0);
+        var vm = try Vm.init(
+            allocator,
+            &executable,
+            map,
+            &loader,
+            .noop,
+            0,
+        );
         defer vm.deinit();
 
         const unsigned_expected: u64 = expected;
@@ -1945,7 +1959,14 @@ test "pqr divide by zero" {
         var loader: BuiltinProgram = .{};
         const map = try MemoryMap.init(&.{}, .v3);
 
-        var vm = try Vm.init(allocator, &executable, map, &loader, 0);
+        var vm = try Vm.init(
+            allocator,
+            &executable,
+            map,
+            &loader,
+            .noop,
+            0,
+        );
         defer vm.deinit();
 
         try expectEqual(error.DivisionByZero, vm.run());
@@ -2167,7 +2188,14 @@ pub fn testElfWithSyscalls(
         Region.init(.mutable, &.{}, memory.INPUT_START),
     }, .v0);
 
-    var vm = try Vm.init(allocator, &executable, m, &loader, stack_memory.len);
+    var vm = try Vm.init(
+        allocator,
+        &executable,
+        m,
+        &loader,
+        .noop,
+        stack_memory.len,
+    );
     defer vm.deinit();
 
     const result = vm.run();

src/svm/vm.zig

@@ -2,6 +2,7 @@ const std = @import("std");
 const lib = @import("lib.zig");
 const sbpf = @import("sbpf.zig");
 const memory = @import("memory.zig");
+const sig = @import("../sig.zig");
 
 const MemoryMap = memory.MemoryMap;
 const Instruction = sbpf.Instruction;
@@ -10,6 +11,7 @@ const BuiltinProgram = lib.BuiltinProgram;
 
 pub const Vm = struct {
     allocator: std.mem.Allocator,
+    logger: sig.trace.Logger,
     executable: *const Executable,
 
     registers: std.EnumArray(sbpf.Instruction.Register, u64),
@@ -32,6 +34,7 @@ pub const Vm = struct {
         executable: *const Executable,
         memory_map: MemoryMap,
         loader: *const BuiltinProgram,
+        logger: sig.trace.Logger,
         stack_len: u64,
     ) !Vm {
         const offset = if (executable.version.enableDynamicStackFrames())
@@ -49,6 +52,7 @@ pub const Vm = struct {
             .instruction_count = 0,
             .vm_addr = executable.text_vaddr,
             .loader = loader,
+            .logger = logger,
         };
 
         self.registers.set(.r10, stack_pointer);