fix: log block event counts after processing (#1820)

* fix: log re-orgs at `INFO` level (#1819)

* chore(release): 7.7.1 [skip ci]

## [7.7.1](v7.7.0...v7.7.1) (2024-01-11)

### Bug Fixes

* log re-orgs at `INFO` level ([#1819](#1819)) ([3b502f7](3b502f7))

* fix: log block event counts after processing

* fix: switch breaks

---------

Co-authored-by: semantic-release-bot <[email protected]>

Author: rafaelcr

CHANGELOG.md

@@ -1,3 +1,10 @@
+## [7.7.1](https://github.com/hirosystems/stacks-blockchain-api/compare/v7.7.0...v7.7.1) (2024-01-11)
+
+
+### Bug Fixes
+
+* log re-orgs at `INFO` level ([#1819](https://github.com/hirosystems/stacks-blockchain-api/issues/1819)) ([3b502f7](https://github.com/hirosystems/stacks-blockchain-api/commit/3b502f73149c185265fc8948e75ba064892ce6d2))
+
 ## [7.7.0](https://github.com/hirosystems/stacks-blockchain-api/compare/v7.6.0...v7.7.0) (2024-01-10)
 
 

src/datastore/common.ts

@@ -981,43 +981,30 @@ export interface FaucetRequestQueryResult {
   occurred_at: string;
 }
 
+interface ReOrgEntities {
+  blocks: number;
+  microblocks: number;
+  minerRewards: number;
+  txs: number;
+  stxLockEvents: number;
+  stxEvents: number;
+  ftEvents: number;
+  nftEvents: number;
+  pox2Events: number;
+  pox3Events: number;
+  pox4Events: number;
+  contractLogs: number;
+  smartContracts: number;
+  names: number;
+  namespaces: number;
+  subdomains: number;
+}
+
 export interface ReOrgUpdatedEntities {
-  markedCanonical: {
-    blocks: number;
-    microblocks: number;
-    minerRewards: number;
-    txs: number;
-    stxLockEvents: number;
-    stxEvents: number;
-    ftEvents: number;
-    nftEvents: number;
-    pox2Events: number;
-    pox3Events: number;
-    pox4Events: number;
-    contractLogs: number;
-    smartContracts: number;
-    names: number;
-    namespaces: number;
-    subdomains: number;
-  };
-  markedNonCanonical: {
-    blocks: number;
-    microblocks: number;
-    minerRewards: number;
-    txs: number;
-    stxLockEvents: number;
-    stxEvents: number;
-    ftEvents: number;
-    nftEvents: number;
-    pox2Events: number;
-    pox3Events: number;
-    pox4Events: number;
-    contractLogs: number;
-    smartContracts: number;
-    names: number;
-    namespaces: number;
-    subdomains: number;
-  };
+  markedCanonical: ReOrgEntities;
+  markedNonCanonical: ReOrgEntities;
+  prunedMempoolTxs: number;
+  restoredMempoolTxs: number;
 }
 
 export interface TransferQueryResult {

src/datastore/helpers.ts

@@ -1331,67 +1331,7 @@ export function newReOrgUpdatedEntities(): ReOrgUpdatedEntities {
       namespaces: 0,
       subdomains: 0,
     },
+    prunedMempoolTxs: 0,
+    restoredMempoolTxs: 0,
   };
 }
-
-export function logReorgResultInfo(updatedEntities: ReOrgUpdatedEntities) {
-  const updates = [
-    ['blocks', updatedEntities.markedCanonical.blocks, updatedEntities.markedNonCanonical.blocks],
-    [
-      'microblocks',
-      updatedEntities.markedCanonical.microblocks,
-      updatedEntities.markedNonCanonical.microblocks,
-    ],
-    ['txs', updatedEntities.markedCanonical.txs, updatedEntities.markedNonCanonical.txs],
-    [
-      'miner-rewards',
-      updatedEntities.markedCanonical.minerRewards,
-      updatedEntities.markedNonCanonical.minerRewards,
-    ],
-    [
-      'stx-lock events',
-      updatedEntities.markedCanonical.stxLockEvents,
-      updatedEntities.markedNonCanonical.stxLockEvents,
-    ],
-    [
-      'stx-token events',
-      updatedEntities.markedCanonical.stxEvents,
-      updatedEntities.markedNonCanonical.stxEvents,
-    ],
-    [
-      'non-fungible-token events',
-      updatedEntities.markedCanonical.nftEvents,
-      updatedEntities.markedNonCanonical.nftEvents,
-    ],
-    [
-      'fungible-token events',
-      updatedEntities.markedCanonical.ftEvents,
-      updatedEntities.markedNonCanonical.ftEvents,
-    ],
-    [
-      'contract logs',
-      updatedEntities.markedCanonical.contractLogs,
-      updatedEntities.markedNonCanonical.contractLogs,
-    ],
-    [
-      'smart contracts',
-      updatedEntities.markedCanonical.smartContracts,
-      updatedEntities.markedNonCanonical.smartContracts,
-    ],
-    ['names', updatedEntities.markedCanonical.names, updatedEntities.markedNonCanonical.names],
-    [
-      'namespaces',
-      updatedEntities.markedCanonical.namespaces,
-      updatedEntities.markedNonCanonical.namespaces,
-    ],
-    [
-      'subdomains',
-      updatedEntities.markedCanonical.subdomains,
-      updatedEntities.markedNonCanonical.subdomains,
-    ],
-  ];
-  const markedCanonical = updates.map(e => `${e[1]} ${e[0]}`).join(', ');
-  logger.debug(`Entities marked as canonical: ${markedCanonical}`);
-  const markedNonCanonical = updates.map(e => `${e[2]} ${e[0]}`).join(', ');
-  logger.debug(`Entities marked as non-canonical: ${markedNonCanonical}`);
-}

src/datastore/pg-write-store.ts

@@ -75,7 +75,6 @@ import {
   TX_METADATA_TABLES,
   validateZonefileHash,
   newReOrgUpdatedEntities,
-  logReorgResultInfo,
 } from './helpers';
 import { PgNotifier } from './pg-notifier';
 import { MIGRATIONS_DIR, PgStore } from './pg-store';
@@ -2762,12 +2761,16 @@ export class PgWriteStore extends PgStore {
         false,
         updatedEntities
       );
-      await this.restoreMempoolTxs(sql, markNonCanonicalResult.txsMarkedNonCanonical);
+      const restoredMempoolTxs = await this.restoreMempoolTxs(
+        sql,
+        markNonCanonicalResult.txsMarkedNonCanonical
+      );
+      updatedEntities.restoredMempoolTxs += restoredMempoolTxs.restoredTxs.length;
     }
 
-    // The canonical microblock tables _must_ be restored _after_ orphaning all other blocks at a given height,
-    // because there is only 1 row per microblock hash, and both the orphaned blocks at this height and the
-    // canonical block can be pointed to the same microblocks.
+    // The canonical microblock tables _must_ be restored _after_ orphaning all other blocks at a
+    // given height, because there is only 1 row per microblock hash, and both the orphaned blocks
+    // at this height and the canonical block can be pointed to the same microblocks.
     const restoredBlock = parseBlockQueryResult(restoredBlockResult[0]);
     const microCanonicalUpdateResult = await this.updateMicroCanonical(sql, {
       isCanonical: true,
@@ -2790,24 +2793,17 @@ export class PgWriteStore extends PgStore {
     updatedEntities.markedCanonical.microblocks += microblocksAccepted.size;
     updatedEntities.markedNonCanonical.microblocks += microblocksOrphaned.size;
 
-    microblocksOrphaned.forEach(mb => logger.debug(`Marked microblock as non-canonical: ${mb}`));
-    microblocksAccepted.forEach(mb => logger.debug(`Marked microblock as canonical: ${mb}`));
-
     const markCanonicalResult = await this.markEntitiesCanonical(
       sql,
       indexBlockHash,
       true,
       updatedEntities
     );
-    const removedTxsResult = await this.pruneMempoolTxs(
+    const prunedMempoolTxs = await this.pruneMempoolTxs(
       sql,
       markCanonicalResult.txsMarkedCanonical
     );
-    if (removedTxsResult.removedTxs.length > 0) {
-      logger.debug(
-        `Removed ${removedTxsResult.removedTxs.length} txs from mempool table during reorg handling`
-      );
-    }
+    updatedEntities.prunedMempoolTxs += prunedMempoolTxs.removedTxs.length;
     const parentResult = await sql<{ index_block_hash: string }[]>`
       SELECT index_block_hash
       FROM blocks
@@ -2857,11 +2853,13 @@ export class PgWriteStore extends PgStore {
             block.parent_index_block_hash
           }`
         );
-      // This blocks builds off a previously orphaned chain. Restore canonical status for this
-      // chain.
+      // This block builds off a previously orphaned chain. Restore canonical status for this chain.
       if (!parentResult[0].canonical && block.block_height > chainTipHeight) {
         await this.restoreOrphanedChain(sql, parentResult[0].index_block_hash, updatedEntities);
-        logReorgResultInfo(updatedEntities);
+        logger.info(
+          updatedEntities,
+          `Re-org resolved. Block ${block.block_height} builds off a previously orphaned chain.`
+        );
       }
       // Reflect updated transaction totals in `chain_tip` table.
       const txCountDelta =

src/event-stream/event-server.ts

@@ -46,6 +46,7 @@ import {
   CoreNodeMsgBlockData,
   parseMicroblocksFromTxs,
   isPoxPrintEvent,
+  newCoreNoreBlockEventCounts,
 } from './reader';
 import {
   decodeTransaction,
@@ -230,6 +231,7 @@ async function handleBlockMessage(
   db: PgWriteStore
 ): Promise<void> {
   const ingestionTimer = stopwatch();
+  const counts = newCoreNoreBlockEventCounts();
   const parsedTxs: CoreNodeParsedTxMessage[] = [];
   const blockData: CoreNodeMsgBlockData = {
     ...msg,
@@ -238,8 +240,42 @@ async function handleBlockMessage(
     const parsedTx = parseMessageTransaction(chainId, item, blockData, msg.events);
     if (parsedTx) {
       parsedTxs.push(parsedTx);
+      counts.tx_total += 1;
+      switch (parsedTx.parsed_tx.payload.type_id) {
+        case TxPayloadTypeID.Coinbase:
+          counts.txs.coinbase += 1;
+          break;
+        case TxPayloadTypeID.CoinbaseToAltRecipient:
+          counts.txs.coinbase_to_alt_recipient += 1;
+          break;
+        case TxPayloadTypeID.ContractCall:
+          counts.txs.contract_call += 1;
+          break;
+        case TxPayloadTypeID.NakamotoCoinbase:
+          counts.txs.nakamoto_coinbase += 1;
+          break;
+        case TxPayloadTypeID.PoisonMicroblock:
+          counts.txs.poison_microblock += 1;
+          break;
+        case TxPayloadTypeID.SmartContract:
+          counts.txs.smart_contract += 1;
+          break;
+        case TxPayloadTypeID.TenureChange:
+          counts.txs.tenure_change += 1;
+          break;
+        case TxPayloadTypeID.TokenTransfer:
+          counts.txs.token_transfer += 1;
+          break;
+        case TxPayloadTypeID.VersionedSmartContract:
+          counts.txs.versioned_smart_contract += 1;
+          break;
+      }
     }
   });
+  for (const event of msg.events) {
+    counts.event_total += 1;
+    counts.events[event.type] += 1;
+  }
 
   const dbBlock: DbBlock = {
     canonical: true,
@@ -281,6 +317,7 @@ async function handleBlockMessage(
       tx_fees_streamed_produced: BigInt(minerReward.tx_fees_streamed_produced),
     };
     dbMinerRewards.push(dbMinerReward);
+    counts.miner_rewards += 1;
   }
 
   logger.debug(`Received ${dbMinerRewards.length} matured miner rewards`);
@@ -304,18 +341,10 @@ async function handleBlockMessage(
       index_block_hash: msg.index_block_hash,
       block_hash: msg.block_hash,
     };
+    counts.microblocks += 1;
     return microblock;
   });
 
-  parsedTxs.forEach(tx => {
-    logger.debug(`Received anchor block mined tx: ${tx.core_tx.txid}`);
-    logger.info('Transaction confirmed', {
-      txid: tx.core_tx.txid,
-      in_microblock: tx.microblock_hash != '',
-      stacks_height: dbBlock.block_height,
-    });
-  });
-
   const dbData: DataStoreBlockUpdateData = {
     block: dbBlock,
     microblocks: dbMicroblocks,
@@ -328,7 +357,10 @@ async function handleBlockMessage(
 
   await db.update(dbData);
   const ingestionTime = ingestionTimer.getElapsed();
-  logger.info(`Ingested block ${msg.block_height} (${msg.block_hash}) in ${ingestionTime}ms`);
+  logger.info(
+    counts,
+    `Ingested block ${msg.block_height} (${msg.block_hash}) in ${ingestionTime}ms`
+  );
 }
 
 function parseDataStoreTxEventData(

src/event-stream/reader.ts

@@ -847,3 +847,67 @@ export function isPoxPrintEvent(event: SmartContractEvent): boolean {
   if (event.contract_event.topic !== 'print') return false;
   return PoxContractIdentifiers.includes(event.contract_event.contract_identifier);
 }
+
+interface CoreNodeBlockEventCounts {
+  microblocks: number;
+  tx_total: number;
+  txs: {
+    token_transfer: number;
+    smart_contract: number;
+    contract_call: number;
+    poison_microblock: number;
+    coinbase: number;
+    coinbase_to_alt_recipient: number;
+    versioned_smart_contract: number;
+    tenure_change: number;
+    nakamoto_coinbase: number;
+  };
+  event_total: number;
+  events: {
+    contract_event: number;
+    stx_transfer_event: number;
+    stx_mint_event: number;
+    stx_burn_event: number;
+    stx_lock_event: number;
+    nft_transfer_event: number;
+    nft_mint_event: number;
+    nft_burn_event: number;
+    ft_transfer_event: number;
+    ft_mint_event: number;
+    ft_burn_event: number;
+  };
+  miner_rewards: number;
+}
+
+export function newCoreNoreBlockEventCounts(): CoreNodeBlockEventCounts {
+  return {
+    microblocks: 0,
+    tx_total: 0,
+    txs: {
+      token_transfer: 0,
+      smart_contract: 0,
+      contract_call: 0,
+      poison_microblock: 0,
+      coinbase: 0,
+      coinbase_to_alt_recipient: 0,
+      versioned_smart_contract: 0,
+      tenure_change: 0,
+      nakamoto_coinbase: 0,
+    },
+    event_total: 0,
+    events: {
+      contract_event: 0,
+      stx_transfer_event: 0,
+      stx_mint_event: 0,
+      stx_burn_event: 0,
+      stx_lock_event: 0,
+      nft_transfer_event: 0,
+      nft_mint_event: 0,
+      nft_burn_event: 0,
+      ft_transfer_event: 0,
+      ft_mint_event: 0,
+      ft_burn_event: 0,
+    },
+    miner_rewards: 0,
+  };
+}

src/tests/datastore-tests.ts

@@ -3607,6 +3607,8 @@ describe('postgres datastore', () => {
         namespaces: 0,
         subdomains: 0,
       },
+      prunedMempoolTxs: 0,
+      restoredMempoolTxs: 0,
     });
 
     const blockQuery1 = await db.getBlock({ hash: block1.block_hash });