Enable more verbose TVM stack dump (#669)

* Verbose stack dump

* Move vm::VmLog::DumpStack and vm::VmLog::DumpStackVerbose to the next verbosity levels

crypto/block/transaction.cpp

@@ -1081,7 +1081,13 @@ bool Transaction::prepare_compute_phase(const ComputePhaseConfig& cfg) {
     if (cfg.vm_log_verbosity > 1) {
       vm_log.log_mask |= vm::VmLog::ExecLocation;
       if (cfg.vm_log_verbosity > 2) {
-        vm_log.log_mask |= vm::VmLog::DumpStack | vm::VmLog::GasRemaining;
+        vm_log.log_mask |= vm::VmLog::GasRemaining;
+        if (cfg.vm_log_verbosity > 3) {
+          vm_log.log_mask |= vm::VmLog::DumpStack;
+          if (cfg.vm_log_verbosity > 4) {
+            vm_log.log_mask |= vm::VmLog::DumpStackVerbose;
+          }
+        }
       }
     }
   }

crypto/smc-envelope/SmartContract.cpp

@@ -185,7 +185,13 @@ SmartContract::Answer run_smartcont(SmartContract::State state, td::Ref<vm::Stac
   if (vm_log_verbosity > 1) {
     log.log_mask |= vm::VmLog::ExecLocation;
     if (vm_log_verbosity > 2) {
-      log.log_mask |= vm::VmLog::DumpStack | vm::VmLog::GasRemaining;
+      log.log_mask |= vm::VmLog::GasRemaining;
+      if (vm_log_verbosity > 3) {
+        log.log_mask |= vm::VmLog::DumpStack;
+        if (vm_log_verbosity > 4) {
+          log.log_mask |= vm::VmLog::DumpStackVerbose;
+        }
+      }
     }
   }
 

crypto/vm/continuation.cpp

@@ -22,6 +22,8 @@
 #include "vm/log.h"
 #include "vm/vm.h"
 #include "vm/vmstate.h"
+#include "vm/boc.h"
+#include "td/utils/misc.h"
 
 namespace vm {
 
@@ -254,6 +256,16 @@ bool Continuation::deserialize_to(Ref<Cell> cell, Ref<Continuation>& cont, int m
   return deserialize_to(cs, cont, mode & ~0x1000) && cs.empty_ext();
 }
 
+std::ostream& operator<<(std::ostream& os, const Continuation& cont) {
+  CellBuilder cb;
+  if (cont.serialize(cb)) {
+    auto boc = vm::std_boc_serialize(cb.finalize());
+    if (boc.is_ok()) {
+      os << td::buffer_to_hex(boc.move_as_ok().as_slice());
+    }
+  }
+}
+
 bool QuitCont::serialize(CellBuilder& cb) const {
   // vmc_quit$1000 exit_code:int32 = VmCont;
   return cb.store_long_bool(8, 4) && cb.store_long_bool(exit_code, 32);
@@ -269,6 +281,10 @@ Ref<QuitCont> QuitCont::deserialize(CellSlice& cs, int mode) {
   }
 }
 
+std::string QuitCont::type() const {
+  return "vmc_quit";
+}
+
 int ExcQuitCont::jump(VmState* st) const & {
   int n = 0;
   try {
@@ -280,6 +296,10 @@ int ExcQuitCont::jump(VmState* st) const & {
   return ~n;
 }
 
+std::string ExcQuitCont::type() const {
+  return "vmc_quit_exc";
+}
+
 bool ExcQuitCont::serialize(CellBuilder& cb) const {
   // vmc_quit_exc$1001 = VmCont;
   return cb.store_long_bool(9, 4);
@@ -302,6 +322,10 @@ int PushIntCont::jump_w(VmState* st) & {
   return st->jump(std::move(next));
 }
 
+std::string PushIntCont::type() const {
+  return "vmc_pushint";
+}
+
 bool PushIntCont::serialize(CellBuilder& cb) const {
   // vmc_pushint$1111 value:int32 next:^VmCont = VmCont;
   return cb.store_long_bool(15, 4) && cb.store_long_bool(push_val, 32) && next->serialize_ref(cb);
@@ -353,6 +377,10 @@ Ref<ArgContExt> ArgContExt::deserialize(CellSlice& cs, int mode) {
              : Ref<ArgContExt>{};
 }
 
+std::string ArgContExt::type() const {
+  return "vmc_envelope";
+}
+
 int RepeatCont::jump(VmState* st) const & {
   VM_LOG(st) << "repeat " << count << " more times (slow)\n";
   if (count <= 0) {
@@ -401,6 +429,10 @@ Ref<RepeatCont> RepeatCont::deserialize(CellSlice& cs, int mode) {
   }
 }
 
+std::string RepeatCont::type() const {
+  return "vmc_repeat";
+}
+
 int VmState::repeat(Ref<Continuation> body, Ref<Continuation> after, long long count) {
   if (count <= 0) {
     body.clear();
@@ -444,6 +476,10 @@ Ref<AgainCont> AgainCont::deserialize(CellSlice& cs, int mode) {
   }
 }
 
+std::string AgainCont::type() const {
+  return "vmc_again";
+}
+
 int VmState::again(Ref<Continuation> body) {
   return jump(Ref<AgainCont>{true, std::move(body)});
 }
@@ -493,6 +529,10 @@ Ref<UntilCont> UntilCont::deserialize(CellSlice& cs, int mode) {
   }
 }
 
+std::string UntilCont::type() const {
+  return "vmc_until";
+}
+
 int VmState::until(Ref<Continuation> body, Ref<Continuation> after) {
   if (!body->has_c0()) {
     set_c0(Ref<UntilCont>{true, body, std::move(after)});
@@ -575,6 +615,10 @@ Ref<WhileCont> WhileCont::deserialize(CellSlice& cs, int mode) {
   }
 }
 
+std::string WhileCont::type() const {
+  return chkcond ? "vmc_while_cond" : "vmc_while_body";
+}
+
 int VmState::loop_while(Ref<Continuation> cond, Ref<Continuation> body, Ref<Continuation> after) {
   if (!cond->has_c0()) {
     set_c0(Ref<WhileCont>{true, cond, std::move(body), std::move(after), true});
@@ -610,4 +654,8 @@ Ref<OrdCont> OrdCont::deserialize(CellSlice& cs, int mode) {
              : Ref<OrdCont>{};
 }
 
+std::string OrdCont::type() const {
+  return "vmc_std";
+}
+
 }  // namespace vm

crypto/vm/continuation.h

@@ -191,8 +191,11 @@ class Continuation : public td::CntObject {
     return (cont = deserialize(cs, mode)).not_null();
   }
   static bool deserialize_to(Ref<Cell> cell, Ref<Continuation>& cont, int mode = 0);
+  virtual std::string type() const = 0;
 };
 
+std::ostream& operator<<(std::ostream& os, const Continuation& cont);
+
 class QuitCont : public Continuation {
   int exit_code;
 
@@ -205,6 +208,7 @@ class QuitCont : public Continuation {
   }
   bool serialize(CellBuilder& cb) const override;
   static Ref<QuitCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class ExcQuitCont : public Continuation {
@@ -214,6 +218,7 @@ class ExcQuitCont : public Continuation {
   int jump(VmState* st) const & override;
   bool serialize(CellBuilder& cb) const override;
   static Ref<ExcQuitCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class PushIntCont : public Continuation {
@@ -228,6 +233,7 @@ class PushIntCont : public Continuation {
   int jump_w(VmState* st) & override;
   bool serialize(CellBuilder& cb) const override;
   static Ref<PushIntCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class RepeatCont : public Continuation {
@@ -243,6 +249,7 @@ class RepeatCont : public Continuation {
   int jump_w(VmState* st) & override;
   bool serialize(CellBuilder& cb) const override;
   static Ref<RepeatCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class AgainCont : public Continuation {
@@ -256,6 +263,7 @@ class AgainCont : public Continuation {
   int jump_w(VmState* st) & override;
   bool serialize(CellBuilder& cb) const override;
   static Ref<AgainCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class UntilCont : public Continuation {
@@ -269,6 +277,7 @@ class UntilCont : public Continuation {
   int jump_w(VmState* st) & override;
   bool serialize(CellBuilder& cb) const override;
   static Ref<UntilCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class WhileCont : public Continuation {
@@ -284,6 +293,7 @@ class WhileCont : public Continuation {
   int jump_w(VmState* st) & override;
   bool serialize(CellBuilder& cb) const override;
   static Ref<WhileCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class ArgContExt : public Continuation {
@@ -315,6 +325,7 @@ class ArgContExt : public Continuation {
   }
   bool serialize(CellBuilder& cb) const override;
   static Ref<ArgContExt> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 class OrdCont : public Continuation {
@@ -369,6 +380,7 @@ class OrdCont : public Continuation {
   }
   bool serialize(CellBuilder& cb) const override;
   static Ref<OrdCont> deserialize(CellSlice& cs, int mode = 0);
+  std::string type() const override;
 };
 
 ControlData* force_cdata(Ref<Continuation>& cont);

crypto/vm/log.h

@@ -31,7 +31,7 @@ namespace vm {
 struct VmLog {
   td::LogInterface *log_interface{td::log_interface};
   td::LogOptions log_options{td::log_options};
-  enum { DumpStack = 2, ExecLocation = 4, GasRemaining = 8 };
+  enum { DumpStack = 2, ExecLocation = 4, GasRemaining = 8, DumpStackVerbose = 16 };
   int log_mask{1};
   static VmLog Null() {
     VmLog res;

crypto/vm/stack.cpp

@@ -21,6 +21,8 @@
 #include "vm/box.hpp"
 #include "vm/atom.h"
 #include "vm/vmstate.h"
+#include "vm/boc.h"
+#include "td/utils/misc.h"
 
 namespace td {
 template class td::Cnt<std::string>;
@@ -81,7 +83,7 @@ std::string StackEntry::to_lisp_string() const {
   return std::move(os).str();
 }
 
-void StackEntry::dump(std::ostream& os) const {
+void StackEntry::dump(std::ostream& os, bool verbose) const {
   switch (tp) {
     case t_null:
       os << "(null)";
@@ -91,14 +93,23 @@ void StackEntry::dump(std::ostream& os) const {
       break;
     case t_cell:
       if (ref.not_null()) {
-        os << "C{" << static_cast<Ref<Cell>>(ref)->get_hash().to_hex() << "}";
+        if (verbose) {
+          std::string serialized = "???";
+          auto boc = vm::std_boc_serialize(as_cell());
+          if (boc.is_ok()) {
+            serialized = td::buffer_to_hex(boc.move_as_ok().as_slice());
+          }
+          os << "C{" << serialized << "}";
+        } else {
+          os << "C{" << *as_cell() << "}";
+        }
       } else {
         os << "C{null}";
       }
       break;
     case t_builder:
       if (ref.not_null()) {
-        os << "BC{" << static_cast<Ref<CellBuilder>>(ref)->to_hex() << "}";
+        os << "BC{" << *as_builder() << "}";
       } else {
         os << "BC{null}";
       }
@@ -149,12 +160,24 @@ void StackEntry::dump(std::ostream& os) const {
       os << "Object{" << (const void*)&*ref << "}";
       break;
     }
+    case t_vmcont: {
+      if (ref.not_null()) {
+        if (verbose) {
+          os << "Cont{" << *as_cont() << "}";
+        } else {
+          os << "Cont{" << as_cont()->type() << "}";
+        }
+      } else {
+        os << "Cont{null}";
+      }
+      break;
+    }
     default:
       os << "???";
   }
 }
 
-void StackEntry::print_list(std::ostream& os) const {
+void StackEntry::print_list(std::ostream& os, bool verbose) const {
   switch (tp) {
     case t_null:
       os << "()";
@@ -163,7 +186,7 @@ void StackEntry::print_list(std::ostream& os) const {
       const auto& tuple = *static_cast<Ref<Tuple>>(ref);
       if (is_list()) {
         os << '(';
-        tuple[0].print_list(os);
+        tuple[0].print_list(os, verbose);
         print_list_tail(os, &tuple[1]);
         break;
       }
@@ -172,7 +195,7 @@ void StackEntry::print_list(std::ostream& os) const {
         os << "[]";
       } else if (n == 1) {
         os << "[";
-        tuple[0].print_list(os);
+        tuple[0].print_list(os, verbose);
         os << "]";
       } else {
         os << "[";
@@ -181,14 +204,14 @@ void StackEntry::print_list(std::ostream& os) const {
           if (c++) {
             os << " ";
           }
-          entry.print_list(os);
+          entry.print_list(os, verbose);
         }
         os << ']';
       }
       break;
     }
     default:
-      dump(os);
+      dump(os, verbose);
   }
 }
 
@@ -687,12 +710,12 @@ void Stack::dump(std::ostream& os, int mode) const {
   os << " [ ";
   if (mode & 2) {
     for (const auto& x : stack) {
-      x.print_list(os);
+      x.print_list(os, mode & 4);
       os << ' ';
     }
   } else {
     for (const auto& x : stack) {
-      x.dump(os);
+      x.dump(os, mode & 4);
       os << ' ';
     }
   }

crypto/vm/stack.hpp

@@ -292,8 +292,8 @@ class StackEntry {
   }
   bool for_each_scalar(const std::function<bool(const StackEntry&)>& func) const;
   void for_each_scalar(const std::function<void(const StackEntry&)>& func) const;
-  void dump(std::ostream& os) const;
+  void dump(std::ostream& os, bool verbose = false) const;
-  void print_list(std::ostream& os) const;
+  void print_list(std::ostream& os, bool verbose = false) const;
   std::string to_string() const;
   std::string to_lisp_string() const;
 
@@ -558,7 +558,7 @@ class Stack : public td::CntObject {
   }
   bool for_each_scalar(const std::function<bool(const StackEntry&)>& func) const;
   void for_each_scalar(const std::function<void(const StackEntry&)>& func) const;
-  // mode: +1 = add eoln, +2 = Lisp-style lists
+  // mode: +1 = add eoln, +2 = Lisp-style lists, +4 = serialized bocs
   void dump(std::ostream& os, int mode = 1) const;
   bool serialize(vm::CellBuilder& cb, int mode = 0) const;
   bool deserialize(vm::CellSlice& cs, int mode = 0);

crypto/vm/vm.cpp

@@ -435,7 +435,11 @@ int VmState::step() {
   CHECK(code.not_null() && stack.not_null());
   if (log.log_mask & vm::VmLog::DumpStack) {
     std::stringstream ss;
-    stack->dump(ss, 3);
+    int mode = 3;
+    if (log.log_mask & vm::VmLog::DumpStackVerbose) {
+      mode += 4;
+    }
+    stack->dump(ss, mode);
     VM_LOG(this) << "stack:" << ss.str();
   }
   if (stack_trace) {