Merge pull request #8788 from dfuse-io/feature/deep-mind

dfuse Deep Mind changes

CMakeLists.txt

@@ -120,6 +120,8 @@ else()
     endif()
 endif()
 
+option(EOSIO_ENABLE_DEVELOPER_OPTIONS "enable developer options for EOSIO" OFF)
+
 # based on http://www.delorie.com/gnu/docs/gdb/gdb_70.html
 # uncomment this line to tell GDB about macros (slows compile times)
 # set( CMAKE_CXX_FLAGS_DEBUG "${CMAKE_CXX_FLAGS_DEBUG} -gdwarf-2 -g3" )

libraries/chain/CMakeLists.txt

@@ -92,6 +92,7 @@ add_library( eosio_chain
 #
 #             contracts/chain_initializer.cpp
 
+             authority.cpp
              trace.cpp
              transaction_metadata.cpp
              protocol_state_object.cpp
@@ -102,6 +103,7 @@ add_library( eosio_chain
              whitelisted_intrinsics.cpp
              thread_utils.cpp
              platform_timer_accuracy.cpp
+
              ${PLATFORM_TIMER_IMPL}
              ${HEADERS}
              )

libraries/chain/authority.cpp

@@ -0,0 +1,7 @@
+#include <eosio/chain/authority.hpp>
+
+namespace fc {
+   void to_variant(const eosio::chain::shared_public_key& var, fc::variant& vo) {
+      vo = var.to_string();
+   }
+} // namespace fc

libraries/chain/authorization_manager.cpp

@@ -133,6 +133,7 @@ namespace eosio { namespace chain {
                                                                       permission_name name,
                                                                       permission_id_type parent,
                                                                       const authority& auth,
+                                                                      uint32_t action_id,
                                                                       time_point initial_creation_time
                                                                     )
    {
@@ -156,6 +157,13 @@ namespace eosio { namespace chain {
          p.name         = name;
          p.last_updated = creation_time;
          p.auth         = auth;
+
+         if (auto dm_logger = _control.get_deep_mind_logger()) {
+            fc_dlog(*dm_logger, "PERM_OP INS ${action_id} ${data}",
+               ("action_id", action_id)
+               ("data", p)
+            );
+         }
       });
       return perm;
    }
@@ -164,6 +172,7 @@ namespace eosio { namespace chain {
                                                                       permission_name name,
                                                                       permission_id_type parent,
                                                                       authority&& auth,
+                                                                      uint32_t action_id,
                                                                       time_point initial_creation_time
                                                                     )
    {
@@ -187,28 +196,60 @@ namespace eosio { namespace chain {
          p.name         = name;
          p.last_updated = creation_time;
          p.auth         = std::move(auth);
+
+         if (auto dm_logger = _control.get_deep_mind_logger()) {
+            fc_dlog(*dm_logger, "PERM_OP INS ${action_id} ${data}",
+               ("action_id", action_id)
+               ("data", p)
+            );
+         }
       });
       return perm;
    }
 
-   void authorization_manager::modify_permission( const permission_object& permission, const authority& auth ) {
+   void authorization_manager::modify_permission( const permission_object& permission, const authority& auth, uint32_t action_id ) {
       for(const key_weight& k: auth.keys)
          EOS_ASSERT(k.key.which() < _db.get<protocol_state_object>().num_supported_key_types, unactivated_key_type,
            "Unactivated key type used when modifying permission");
 
       _db.modify( permission, [&](permission_object& po) {
+         auto dm_logger = _control.get_deep_mind_logger();
+
+         fc::variant old_permission;
+         if (dm_logger) {
+            old_permission = po;
+         }
+
          po.auth = auth;
          po.last_updated = _control.pending_block_time();
+
+         if (auto dm_logger = _control.get_deep_mind_logger()) {
+            fc_dlog(*dm_logger, "PERM_OP UPD ${action_id} ${data}",
+               ("action_id", action_id)
+               ("data", fc::mutable_variant_object()
+                  ("old", old_permission)
+                  ("new", po)
+               )
+            );
+         }
       });
    }
 
-   void authorization_manager::remove_permission( const permission_object& permission ) {
+   void authorization_manager::remove_permission( const permission_object& permission, uint32_t action_id) {
       const auto& index = _db.template get_index<permission_index, by_parent>();
       auto range = index.equal_range(permission.id);
       EOS_ASSERT( range.first == range.second, action_validate_exception,
                   "Cannot remove a permission which has children. Remove the children first.");
 
       _db.get_mutable_index<permission_usage_index>().remove_object( permission.usage_id._id );
+
+      if (auto dm_logger = _control.get_deep_mind_logger()) {
+         fc_dlog(*dm_logger, "PERM_OP REM ${action_id} ${data}",
+              ("action_id", action_id)
+              ("data", permission)
+         );
+      }
+
       _db.remove( permission );
    }
 
@@ -340,7 +381,7 @@ namespace eosio { namespace chain {
                   "the owner of the linked permission needs to be the actor of the declared authorization" );
 
       if( link.code == config::system_account_name
-            || !_control.is_builtin_activated( builtin_protocol_feature_t::fix_linkauth_restriction ) ) 
+            || !_control.is_builtin_activated( builtin_protocol_feature_t::fix_linkauth_restriction ) )
       {
          EOS_ASSERT( link.type != updateauth::get_name(),  action_validate_exception,
                      "Cannot link eosio::updateauth to a minimum permission" );

libraries/chain/controller.cpp

@@ -247,6 +247,7 @@ struct controller_impl {
    uint32_t                       snapshot_head_block = 0;
    named_thread_pool              thread_pool;
    platform_timer                 timer;
+   fc::logger*                    deep_mind_logger = nullptr;
 #if defined(EOSIO_EOS_VM_RUNTIME_ENABLED) || defined(EOSIO_EOS_VM_JIT_RUNTIME_ENABLED)
    vm::wasm_allocator                 wasm_alloc;
 #endif
@@ -310,9 +311,9 @@ struct controller_impl {
     blog( cfg.blocks_dir ),
     fork_db( cfg.state_dir ),
     wasmif( cfg.wasm_runtime, cfg.eosvmoc_tierup, db, cfg.state_dir, cfg.eosvmoc_config ),
-    resource_limits( db ),
+    resource_limits( db, [&s]() { return s.get_deep_mind_logger(); }),
     authorization( s, db ),
-    protocol_features( std::move(pfs) ),
+    protocol_features( std::move(pfs), [&s]() { return s.get_deep_mind_logger(); } ),
     conf( cfg ),
     chain_id( chain_id ),
     read_mode( cfg.read_mode ),
@@ -1020,9 +1021,9 @@ struct controller_impl {
       });
 
       const auto& owner_permission  = authorization.create_permission(name, config::owner_name, 0,
-                                                                      owner, initial_timestamp );
+                                                                      owner, 0, initial_timestamp );
       const auto& active_permission = authorization.create_permission(name, config::active_name, owner_permission.id,
-                                                                      active, initial_timestamp );
+                                                                      active, 0, initial_timestamp );
 
       resource_limits.initialize_account(name);
 
@@ -1031,7 +1032,12 @@ struct controller_impl {
       ram_delta += owner_permission.auth.get_billable_size();
       ram_delta += active_permission.auth.get_billable_size();
 
-      resource_limits.add_pending_ram_usage(name, ram_delta);
+      std::string event_id;
+      if (get_deep_mind_logger() != nullptr) {
+         event_id = RAM_EVENT_ID("${name}", ("name", name));
+      }
+
+      resource_limits.add_pending_ram_usage(name, ram_delta, ram_trace(0, event_id.c_str(), "account", "add", "newaccount"));
       resource_limits.verify_account_ram_usage(name);
    }
 
@@ -1082,11 +1088,13 @@ struct controller_impl {
                                                                              config::majority_producers_permission_name,
                                                                              active_permission.id,
                                                                              active_producers_authority,
+                                                                             0,
                                                                              genesis.initial_timestamp );
       const auto& minority_permission     = authorization.create_permission( config::producers_account_name,
                                                                              config::minority_producers_permission_name,
                                                                              majority_permission.id,
                                                                              active_producers_authority,
+                                                                             0,
                                                                              genesis.initial_timestamp );
    }
 
@@ -1138,6 +1146,13 @@ struct controller_impl {
          etrx.set_reference_block( self.head_block_id() );
       }
 
+      if (auto dm_logger = get_deep_mind_logger()) {
+         fc_dlog(*dm_logger, "TRX_OP CREATE onerror ${id} ${trx}",
+            ("id", etrx.id())
+            ("trx", self.maybe_to_variant_with_abi(etrx, abi_serializer::create_yield_function(self.get_abi_serializer_max_time())))
+         );
+      }
+
       transaction_checktime_timer trx_timer(timer);
       transaction_context trx_context( self, etrx, etrx.id(), std::move(trx_timer), start );
       trx_context.deadline = deadline;
@@ -1174,8 +1189,13 @@ struct controller_impl {
    }
 
    int64_t remove_scheduled_transaction( const generated_transaction_object& gto ) {
+      std::string event_id;
+      if (get_deep_mind_logger() != nullptr) {
+         event_id = RAM_EVENT_ID("${id}", ("id", gto.id));
+      }
+
       int64_t ram_delta = -(config::billable_size_v<generated_transaction_object> + gto.packed_trx.size());
-      resource_limits.add_pending_ram_usage( gto.payer, ram_delta );
+      resource_limits.add_pending_ram_usage( gto.payer, ram_delta, ram_trace(0, event_id.c_str(), "deferred_trx", "remove", "deferred_trx_removed") );
       // No need to verify_account_ram_usage since we are only reducing memory
 
       db.remove( gto );
@@ -1321,6 +1341,12 @@ struct controller_impl {
          trace->except = e;
          trace->except_ptr = std::current_exception();
          trace->elapsed = fc::time_point::now() - trx_context.start;
+
+         if (auto dm_logger = get_deep_mind_logger()) {
+            fc_dlog(*dm_logger, "DTRX_OP FAILED ${action_id}",
+               ("action_id", trx_context.get_action_id())
+            );
+         }
       }
       trx_context.undo();
 
@@ -1543,6 +1569,11 @@ struct controller_impl {
    {
       EOS_ASSERT( !pending, block_validate_exception, "pending block already exists" );
 
+      if (auto dm_logger = get_deep_mind_logger()) {
+         // The head block represents the block just before this one that is about to start, so add 1 to get this block num
+         fc_dlog(*dm_logger, "START_BLOCK ${block_num}", ("block_num", head->block_num + 1));
+      }
+
       auto guard_pending = fc::make_scoped_exit([this, head_block_num=head->block_num](){
          protocol_features.popped_blocks_to( head_block_num );
          pending.reset();
@@ -2109,6 +2140,14 @@ struct controller_impl {
          auto old_head = head;
          ilog("switching forks from ${current_head_id} (block number ${current_head_num}) to ${new_head_id} (block number ${new_head_num})",
               ("current_head_id", head->id)("current_head_num", head->block_num)("new_head_id", new_head->id)("new_head_num", new_head->block_num) );
+
+         if (auto dm_logger = get_deep_mind_logger()) {
+            fc_dlog(*dm_logger, "SWITCH_FORK ${from_id} ${to_id}",
+               ("from_id", head->id)
+               ("to_id", new_head->id)
+            );
+         }
+
          auto branches = fork_db.fetch_branch_from( new_head->id, head->id );
 
          if( branches.second.size() > 0 ) {
@@ -2405,9 +2444,21 @@ struct controller_impl {
          trx.expiration = self.pending_block_time() + fc::microseconds(999'999); // Round up to nearest second to avoid appearing expired
          trx.set_reference_block( self.head_block_id() );
       }
+
+      if (auto dm_logger = get_deep_mind_logger()) {
+         fc_dlog(*dm_logger, "TRX_OP CREATE onblock ${id} ${trx}",
+            ("id", trx.id())
+            ("trx", self.maybe_to_variant_with_abi(trx, abi_serializer::create_yield_function(self.get_abi_serializer_max_time())))
+         );
+      }
+
       return trx;
    }
 
+   inline fc::logger* get_deep_mind_logger() const {
+      return deep_mind_logger;
+   }
+
 }; /// controller_impl
 
 const resource_limits_manager&   controller::get_resource_limits_manager()const
@@ -2477,7 +2528,7 @@ const fork_database& controller::fork_db()const { return my->fork_db; }
 
 const chainbase::database& controller::reversible_db()const { return my->reversible_blocks; }
 
-void controller::preactivate_feature( const digest_type& feature_digest ) {
+void controller::preactivate_feature( uint32_t action_id, const digest_type& feature_digest ) {
    const auto& pfs = my->protocol_features.get_protocol_feature_set();
    auto cur_time = pending_block_time();
 
@@ -2574,6 +2625,16 @@ void controller::preactivate_feature( const digest_type& feature_digest ) {
                ("digest", feature_digest)
    );
 
+   if (auto dm_logger = get_deep_mind_logger()) {
+      const auto feature = pfs.get_protocol_feature(feature_digest);
+
+      fc_dlog(*dm_logger, "FEATURE_OP PRE_ACTIVATE ${action_id} ${feature_digest} ${feature}",
+         ("action_id", action_id)
+         ("feature_digest", feature_digest)
+         ("feature", feature.to_variant())
+      );
+   }
+
    my->db.modify( pso, [&]( auto& ps ) {
       ps.preactivated_protocol_features.push_back( feature_digest );
    } );
@@ -3244,23 +3305,50 @@ const flat_set<account_name> &controller::get_resource_greylist() const {
 }
 
 
-void controller::add_to_ram_correction( account_name account, uint64_t ram_bytes ) {
+void controller::add_to_ram_correction( account_name account, uint64_t ram_bytes, uint32_t action_id, const char* event_id ) {
+   int64_t correction_object_id = 0;
+
    if( auto ptr = my->db.find<account_ram_correction_object, by_name>( account ) ) {
       my->db.modify<account_ram_correction_object>( *ptr, [&]( auto& rco ) {
+         correction_object_id = rco.id._id;
          rco.ram_correction += ram_bytes;
       } );
    } else {
       my->db.create<account_ram_correction_object>( [&]( auto& rco ) {
+         correction_object_id = rco.id._id;
          rco.name = account;
          rco.ram_correction = ram_bytes;
       } );
    }
+
+   if (auto dm_logger = get_deep_mind_logger()) {
+      fc_dlog(*dm_logger, "RAM_CORRECTION_OP ${action_id} ${correction_id} ${event_id} ${payer} ${delta}",
+         ("action_id", action_id)
+         ("correction_id", correction_object_id)
+         ("event_id", event_id)
+         ("payer", account)
+         ("delta", ram_bytes)
+      );
+   }
+}
+
+fc::microseconds controller::get_abi_serializer_max_time()const {
+   return my->conf.abi_serializer_max_time_us;
 }
 
 bool controller::all_subjective_mitigations_disabled()const {
    return my->conf.disable_all_subjective_mitigations;
 }
 
+fc::logger* controller::get_deep_mind_logger()const {
+   return my->get_deep_mind_logger();
+}
+
+void controller::enable_deep_mind(fc::logger* logger) {
+   EOS_ASSERT( logger != nullptr, misc_exception, "Invalid logger passed into enable_deep_mind, must be set" );
+   my->deep_mind_logger = logger;
+}
+
 #if defined(EOSIO_EOS_VM_RUNTIME_ENABLED) || defined(EOSIO_EOS_VM_JIT_RUNTIME_ENABLED)
 vm::wasm_allocator& controller::get_wasm_allocator() {
    return my->wasm_alloc;
@@ -3348,7 +3436,12 @@ void controller_impl::on_activation<builtin_protocol_feature_t::replace_deferred
                ("name", itr->name)("adjust", itr->ram_correction)("current", current_ram_usage) );
       }
 
-      resource_limits.add_pending_ram_usage( itr->name, ram_delta );
+      std::string event_id;
+      if (get_deep_mind_logger() != nullptr) {
+         event_id = RAM_EVENT_ID("${id}", ("id", itr->id._id));
+      }
+
+      resource_limits.add_pending_ram_usage( itr->name, ram_delta, ram_trace(0, event_id.c_str(), "deferred_trx", "correction", "deferred_trx_ram_correction") );
       db.remove( *itr );
    }
 }