Merge pull request #5567 from mempool/natsoni/block-first-seen-audit

Store first seen time in block audit

backend/mempool-config.sample.json

@@ -46,7 +46,8 @@
     "PASSWORD": "mempool",
     "TIMEOUT": 60000,
     "COOKIE": false,
-    "COOKIE_PATH": "/path/to/bitcoin/.cookie"
+    "COOKIE_PATH": "/path/to/bitcoin/.cookie",
+    "DEBUG_LOG_PATH": "/path/to/bitcoin/debug.log"
   },
   "ELECTRUM": {
     "HOST": "127.0.0.1",

backend/src/__fixtures__/mempool-config.template.json

@@ -47,7 +47,8 @@
     "PASSWORD": "__CORE_RPC_PASSWORD__",
     "TIMEOUT": 1000,
     "COOKIE": false,
-    "COOKIE_PATH": "__CORE_RPC_COOKIE_PATH__"
+    "COOKIE_PATH": "__CORE_RPC_COOKIE_PATH__",
+    "DEBUG_LOG_PATH": "__CORE_RPC_DEBUG_LOG_PATH__"
   },
   "ELECTRUM": {
     "HOST": "__ELECTRUM_HOST__",

backend/src/__tests__/config.test.ts

@@ -74,7 +74,8 @@ describe('Mempool Backend Config', () => {
         PASSWORD: 'mempool',
         TIMEOUT: 60000,
         COOKIE: false,
-        COOKIE_PATH: '/bitcoin/.cookie'
+        COOKIE_PATH: '/bitcoin/.cookie',
+        DEBUG_LOG_PATH: '',
       });
 
       expect(config.SECOND_CORE_RPC).toStrictEqual({

backend/src/api/database-migration.ts

@@ -7,7 +7,7 @@ import cpfpRepository from '../repositories/CpfpRepository';
 import { RowDataPacket } from 'mysql2';
 
 class DatabaseMigration {
-  private static currentVersion = 82;
+  private static currentVersion = 83;
   private queryTimeout = 3600_000;
   private statisticsAddedIndexed = false;
   private uniqueLogs: string[] = [];
@@ -705,6 +705,11 @@ class DatabaseMigration {
       await this.$fixBadV1AuditBlocks();
       await this.updateToSchemaVersion(82);
     }
+
+    if (databaseSchemaVersion < 83 && isBitcoin === true) {
+      await this.$executeQuery('ALTER TABLE `blocks` ADD first_seen datetime(6) DEFAULT NULL');
+      await this.updateToSchemaVersion(83);
+    }
   }
 
   /**

backend/src/api/websocket-handler.ts

@@ -16,6 +16,7 @@ import transactionUtils from './transaction-utils';
 import rbfCache, { ReplacementInfo } from './rbf-cache';
 import difficultyAdjustment from './difficulty-adjustment';
 import feeApi from './fee-api';
+import BlocksRepository from '../repositories/BlocksRepository';
 import BlocksAuditsRepository from '../repositories/BlocksAuditsRepository';
 import BlocksSummariesRepository from '../repositories/BlocksSummariesRepository';
 import Audit from './audit';
@@ -34,6 +35,7 @@ interface AddressTransactions {
 }
 import bitcoinSecondClient from './bitcoin/bitcoin-second-client';
 import { calculateMempoolTxCpfp } from './cpfp';
+import { getRecentFirstSeen } from '../utils/file-read';
 
 // valid 'want' subscriptions
 const wantable = [
@@ -1028,6 +1030,14 @@ class WebsocketHandler {
       }
     }
 
+    if (config.CORE_RPC.DEBUG_LOG_PATH && block.extras) {
+      const firstSeen = getRecentFirstSeen(block.id);
+      if (firstSeen) {
+        BlocksRepository.$saveFirstSeenTime(block.id, firstSeen);
+        block.extras.firstSeen = firstSeen;
+      }
+    }
+
     const confirmedTxids: { [txid: string]: boolean } = {};
 
     // Update mempool to remove transactions included in the new block

backend/src/config.ts

@@ -86,6 +86,7 @@ interface IConfig {
     TIMEOUT: number;
     COOKIE: boolean;
     COOKIE_PATH: string;
+    DEBUG_LOG_PATH: string;
   };
   SECOND_CORE_RPC: {
     HOST: string;
@@ -227,7 +228,8 @@ const defaults: IConfig = {
     'PASSWORD': 'mempool',
     'TIMEOUT': 60000,
     'COOKIE': false,
-    'COOKIE_PATH': '/bitcoin/.cookie'
+    'COOKIE_PATH': '/bitcoin/.cookie',
+    'DEBUG_LOG_PATH': '',
   },
   'SECOND_CORE_RPC': {
     'HOST': '127.0.0.1',

backend/src/mempool.interfaces.ts

@@ -320,6 +320,7 @@ export interface BlockExtension {
   segwitTotalSize: number;
   segwitTotalWeight: number;
   header: string;
+  firstSeen: number | null;
   utxoSetChange: number;
   // Requires coinstatsindex, will be set to NULL otherwise
   utxoSetSize: number | null;

backend/src/repositories/BlocksRepository.ts

@@ -57,6 +57,7 @@ interface DatabaseBlock {
   utxoSetChange: number;
   utxoSetSize: number;
   totalInputAmt: number;
+  firstSeen: number;
 }
 
 const BLOCK_DB_FIELDS = `
@@ -99,7 +100,8 @@ const BLOCK_DB_FIELDS = `
   blocks.header,
   blocks.utxoset_change AS utxoSetChange,
   blocks.utxoset_size AS utxoSetSize,
-  blocks.total_input_amt AS totalInputAmt
+  blocks.total_input_amt AS totalInputAmt,
+  UNIX_TIMESTAMP(blocks.first_seen) AS firstSeen
 `;
 
 class BlocksRepository {
@@ -1021,6 +1023,24 @@ class BlocksRepository {
     }
   }
 
+  /**
+   * Save block first seen time
+   * 
+   * @param id 
+   */
+  public async $saveFirstSeenTime(id: string, firstSeen: number): Promise<void> {
+    try {
+      await DB.query(`
+        UPDATE blocks SET first_seen = FROM_UNIXTIME(?)
+        WHERE hash = ?`,
+        [firstSeen, id]
+      );
+    } catch (e) {
+      logger.err(`Cannot update block first seen time. Reason: ` + (e instanceof Error ? e.message : e));
+      throw e;
+    }
+  }
+
   /**
    * Convert a mysql row block into a BlockExtended. Note that you
    * must provide the correct field into dbBlk object param
@@ -1078,6 +1098,7 @@ class BlocksRepository {
     extras.utxoSetSize = dbBlk.utxoSetSize;
     extras.totalInputAmt = dbBlk.totalInputAmt;
     extras.virtualSize = dbBlk.weight / 4.0;
+    extras.firstSeen = dbBlk.firstSeen;
 
     // Re-org can happen after indexing so we need to always get the
     // latest state from core

backend/src/utils/file-read.ts

@@ -0,0 +1,58 @@
+import * as fs from 'fs';
+import logger from '../logger';
+import config from '../config';
+
+function readFile(filePath: string, bufferSize?: number): string[] {
+  const fileSize = fs.statSync(filePath).size;
+  const chunkSize = bufferSize || fileSize;
+  const fileDescriptor = fs.openSync(filePath, 'r');
+  const buffer = Buffer.alloc(chunkSize);
+
+  fs.readSync(fileDescriptor, buffer, 0, chunkSize, fileSize - chunkSize);
+  fs.closeSync(fileDescriptor);
+
+  const lines = buffer.toString('utf8', 0, chunkSize).split('\n');
+  return lines;
+}
+
+function extractDateFromLogLine(line: string): number | undefined {
+  // Extract time from log: "2021-08-31T12:34:56Z" or "2021-08-31T12:34:56.123456Z"
+  const dateMatch = line.match(/^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d{6})?Z/);
+  if (!dateMatch) {
+    return undefined;
+  }
+
+  const dateStr = dateMatch[0];
+  const date = new Date(dateStr);
+  let timestamp = Math.floor(date.getTime() / 1000); // Remove decimal (microseconds are added later)
+
+  const timePart = dateStr.split('T')[1];
+  const microseconds = timePart.split('.')[1] || '';
+
+  if (!microseconds) {
+    return timestamp;
+  }
+
+  return parseFloat(timestamp + '.' + microseconds);
+}
+
+export function getRecentFirstSeen(hash: string): number | undefined {
+  const debugLogPath = config.CORE_RPC.DEBUG_LOG_PATH;
+  if (debugLogPath) {
+    try {
+      // Read the last few lines of debug.log
+      const lines = readFile(debugLogPath, 2048);
+
+      for (let i = lines.length - 1; i >= 0; i--) {
+        const line = lines[i];
+        if (line && line.includes(`Saw new header hash=${hash}`)) {
+          return extractDateFromLogLine(line);
+        }
+      }
+    } catch (e) {
+      logger.err(`Cannot parse block first seen time from Core logs. Reason: ` + (e instanceof Error ? e.message : e));
+    }
+  }
+
+  return undefined;
+}

docker/backend/mempool-config.json

@@ -47,7 +47,8 @@
     "PASSWORD": "__CORE_RPC_PASSWORD__",
     "TIMEOUT": __CORE_RPC_TIMEOUT__,
     "COOKIE": __CORE_RPC_COOKIE__,
-    "COOKIE_PATH": "__CORE_RPC_COOKIE_PATH__"
+    "COOKIE_PATH": "__CORE_RPC_COOKIE_PATH__",
+    "DEBUG_LOG_PATH": "__CORE_RPC_DEBUG_LOG_PATH__"
   },
   "ELECTRUM": {
     "HOST": "__ELECTRUM_HOST__",

docker/backend/start.sh

@@ -49,6 +49,7 @@ __CORE_RPC_PASSWORD__=${CORE_RPC_PASSWORD:=mempool}
 __CORE_RPC_TIMEOUT__=${CORE_RPC_TIMEOUT:=60000}
 __CORE_RPC_COOKIE__=${CORE_RPC_COOKIE:=false}
 __CORE_RPC_COOKIE_PATH__=${CORE_RPC_COOKIE_PATH:=""}
+__CORE_RPC_DEBUG_LOG_PATH__=${CORE_RPC_DEBUG_LOG_PATH:=""}
 
 # ELECTRUM
 __ELECTRUM_HOST__=${ELECTRUM_HOST:=127.0.0.1}
@@ -207,6 +208,7 @@ sed -i "s!__CORE_RPC_PASSWORD__!${__CORE_RPC_PASSWORD__}!g" mempool-config.json
 sed -i "s!__CORE_RPC_TIMEOUT__!${__CORE_RPC_TIMEOUT__}!g" mempool-config.json
 sed -i "s!__CORE_RPC_COOKIE__!${__CORE_RPC_COOKIE__}!g" mempool-config.json
 sed -i "s!__CORE_RPC_COOKIE_PATH__!${__CORE_RPC_COOKIE_PATH__}!g" mempool-config.json
+sed -i "s!__CORE_RPC_DEBUG_LOG_PATH__!${__CORE_RPC_DEBUG_LOG_PATH__}!g" mempool-config.json
 
 sed -i "s!__ELECTRUM_HOST__!${__ELECTRUM_HOST__}!g" mempool-config.json
 sed -i "s!__ELECTRUM_PORT__!${__ELECTRUM_PORT__}!g" mempool-config.json