Logs Missing for Callback Methods

[idea404]

Current version v3.2.2 shows smart contract method logs on terminal output when running tests. However, whenever the contract method invoked by the test invokes a callback, any near.log() calls in the callback method are not shown.

For example, this contract code:

  @call({ payableFunction: true })
  calculate_index({ account_id }: { account_id: string }): void {
    near.log("calculate_index");
    // some logic here that invokes internalCallback method
  }

  @call({ privateFunction: true })
  internalCallback({ accountId, callCount }: { accountId: string; callCount: number }): void {
    near.log("internalCallback");
    // some further logic here
  }

When run by this test:

test.only("should return 0.00 if account with no transactions is not in whitelist and is in history", async (t) => {
  const { alice, indexContract } = t.context.accounts;
  await alice.call(indexContract, "calculate_index", {account_id: alice.accountId}, { gas: "30" + "0".repeat(12), attachedDeposit: "1" });
  t.pass();
});

Only shows the following logs after running test:

[idea404]

Upon digging a little further, I believe this might have to do with the underlying logic for promises I've implemented. Here's a simplified example of the contract code:

import { NearBindgen, near, call, view, LookupMap, NearPromise, UnorderedMap } from "near-sdk-js";
import Decimal from "decimal.js";

const WHITELISTED_ACCOUNTS = ["asac.test.near", "nearnautnft.test.near"]

@NearBindgen({})
class NearTrustIndex {
  accountIndexHistory: LookupMap<string>;
  accountIndexHistoryTimestamp: LookupMap<string>;
  accountIndexHistoryFailures: LookupMap<string>;
  accountResult: UnorderedMap<bigint>;
  testLogs: string[];

  constructor() {
    this.accountIndexHistory = new LookupMap("aih");
    this.accountIndexHistoryTimestamp = new LookupMap("aiht");
    this.accountIndexHistoryFailures = new LookupMap("aihf");
    this.accountResult = new UnorderedMap("ar");
    this.testLogs = [];
  }

  @view({})
  get_temp_logs(): string[] {
    return this.testLogs;
  }

  @call({ payableFunction: true })
  calculate_index({ account_id }: { account_id: string }): NearPromise | void {
    near.log("calculate_index");
    this.testLogs.push("calculate_index");
    // query whitelisted accounts for this account_id using NearPromise
    // ----
    const thirtyTgas = BigInt("30" + "0".repeat(12));
    let callCount = 0;
    let thisContract = Object.keys(WHITELISTED_ACCOUNTS)[0];
    near.log("thisContract: " + thisContract);
    this.testLogs.push("thisContract: " + thisContract);
    const promise = NearPromise.new(thisContract);
    // iterate through WHITELIST[thisContract] values
    for (let i = 0; i < 1; i++) { // only one function for now
      const functionName = "nft_supply_for_owner";
      near.log("functionName: " + functionName);
      this.testLogs.push("functionName: " + functionName);
      promise.functionCall(functionName, JSON.stringify({ account_id: account_id }), BigInt(0), thirtyTgas); // view method
      callCount++;
    }
    // iterate through remaining WHITELIST keys
    for (let i = 1; i < WHITELISTED_ACCOUNTS.length; i++) {
      thisContract = WHITELISTED_ACCOUNTS[i];
      near.log("thisContract: " + thisContract);
      this.testLogs.push("thisContract: " + thisContract);
      if (true) { // if contract has functions, in this case always 1
        near.log("creating promise");
        this.testLogs.push("creating promise");
        let newPromise = NearPromise.new(thisContract);
        // iterate through WHITELIST[thisContract] values
        for (let i = 0; i < 1; i++) { // only one function for now
          const functionName = "nft_supply_for_owner";
          near.log("functionName: " + functionName);
          this.testLogs.push("functionName: " + functionName);
          newPromise.functionCall(functionName, JSON.stringify({ account_id: account_id }), BigInt(0), thirtyTgas); // view method
          callCount++;
        }
        promise.then(newPromise);
        near.log("promise pushed");
        this.testLogs.push("promise pushed");
      }
    }
    near.log("invoking callback");
    this.testLogs.push("invoking callback");
    // call internalCallback
    promise.then(
      NearPromise
        .new(near.currentAccountId())
        .functionCall("internalCallback", JSON.stringify({ accountId: account_id, callCount: callCount }), BigInt(0), thirtyTgas)
    );
    // ----
    return promise.asReturn();
  } 

  @call({ privateFunction: true })
  internalCallback({ accountId, callCount }: { accountId: string; callCount: number }): void {
    near.log("internalCallback");
    this.testLogs.push("internalCallback");
    // loop through all call counts
    this.accountIndexHistoryFailures.set(accountId, "");
    let accountScores: number[] = [];
    // TODO: review this when we have more than 1 function in WHITELIST account functions
    for (let i = 0; i < callCount; i++) {
      let accountFunctions = ["nft_supply_for_owner"];
      for (let j = 0; j < accountFunctions.length; j++) {
        let functionName = accountFunctions[j];
        let mapKey = accountId + ":" + functionName; // nested collections cumbersome: https://docs.near.org/develop/contracts/storage#map
        this.testLogs.push("mapKey: " + mapKey);
        try {
          const promiseResult = near.promiseResult(i);
          try {
            const promiseObject = JSON.parse(promiseResult);
            this.accountResult.set(mapKey, promiseObject);
            const score = 1;
            accountScores.push(score);
          } catch (error) {
            const msg = "Failed saving result from successful promise for id: " + i + " with error message: " + error.message;
            near.log(msg);
            this.accountIndexHistoryFailures.set(mapKey, msg);
          }
        } catch (error) {
          const msg = `Contract Function ${i} threw error`;
          near.log(msg);
          this.accountIndexHistoryFailures.set(mapKey, msg);
        }
      }
    }
    // we save the new scores for every account and timestamp every record
    const timestamp = near.blockTimestamp().toString();
    const accountIndex = new Decimal("1").toFixed(2);
    // we iterate through accountAverageScores
    this.testLogs.push("accountIndex: " + accountIndex);
    this.accountIndexHistory.set(accountId, accountIndex);
    this.accountIndexHistoryTimestamp.set(accountId, timestamp);
  }
}

In essence, this creates a NearPromise.new() and adds additional promises in a for loop with .then(newPromise) and finally calls the callback again with .then(). It seems though as if the callback method of the contract is not entered.

I made a repo to replicate this here. To replicate, clone repo and run npm ci && npm run test:run. Terminal output upon running tests:

[volovyks]

@idea404 thanks for your investigation! It is always better to create a broken test in the repo, so we can iterate faster.
Can you please move a piece of code from your repo to tests?

[idea404]

@volovyks Have created a PR in JS SDK here: near/near-sdk-js#309

[idea404]

Closing the issue as undesired behavior was caused by improper syntax. Will leave PR open as an example of proper for loop promise syntax for the JS SDK.