Walletwasabi: Backend: CoinJoin transaction is not paying any fee.

[molnard]

It seems that the coordinator calculates the fee wrongly in some cases. This causes CJ fail to broadcast, then the round recreated and the problems go away but sometimes it happens again. So this seems like a permanent issue.

Exceptions

2020-08-03 15:04:24 ERROR   CoordinatorRound (769)  CoinJoin transaction is not paying any fee.
2020-08-03 15:04:24 ERROR   CoordinatorRound (816)  This is impossible. optimalFeeRate: 21.093 Sat/B, currentFeeRate: .

Aug  4 17:45:43 WalletWasabi walletwasabi-backend[22241]: 2020-08-04 17:45:43 ERROR#011CoordinatorRound (1147)#011System.ArgumentOutOfRangeException: Cannot be less than 0. (Parameter 'feePaid')
Aug  4 17:45:43 WalletWasabi walletwasabi-backend[22241]:    at NBitcoin.FeeRate..ctor(Money feePaid, Int32 size)
Aug  4 17:45:43 WalletWasabi walletwasabi-backend[22241]:    at NBitcoin.Transaction.GetFeeRate(ICoin[] spentCoins)
Aug  4 17:45:43 WalletWasabi walletwasabi-backend[22241]:    at WalletWasabi.CoinJoin.Coordinator.Rounds.CoordinatorRound.BroadcastCoinJoinIfFullySignedAsync()

Logs

2020-08-03 15:02:51 INFO    CoordinatorRound (216)  Round (25422): Phase change requested: InputRegistration.
2020-08-03 15:02:51 INFO    CoordinatorRound (263)  Round (25422): Phase initialized: InputRegistration.
2020-08-03 15:03:20 INFO    UtxoReferee (158)   UTXO unbanned: .
2020-08-03 15:03:29 INFO    IndexBuilderService (220)   Created filter for block: 642047.
2020-08-03 15:03:39 INFO    CoordinatorRound (299)  Round (25421): ConnectionConfirmation timed out after 60 seconds.
2020-08-03 15:03:39 INFO    UtxoReferee (138)   UTXO noted with severity: 1. UTXO: for disrupting Round 25421.
2020-08-03 15:03:39 INFO    UtxoReferee (138)   UTXO noted with severity: 1. UTXO: for disrupting Round 25421.
2020-08-03 15:03:39 INFO    CoordinatorRound (1352) Round (25421): 1 alices are removed.
2020-08-03 15:03:39 INFO    CoordinatorRound (1179) Round (25421): AnonymitySet updated: 57.
2020-08-03 15:03:39 INFO    CoordinatorRound (216)  Round (25421): Phase change requested: OutputRegistration.
2020-08-03 15:03:39 INFO    CoordinatorRound (263)  Round (25421): Phase initialized: OutputRegistration.
2020-08-03 15:03:46 INFO    UtxoReferee (158)   UTXO unbanned: .
2020-08-03 15:04:24 INFO    CoordinatorRound (216)  Round (25421): Phase change requested: Signing.
2020-08-03 15:04:24 INFO    CoordinatorRound (839)  Confirmation target is optimized from 4 blocks to 34 blocks.
2020-08-03 15:04:24 ERROR   CoordinatorRound (769)  CoinJoin transaction is not paying any fee.
2020-08-03 15:04:24 ERROR   CoordinatorRound (816)  This is impossible. optimalFeeRate: 21.093 Sat/B, currentFeeRate: .
2020-08-03 15:04:24 INFO    CoordinatorRound (263)  Round (25421): Phase initialized: Signing.
2020-08-03 15:04:33 INFO    CoordinatorRound (1091) Round (25422): Alice () timed out.
2020-08-03 15:04:47 INFO    UtxoReferee (158)   UTXO unbanned: .
2020-08-03 15:04:52 INFO    CoordinatorRound (1091) Round (25422): Alice () timed out.
2020-08-03 15:04:53 INFO    CoordinatorRound (1091) Round (25422): Alice () timed out.
2020-08-03 15:04:56 INFO    CoordinatorRound (1091) Round (25422): Alice () timed out.
2020-08-03 15:04:56 INFO    CoordinatorRound (1091) Round (25422): Alice () timed out.
2020-08-03 15:05:06 INFO    CoordinatorRound (1091) Round (25422): Alice () timed out.
2020-08-03 15:06:54 INFO    CoordinatorRound (307)  Round (25421): Signing timed out after 150 seconds. Aborting...
2020-08-03 15:06:54 INFO    UtxoReferee (138)   UTXO noted with severity: 1. UTXO: for disrupting Round 25421.
2020-08-03 15:06:54 INFO    UtxoReferee (138)   UTXO noted with severity: 1. UTXO: for disrupting Round 25421.
2020-08-03 15:06:54 INFO    CoordinatorRound (1179) Round (25422): AnonymitySet updated: 72.
2020-08-03 15:06:54 INFO    CoordinatorRound (362)  Round (25421): Aborted. Reason: 2 Alices did not sign..
2020-08-03 15:06:54 INFO    CoordinatorRound (216)  Round (25422): Phase change requested: ConnectionConfirmation.
2020-08-03 15:06:54 INFO    CoordinatorRound (263)  Round (25422): Phase initialized: ConnectionConfirmation.
2020-08-03 15:06:54 INFO    CoordinatorRound (69)   New round (25423) is created.
    BaseDenomination: 0.09510301 BTC.
    AdjustedConfirmationTarget: 2.
    CoordinatorFeePercent: 0.003%.
    AnonymitySet: 100.

[lontivero]

I still clueless. These are some facts:

* the problem happened on 3rd, 4th and 5th August
* the cj transaction contains all the inputs for all the Alices.
* all the inputs are signed, this means that:
* all the participants saw their outputs are there.
* the sum of the outputs is bigger than the sum of the inputs so,
* there have to be more outputs than what should be.

I remember @David fixed something similar time ago but the problem was the opposite.

[nopara73]

Investigation Part 1

TLDR. With @molnard we verified that

• The code around the fee calculation is correct.
• The sum of the outputs is bigger than the sum of the inputs.
• We cannot have duplicate alices (inputs.)

There are only 2 possibilities left, which we will investigate in Part 2:

• We remove Alices the wrong time.
• We add more outputs somehow.

How can the This is impossible. optimalFeeRate: 75.689 Sat/B, currentFeeRate: . log entry be possible?

The log entry comes in the else branch of if (optimalFeeRate != null && optimalFeeRate != FeeRate.Zero && currentFeeRate != null && currentFeeRate != FeeRate.Zero) // This would be really strange if it'd happen.. This can only happen if the currentFeeRate is null. Notice that is { } is checked with the != null, which suggest the code is old.

How can the currentFeeRate be null?

The previous log entry explains this: CoinJoin transaction is not paying any fee.. This log entry is written out if fee <= Money.Zero is true.

How can the fee be negative or zero?

The fee is calculated as follows: Money fee = transaction.GetFee(spentCoins.ToArray());. The issue can be sourced from two places:

1. Transaction.GetFee
2. spentCoins

Investigating Transaction.GetFee

Investigating the proper behavior of Transaction.GetFee is probably easier so I start with that. This is coming from NBitcoin. If NBitcoin changed this recently, then that would explain why the issue is coming out now. But the Transaction.cs in NBitcoin didn't change around GetFee lately: https://github.com/MetacoSA/NBitcoin/commits/master/NBitcoin/Transaction.cs

Maybe it makes sense to investigate the GetFee function if it works properly regardless.

One thing that sticks out is that if there are spentCoins given to this function those are spending the same outputs, then this function uses a dictionary to avoid duplicates. If we made a mistake and somehow are adding duplicate alices, then that would explain what we are experiencing. We traced it back to this crucial (and ugly) part of Wasabi's codebase:

if (round.ContainsInput(inputProof.Input, out List<Alice> tr))
{
    alicesToRemove.UnionWith(tr.Select(x => x.UniqueId)); // Input is already registered by this alice, remove it later if all the checks are completed fine.
}
if (Coordinator.AnyRunningRoundContainsInput(inputProof.Input, out List<Alice> tnr))
{
    if (tr.Union(tnr).Count() > tr.Count)
    {
        return BadRequest("Input is already registered in another round.");
    }
}

But this is correct, so duplicate alices are impossible unless there's a race condition.

Can there be a race condition so duplicate Alices are added?

Since the above function and the only place where we add Alice to the round round.AddAlice(alice); is in the same lock: using (await InputsLock.LockAsync()) there cannot be duplicated Alices.

Any issue with the remaining of Transaction.GetFee?

No, it actually makes sure that we are giving the correct spentCoins array and calculates the fees properly.

Money fees = -TotalOut;
foreach (var input in this.Inputs)
{
    if (!coinsByOutpoint.TryGetValue(input.PrevOut, out var coin))
        return null;
    fees += coin.TxOut.Value;
}
return fees;

This investigation verifies that the sum of the outputs is bigger than the sum of the inputs.

[MaxHillebrand]

This is a very well written report, thanks @nopara73 for keeping us up to date!

[nopara73]

If the issue is still here after days of deploying https://github.com/zkSNACKs/WalletWasabi/pull/4133, then we can be sure that the issue is on the output side.

[MaxHillebrand]

how often has the issue happened so far?

[nopara73]

I checked the server logs. Since https://github.com/zkSNACKs/WalletWasabi/pull/4133 was deployed this issue didn't come up. Considering that this issue was coming up about every 1-2 hours before that I think it's safe to say that this issue is resolved and the problem was with input removals after giving out blind signatures.