fix: dfx ledger transfer outputs messages about duplicates to log, no…

…t stdout (#3420)

If the replica reports a duplicate transaction in `dfx ledger transfer`, dfx prints out a message about this.  This change logs that message at info level, rather than printing it to stdout.  This makes the stdout output of `dfx ledger transfer` consistent.

Why info level, rather than warn level?  Anyone calling `dfx ledger transfer`, even without specifying `--created-at-time`, can see this duplicate transaction message.  This is because dfx retries failures, and uses a consistent created_at_time (either from `--created-at-time`, or by getting the current system time before the first attempt).  It's possible that a call succeeds, but there is an i/o error before dfx receives the response.  In this case dfx will retry, and get a duplicate transaction result.

Motivation: #3419 (comment)

CHANGELOG.md

@@ -2,6 +2,10 @@
 
 # UNRELEASED
 
+### fix: `dfx ledger transfer` now logs to stderr messages about duplicates rather than printing them to stdout
+
+The message "transaction is a duplicate of another transaction in block ...", previously printed to stdout, is now logged to stderr. This means that the output of `dfx ledger transfer` to stdout will contain only "Transfer sent at block height <block height>".
+
 ### feat: added `dfx cycles` command
 
 This won't work on mainnet yet, but can work locally after installing the cycles ledger.

e2e/tests-dfx/ledger.bash

@@ -43,32 +43,32 @@ current_time_nanoseconds() {
 @test "ledger balance & transfer" {
   dfx identity use alice
   assert_command dfx ledger account-id
-  assert_match 345f723e9e619934daac6ae0f4be13a7b0ba57d6a608e511a00fd0ded5866752
+  assert_eq 345f723e9e619934daac6ae0f4be13a7b0ba57d6a608e511a00fd0ded5866752
 
   assert_command dfx ledger balance
-  assert_match "1000000000.00000000 ICP"
+  assert_eq "1000000000.00000000 ICP"
 
   assert_command dfx ledger transfer --amount 100 --memo 1 22ca7edac648b814e81d7946e8bacea99280e07c5f51a04ba7a38009d8ad8e89 # to bob
-  assert_match "Transfer sent at block height"
+  assert_contains "Transfer sent at block height"
 
   # The sender(alice) paid transaction fee which is 0.0001 ICP
   assert_command dfx ledger balance
-  assert_match "999999899.99990000 ICP"
+  assert_eq "999999899.99990000 ICP"
 
   dfx identity use bob
   assert_command dfx ledger account-id
-  assert_match 22ca7edac648b814e81d7946e8bacea99280e07c5f51a04ba7a38009d8ad8e89
+  assert_eq 22ca7edac648b814e81d7946e8bacea99280e07c5f51a04ba7a38009d8ad8e89
 
   assert_command dfx ledger balance
-  assert_match "1000000100.00000000 ICP"
+  assert_eq "1000000100.00000000 ICP"
 
   assert_command dfx ledger transfer --icp 100 --e8s 1 --memo 2 345f723e9e619934daac6ae0f4be13a7b0ba57d6a608e511a00fd0ded5866752 # to alice
-  assert_match "Transfer sent at block height"
+  assert_contains "Transfer sent at block height"
 
   # The sender(bob) paid transaction fee which is 0.0001 ICP
   # 10100 - 100 - 0.0001 - 0.00000001 = 9999.99989999
   assert_command dfx ledger balance
-  assert_match "999999999.99989999 ICP"
+  assert_eq "999999999.99989999 ICP"
 
   # Transaction Deduplication
   t=$(current_time_nanoseconds)
@@ -77,25 +77,24 @@ current_time_nanoseconds() {
   # shellcheck disable=SC2154
   block_height=$(echo "$stdout" | sed '1q' | sed 's/Transfer sent at block height //')
   # shellcheck disable=SC2154
-  assert_match "Transfer sent at block height $block_height" "$stdout"
+  assert_eq "Transfer sent at block height $block_height" "$stdout"
 
   assert_command dfx ledger transfer --icp 1 --memo 1 --created-at-time $((t+1)) 345f723e9e619934daac6ae0f4be13a7b0ba57d6a608e511a00fd0ded5866752
   # shellcheck disable=SC2154
-  assert_match "Transfer sent at block height" "$stdout"
+  assert_contains "Transfer sent at block height" "$stdout"
   # shellcheck disable=SC2154
-  assert_not_match "Transfer sent at block height $block_height" "$stdout"
+  assert_not_contains "Transfer sent at block height $block_height" "$stdout"
 
   assert_command dfx ledger transfer --icp 1 --memo 1 --created-at-time "$t" 345f723e9e619934daac6ae0f4be13a7b0ba57d6a608e511a00fd0ded5866752
   # shellcheck disable=SC2154
-  assert_match "transaction is a duplicate of another transaction in block $block_height" "$stdout"
-  # shellcheck disable=SC2154
-  assert_match "Transfer sent at block height $block_height" "$stdout"
+  assert_eq "transaction is a duplicate of another transaction in block $block_height" "$stderr"
+  assert_eq "Transfer sent at block height $block_height" "$stdout"
 
   assert_command dfx ledger transfer --icp 1 --memo 2 --created-at-time "$t" 345f723e9e619934daac6ae0f4be13a7b0ba57d6a608e511a00fd0ded5866752
   # shellcheck disable=SC2154
-  assert_match "Transfer sent at block height" "$stdout"
+  assert_contains "Transfer sent at block height" "$stdout"
   # shellcheck disable=SC2154
-  assert_not_match "Transfer sent at block height $block_height" "$stdout"
+  assert_not_contains "Transfer sent at block height $block_height" "$stdout"
 
 }
 
@@ -178,13 +177,13 @@ tc_to_num() {
 
   assert_command dfx ledger top-up "$wallet" --icp 5 --created-at-time "$t"
   # shellcheck disable=SC2154
-  assert_match "transaction is a duplicate of another transaction in block $block_height" "$stdout"
+  assert_contains "transaction is a duplicate of another transaction in block $block_height" "$stderr"
   # shellcheck disable=SC2154
-  assert_match "Transfer sent at block height $block_height" "$stdout"
+  assert_contains "Transfer sent at block height $block_height" "$stdout"
   # shellcheck disable=SC2154
-  assert_match "Using transfer at block height $block_height" "$stdout"
+  assert_contains "Using transfer at block height $block_height" "$stdout"
   # shellcheck disable=SC2154
-  assert_match "Canister was topped up with" "$stdout"
+  assert_contains "Canister was topped up with" "$stdout"
 }
 
 @test "ledger create-canister" {
@@ -226,13 +225,13 @@ tc_to_num() {
 
   assert_command dfx ledger create-canister --amount=100 --created-at-time "$t" "$(dfx identity get-principal)"
   # shellcheck disable=SC2154
-  assert_match "transaction is a duplicate of another transaction in block $block_height" "$stdout"
+  assert_contains "transaction is a duplicate of another transaction in block $block_height" "$stderr"
   # shellcheck disable=SC2154
-  assert_match "Transfer sent at block height $block_height" "$stdout"
+  assert_contains "Transfer sent at block height $block_height" "$stdout"
   # shellcheck disable=SC2154
-  assert_match "Using transfer at block height $block_height" "$stdout"
+  assert_contains "Using transfer at block height $block_height" "$stdout"
   # shellcheck disable=SC2154
-  assert_match "Canister created with id: $created_canister_id" "$stdout"
+  assert_contains "Canister created with id: $created_canister_id" "$stdout"
 
 }
 

src/dfx/src/commands/ledger/create_canister.rs

@@ -77,6 +77,7 @@ pub async fn exec(env: &dyn Environment, opts: CreateCanisterOpts) -> DfxResult
 
     let height = transfer_cmc(
         agent,
+        env.get_logger(),
         memo,
         amount,
         fee,

src/dfx/src/commands/ledger/top_up.rs

@@ -71,6 +71,7 @@ pub async fn exec(env: &dyn Environment, opts: TopUpOpts) -> DfxResult {
 
     let height = transfer_cmc(
         agent,
+        env.get_logger(),
         memo,
         amount,
         fee,

src/dfx/src/commands/ledger/transfer.rs

@@ -80,6 +80,7 @@ pub async fn exec(env: &dyn Environment, opts: TransferOpts) -> DfxResult {
 
     let _block_height = transfer(
         agent,
+        env.get_logger(),
         &canister_id,
         memo,
         amount,

src/dfx/src/commands/quickstart.rs

@@ -31,6 +31,7 @@ use ic_utils::interfaces::{
 use indicatif::ProgressBar;
 use num_traits::Inv;
 use rust_decimal::Decimal;
+use slog::Logger;
 use tokio::runtime::Runtime;
 
 /// Use the `dfx quickstart` command to perform initial one time setup for your identity and/or wallet. This command
@@ -151,13 +152,14 @@ async fn step_deploy_wallet(
         eprintln!("Run this command again at any time to continue from here.");
         return Ok(());
     }
-    let wallet = step_interact_ledger(agent, ident_principal, rounded).await?;
+    let wallet = step_interact_ledger(agent, env.get_logger(), ident_principal, rounded).await?;
     step_finish_wallet(env, agent, wallet, ident).await?;
     Ok(())
 }
 
 async fn step_interact_ledger(
     agent: &Agent,
+    logger: &Logger,
     ident_principal: Principal,
     to_spend: Decimal,
 ) -> DfxResult<Principal> {
@@ -169,6 +171,7 @@ async fn step_interact_ledger(
     let icpts = ICPTs::from_decimal(to_spend)?;
     let height = transfer_cmc(
         agent,
+        logger,
         Memo(MEMO_CREATE_CANISTER /* 👽 */),
         icpts,
         TRANSACTION_FEE,

src/dfx/src/lib/operations/cmc.rs

@@ -8,12 +8,14 @@ use crate::lib::nns_types::icpts::ICPTs;
 use crate::lib::operations::ledger::transfer;
 use candid::{Decode, Encode, Principal};
 use ic_agent::Agent;
+use slog::Logger;
 
 const NOTIFY_CREATE_CANISTER_METHOD: &str = "notify_create_canister";
 const NOTIFY_TOP_UP_METHOD: &str = "notify_top_up";
 
 pub async fn transfer_cmc(
     agent: &Agent,
+    logger: &Logger,
     memo: Memo,
     amount: ICPTs,
     fee: ICPTs,
@@ -26,6 +28,7 @@ pub async fn transfer_cmc(
         AccountIdentifier::new(MAINNET_CYCLE_MINTER_CANISTER_ID, Some(to_subaccount)).to_address();
     transfer(
         agent,
+        logger,
         &MAINNET_LEDGER_CANISTER_ID,
         memo,
         amount,

src/dfx/src/lib/operations/ledger.rs

@@ -20,6 +20,7 @@ use ic_agent::{
     lookup_value, Agent, AgentError,
 };
 use ic_utils::{call::SyncCall, Canister};
+use slog::{info, Logger};
 use std::time::{SystemTime, UNIX_EPOCH};
 
 const ACCOUNT_BALANCE_METHOD: &str = "account_balance_dfx";
@@ -98,6 +99,7 @@ pub async fn xdr_permyriad_per_icp(agent: &Agent) -> DfxResult<u64> {
 #[context("Failed to transfer funds.")]
 pub async fn transfer(
     agent: &Agent,
+    logger: &Logger,
     canister_id: &Principal,
     memo: Memo,
     amount: ICPTs,
@@ -138,7 +140,7 @@ pub async fn transfer(
                 match result {
                     Ok(block_height) => break block_height,
                     Err(TransferError::TxDuplicate { duplicate_of }) => {
-                        println!("{}", TransferError::TxDuplicate { duplicate_of });
+                        info!(logger, "{}", TransferError::TxDuplicate { duplicate_of });
                         break duplicate_of;
                     }
                     Err(transfer_err) => bail!(transfer_err),