feat: use a proper logger

hirosystems · Mar 8, 2024 · a174f17 · a174f17
1 parent cc71057
commit a174f17
Show file tree

Hide file tree

Showing 6 changed files with 165 additions and 53 deletions.
diff --git a/docker-compose.yml b/docker-compose.yml
@@ -165,6 +165,7 @@ services:
       STACKING_KEYS: 08c14a1eada0dd42b667b40f59f7c8dedb12113613448dc04980aea20b268ddb01,ce109fee08860bb16337c76647dcbc02df0c06b455dd69bcf30af74d4eedd19301,e75dcb66f84287eaf347955e94fa04337298dbd95aa0dbb985771104ef1913db01
       STACKS_25_HEIGHT: *STACKS_25_HEIGHT
       STACKS_30_HEIGHT: *STACKS_30_HEIGHT
+      SERVICE_NAME: stacker
     depends_on:
       - stacks-node
 
@@ -182,6 +183,7 @@ services:
       STACKS_25_HEIGHT: *STACKS_25_HEIGHT
       STACKS_30_HEIGHT: *STACKS_30_HEIGHT
       EXIT_FROM_MONITOR: *EXIT_FROM_MONITOR
+      SERVICE_NAME: monitor
     depends_on:
       - stacks-node
     entrypoint:

diff --git a/stacking/common.ts b/stacking/common.ts
@@ -9,6 +9,27 @@ import { getPublicKeyFromPrivate, publicKeyToBtcAddress } from '@stacks/encrypti
 import { StacksNodeApi } from '@stacks/api';
 import crypto from 'crypto';
 import { InfoApi, Configuration, BlocksApi, TransactionsApi } from '@stacks/blockchain-api-client';
+import pino, { Logger } from 'pino';
+import pinoPretty from 'pino-pretty';
+
+const serviceName = process.env.SERVICE_NAME || 'JS';
+export let logger: Logger;
+if (process.env.STACKS_LOG_JSON === '1') {
+  logger = pino({
+    name: serviceName,
+  });
+} else {
+  logger = pino({
+    name: serviceName,
+    transport: {
+      target: 'pino-pretty',
+    },
+    // @ts-ignore
+    options: {
+      colorize: true,
+    },
+  });
+}
 
 export const nodeUrl = `http://${process.env.STACKS_CORE_RPC_HOST}:${process.env.STACKS_CORE_RPC_PORT}`;
 export const network = new StacksTestnet({ url: nodeUrl });
@@ -35,7 +56,12 @@ export const accounts = process.env.STACKING_KEYS!.split(',').map((privKey, inde
     signerPrivKey: signerPrivKey,
     signerPubKey: signerPubKey,
     targetSlots: (index + 1) * 2,
+    index,
     client: new StackingClient(stxAddress, network),
+    logger: logger.child({
+      account: stxAddress,
+      index: index,
+    }),
   };
 });
 
@@ -48,7 +74,7 @@ export async function waitForSetup() {
   try {
     await accounts[0].client.getPoxInfo();
   } catch (error) {
-    if (/(ECONNREFUSED|ENOTFOUND)/.test(error.cause?.message)) {
+    if (/(ECONNREFUSED|ENOTFOUND|SyntaxError)/.test(error.cause?.message)) {
       console.log(`Stacks node not ready, waiting...`);
       await new Promise(resolve => setTimeout(resolve, 3000));
       return waitForSetup();

diff --git a/stacking/monitor-ext.sh b/stacking/monitor-ext.sh
@@ -5,5 +5,7 @@ export STACKS_CORE_RPC_PORT=80
 export STACKS_30_HEIGHT=131 
 export STACKS_25_HEIGHT=121 
 export STACKING_KEYS="08c14a1eada0dd42b667b40f59f7c8dedb12113613448dc04980aea20b268ddb01,ce109fee08860bb16337c76647dcbc02df0c06b455dd69bcf30af74d4eedd19301,e75dcb66f84287eaf347955e94fa04337298dbd95aa0dbb985771104ef1913db01"
+# export STACKS_LOG_JSON=1
+export SERVICE_NAME=monitor
 
 npx tsx monitor.ts
diff --git a/stacking/monitor.ts b/stacking/monitor.ts
@@ -9,6 +9,7 @@ import {
   blocksApi,
   parseEnvInt,
   txApi,
+  logger,
 } from './common';
 import { Transaction, ContractCallTransaction } from '@stacks/stacks-blockchain-api-types';
 
@@ -17,13 +18,14 @@ let lastStxHeight = 0;
 let lastRewardCycle = 0;
 let lastStxBlockTime = new Date().getTime();
 let lastStxBlockDiff = 0;
+let lastBlockWarnTime = 0;
 
-console.log('Monitoring...');
+logger.info('Starting monitor script...');
 
 const EXIT_FROM_MONITOR = process.env.EXIT_FROM_MONITOR === '1';
 const monitorInterval = parseEnvInt('MONITOR_INTERVAL') ?? 2;
 
-console.log('Exit from monitor:', EXIT_FROM_MONITOR);
+logger.debug('Exit from monitor?', EXIT_FROM_MONITOR);
 
 async function getTransactions(): Promise<ContractCallTransaction[]> {
   let res = await txApi.getTransactionsByBlock({
@@ -84,6 +86,17 @@ async function loop() {
     let showPrepareMsg = false;
     let showCycleMsg = false;
     let showStxBlockMsg = false;
+    let burnHeightDate = new Date(blockInfo.burn_block_time * 1000);
+    let burnHeightTimeAgo = (new Date().getTime() - burnHeightDate.getTime()) / 1000;
+    const loopLog = logger.child({
+      height,
+      burnHeight: current_burnchain_block_height,
+      // burnHeightTime:
+      cycle: reward_cycle_id,
+      txCount: blockInfo.tx_count,
+      rewardCycle: reward_cycle_id,
+      lastBurnBlock: `${burnHeightTimeAgo.toFixed(0)}s ago`,
+    });
 
     if (current_burnchain_block_height && current_burnchain_block_height !== lastBurnHeight) {
       if (didCrossPreparePhase(lastBurnHeight, current_burnchain_block_height)) {
@@ -98,53 +111,89 @@ async function loop() {
       lastRewardCycle = reward_cycle_id;
     }
 
+    const now = new Date().getTime();
+    lastStxBlockDiff = now - lastStxBlockTime;
+
     if (height !== lastStxHeight) {
       showStxBlockMsg = true;
       lastStxHeight = height;
-      const now = new Date().getTime();
-      lastStxBlockDiff = now - lastStxBlockTime;
       lastStxBlockTime = now;
+      lastBlockWarnTime = now;
     }
 
-    if (showBurnMsg) {
-      console.log(
-        `Burn block: ${current_burnchain_block_height}\tSTX block: ${height}\t${blockInfo.tx_count} TX`
+    // how many ms to warn about no stx blocks
+    const blockWarnInterval = 60 * 1000;
+    const lastWarnDiff = now - lastBlockWarnTime;
+    // if no stx block in a minute
+    if (lastStxBlockDiff > blockWarnInterval && lastWarnDiff > blockWarnInterval) {
+      // const diff = new Date().getTime() - lastStxBlockTime;
+      const lastSeen = new Date(lastStxBlockTime).toISOString();
+      const minSinceStxBlock = (lastStxBlockDiff / (1000 * 60)).toFixed(2);
+      lastBlockWarnTime = now;
+      logger.warn(
+        {
+          lastSeen,
+          secSinceStxBlock: lastStxBlockDiff / 1000,
+          minSinceStxBlock,
+        },
+        `No new stx block since ${minSinceStxBlock} minutes ago`
       );
+    }
+
+    if (showBurnMsg) {
+      loopLog.info('New burn block');
       if (current_burnchain_block_height === EPOCH_30_START) {
-        console.log('Starting Nakamoto!');
+        loopLog.info('Starting Nakamoto');
       }
     }
     if (showPrepareMsg) {
-      console.log(`Prepare phase started. Next cycle is ${reward_cycle_id + 1}`);
+      loopLog.info(
+        {
+          nextRewardCycle: reward_cycle_id + 1,
+        },
+        'Prepare phase started'
+      );
       const nextSigners = await getSignerSet(reward_cycle_id + 1);
       if (nextSigners) {
-        console.log(
-          `Next cycle (${info.nextCycleId}) has ${nextSigners.stacker_set.signers.length} signers`
+        loopLog.info(
+          {
+            nextSigners: nextSigners.stacker_set.signers.length,
+          },
+          `Next cycle (${reward_cycle_id + 1}) has ${
+            nextSigners.stacker_set.signers.length
+          } signers`
         );
       }
     }
 
-    if (!showBurnMsg && showStxBlockMsg) {
-      console.log(
-        `Nakamoto block: ${height}\t${blockInfo.tx_count} TX\t(${(lastStxBlockDiff / 1000).toFixed(
-          2
-        )} seconds)`
-      );
+    if (!showBurnMsg && showStxBlockMsg && blockInfo.burn_block_height >= EPOCH_30_START) {
+      loopLog.info({ lastStxBlockDiff: lastStxBlockDiff / 1000 }, 'Nakamoto block');
     }
     if (showStxBlockMsg && info.txs.length > 0) {
-      info.txs.forEach(({ contract_call, sender_address, tx_status }) => {
-        console.log(`${sender_address}:\t${contract_call.function_name}\t${tx_status}`);
+      info.txs.forEach(({ contract_call, sender_address, tx_status, ...tx }) => {
+        loopLog.info(
+          {
+            sender_address,
+            contract_call: contract_call.function_name,
+            tx_status,
+            tx_result: tx.tx_result.repr,
+          },
+          'New transaction confirmed'
+        );
       });
     }
 
     if (showCycleMsg) {
       const currentSigners = await getSignerSet(reward_cycle_id);
       const signerCount = currentSigners?.stacker_set.signers.length ?? 0;
-      console.log(`New cycle started (${reward_cycle_id}) with ${signerCount} signers`);
+      loopLog.info(
+        { signerCount },
+        `New cycle started (${reward_cycle_id}) with ${signerCount} signers`
+      );
     }
 
     if (reward_cycle_id >= EPOCH_30_START && !poxInfo.reward_slots) {
-      console.error('FATAL: no signers while going in to Epoch 3.0');
+      logger.error('FATAL: no signers while going in to Epoch 3.0');
       exit();
     }
   } catch (error) {
@@ -154,16 +203,13 @@ async function loop() {
     } else {
       console.error(error);
     }
-    console.error(message);
-    // if (!message.toLowerCase().includes('fetch failed')) {
-    //   throw error;
-    // }
+    logger.error(message);
   }
 }
 
 function exit() {
   if (EXIT_FROM_MONITOR) {
-    console.log('Exiting...');
+    logger.info('Exiting...');
     process.exit(1);
   }
 }

diff --git a/stacking/package.json b/stacking/package.json
@@ -9,13 +9,15 @@
   "license": "ISC",
   "dependencies": {
     "@stacks/api": "6.11.4-pr.472091f.0",
+    "@stacks/blockchain-api-client": "7.8.2",
+    "@stacks/common": "6.11.4-pr.36558cf.0",
     "@stacks/encryption": "6.11.4-pr.36558cf.0",
     "@stacks/network": "6.11.4-pr.36558cf.0",
     "@stacks/stacking": "6.11.4-pr.36558cf.0",
+    "@stacks/stacks-blockchain-api-types": "7.8.2",
     "@stacks/transactions": "6.11.4-pr.36558cf.0",
-    "@stacks/common": "6.11.4-pr.36558cf.0",
-    "@stacks/blockchain-api-client": "7.8.2",
-    "@stacks/stacks-blockchain-api-types": "7.8.2"
+    "pino": "^8.19.0",
+    "pino-pretty": "^10.3.1"
   },
   "devDependencies": {
     "@stacks/prettier-config": "^0.0.10",