fix: remove submitTransaction loop issue and improve logging

package.json

@@ -1,6 +1,6 @@
 {
   "name": "auctioneer-bot",
-  "version": "0.2.1",
+  "version": "0.2.2",
   "main": "index.js",
   "type": "module",
   "scripts": {

src/auction.ts

@@ -156,7 +156,7 @@ export async function calculateBlockFillAndPercent(
       const loopFillerBalances = new Map(fillerBalances);
       requests = [];
       logger.info(
-        `Calculating auction fill iteration ${iterations} with delay ${fillBlockDelay} and percent ${fillPercent}`
+        `Calculating auction fill iteration ${iterations} with delay ${fillBlockDelay} and percent ${fillPercent} and user ${auction.user}`
       );
       const [loopScaledAuction] = auction.scale(auction.data.block + fillBlockDelay, fillPercent);
       iterations++;

src/bidder_submitter.ts

@@ -135,6 +135,13 @@ export class BidderSubmitter extends SubmissionQueue<BidderSubmission> {
         await sendSlackNotification(logMessage);
         logger.info(logMessage);
         return true;
+      } else {
+        logger.info(
+          `Fill ledger not reached for auction bid\n` +
+          `Type: ${auctionBid.auctionEntry.auction_type}\n` +
+          `User: ${auctionBid.auctionEntry.user_id}\n` +
+          `Fill Ledger: ${fill.block}, Next Ledger: ${nextLedger}`
+        );
       }
       // allow bidder handler to re-process the auction entry
       return true;

src/filler.ts

@@ -27,12 +27,14 @@ export function canFillerBid(filler: Filler, auctionData: AuctionData): boolean
   // validate lot
   for (const [assetId, _] of auctionData.lot) {
     if (!filler.supportedLot.some((address) => assetId === address)) {
+      logger.info("Filler doesn't support lot asset: " + assetId);
       return false;
     }
   }
   // validate bid
   for (const [assetId, _] of auctionData.bid) {
     if (!filler.supportedBid.some((address) => assetId === address)) {
+      logger.info("Filler doesn't support bid asset: " + assetId);
       return false;
     }
   }

src/utils/soroban_helper.ts

@@ -240,7 +240,7 @@ export class SorobanHelper {
       .addOperation(xdr.Operation.fromXDR(operation, 'base64'))
       .build();
 
-    logger.info(`Attempting to simulate and submit transaction: ${tx.toXDR()}`);
+    logger.info(`Attempting to simulate and submit transaction ${tx.hash().toString("hex")}: ${tx.toXDR()}`);
     let simResult = await stellarRpc.simulateTransaction(tx);
 
     if (rpc.Api.isSimulationRestore(simResult)) {
@@ -281,6 +281,8 @@ export class SorobanHelper {
   private async sendTransaction(
     transaction: Transaction
   ): Promise<rpc.Api.GetSuccessfulTransactionResponse & { txHash: string }> {
+    logger.info(`Submitting transaction: ${transaction.hash().toString("hex")}`);
+    let submitStartTime = Date.now();
     const stellarRpc = new rpc.Server(this.network.rpc, this.network.opts);
     let txResponse = await stellarRpc.sendTransaction(transaction);
     if (txResponse.status === 'TRY_AGAIN_LATER') {
@@ -296,11 +298,16 @@ export class SorobanHelper {
       throw error;
     }
     let get_tx_response = await stellarRpc.getTransaction(txResponse.hash);
-    while (get_tx_response.status === 'NOT_FOUND') {
-      await new Promise((resolve) => setTimeout(resolve, 250));
+    while (get_tx_response.status === 'NOT_FOUND' && Date.now() - submitStartTime < 6000) {
+      await new Promise((resolve) => setTimeout(resolve, 500));
       get_tx_response = await stellarRpc.getTransaction(txResponse.hash);
     }
 
+    if (get_tx_response.status === 'NOT_FOUND') {
+      logger.error(`Transaction not found: ${txResponse.hash}`);
+      throw new Error('Transaction not found');
+    }
+
     if (get_tx_response.status !== 'SUCCESS') {
       const error = parseError(get_tx_response);
       logger.error(

src/utils/submission_queue.ts

@@ -43,6 +43,7 @@ export abstract class SubmissionQueue<T> {
       minRetryTimeout: minRetryTimeout,
       submission: submission,
     };
+    logger.info(`Adding submission to queue: ${stringify(submission)}`);
     this.submissions.push(retrieableSubmission);
     if (!this.processing) {
       this.processQueue();
@@ -52,7 +53,7 @@ export abstract class SubmissionQueue<T> {
   private retrySubmission(submission: Retriable<T>): void {
     if (submission.retries > 0) {
       submission.retries--;
-      logger.warn(`Retrying submission, ${submission.retries} retries remaining.`);
+      logger.warn(`Retrying submission, ${submission.retries} retries remaining. ${stringify(submission.submission)}`);
       this.submissions.push(submission);
     } else {
       logger.error(
@@ -66,13 +67,16 @@ export abstract class SubmissionQueue<T> {
    * Process the submission queue in FIFO order.
    */
   async processQueue() {
+    logger.info(`Processing queue with ${this.submissions.length} submissions.`);
     if (this.processing || this.submissions.length === 0) {
+      logger.info(`Queue is already processing or empty, stopping this task.`);
       return;
     }
     this.processing = true;
 
     while (this.submissions.length > 0) {
       let retrieableSubmission = this.submissions[0];
+      logger.info(`Processing submission: ${stringify(retrieableSubmission.submission)}`);
       let time_now = Date.now();
       let startTime = retrieableSubmission.timestamp + retrieableSubmission.minRetryTimeout;
       if (time_now < startTime) {

src/work_submitter.ts

@@ -58,6 +58,7 @@ export class WorkSubmitter extends SubmissionQueue<WorkSubmission> {
     userLiquidation: UserLiquidation
   ): Promise<boolean> {
     try {
+      logger.info(`Creating liquidation for user: ${userLiquidation.user}`);
       const pool = new PoolContract(APP_CONFIG.poolAddress);
       let op = pool.newLiquidationAuction({
         user: userLiquidation.user,
@@ -71,7 +72,7 @@ export class WorkSubmitter extends SubmissionQueue<WorkSubmission> {
         return true;
       }
       await sorobanHelper.submitTransaction(op, APP_CONFIG.keypair);
-      const logMessage = `Successfully submitted liquidation for user: ${userLiquidation.user} Liquidation Percent: ${userLiquidation.liquidationPercent}`;
+      const logMessage = `Successfully created liquidation for user: ${userLiquidation.user} Liquidation Percent: ${userLiquidation.liquidationPercent}`;
       logger.info(logMessage);
       await sendSlackNotification(logMessage);
       return true;
@@ -108,10 +109,11 @@ export class WorkSubmitter extends SubmissionQueue<WorkSubmission> {
     badDebtTransfer: BadDebtTransfer
   ): Promise<boolean> {
     try {
+      logger.info(`Transferring bad debt to backstop for user: ${badDebtTransfer.user}`);
       const pool = new PoolContract(APP_CONFIG.poolAddress);
       let op = pool.badDebt(badDebtTransfer.user);
       await sorobanHelper.submitTransaction(op, APP_CONFIG.keypair);
-      const logMessage = `Successfully submitted bad debt transfer for user: ${badDebtTransfer.user}`;
+      const logMessage = `Successfully transferred bad debt to backstop for user: ${badDebtTransfer.user}`;
       await sendSlackNotification(logMessage);
       logger.info(logMessage);
       return true;
@@ -127,6 +129,7 @@ export class WorkSubmitter extends SubmissionQueue<WorkSubmission> {
 
   async submitBadDebtAuction(sorobanHelper: SorobanHelper): Promise<boolean> {
     try {
+      logger.info(`Creating bad debt auction`);
       const pool = new PoolContract(APP_CONFIG.poolAddress);
       let op = pool.newBadDebtAuction();
       const auctionExists =
@@ -137,7 +140,7 @@ export class WorkSubmitter extends SubmissionQueue<WorkSubmission> {
         return true;
       }
       await sorobanHelper.submitTransaction(op, APP_CONFIG.keypair);
-      const logMessage = `Successfully submitted bad debt auction`;
+      const logMessage = `Successfully created bad debt auction`;
       logger.info(logMessage);
       await sendSlackNotification(logMessage);
       return true;