Solves #28918. Coming from #28918 (comment) discussion.
The intention is to decouple only the bugfix relevant commits from #28985, allowing them to be included in the 26.x release. This way, we can avoid disabling the coin selection fuzzing test for an entire release.
Note: Have introduced few changes to the bug fix commit so that the unit tests pass without the additional burden introduced in #28985.
<!--e57a25ab6845829454e8d69fc972939a-->
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
<!--006a51241073e994b41acfe9ec718e94-->
For detailed information about the code coverage, see the test coverage report.
<!--021abf342d371248e50ceaed478a90ca-->
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | josibake, murchandamus, achow101 |
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
<!--174a7506f384e20aa4161008e828411d-->
Reviewers, this pull request conflicts with the following ones:
If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.
38 | + if (m_found && m_match(nullptr)) { 39 | + throw std::runtime_error(strprintf("'%s' found in debug log\n", m_message)); 40 | + } 41 | + break; 42 | + case CheckType::DISABLE: 43 | + break; // do nothing
The DISABLE case doesn’t seem to get used anywhere.
10 | @@ -11,6 +11,12 @@ 11 | #include <list> 12 | #include <string> 13 | 14 | +enum class CheckType { 15 | + MATCH, // asserts message is found 16 | + NOT_MATCH, // asserts message is not found 17 | + DISABLE // disable assertion
Is this used? What would this be used for? Seems easier to use a bool, no?
No, it is not used. IIRC, I did it in this way to get a mechanism to enable/disable the logs watcher on the fly, without requiring to create a new one per watched message. Can migrate it to use a bool too. Was just considering potential future utilities.
477 | + // Add spendable coin at the BnB selection upper bound 478 | + CoinsResult available_coins; 479 | + add_coin(available_coins, *wallet, COIN + cost_of_change, /*feerate=*/CFeeRate(0), /*nAge=*/6*24, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true); 480 | + 481 | + // Now verify coin selection does not produce BnB result 482 | + ASSERT_DEBUG_LOG_NOT_FOUND("Coin Selection: Algorithm:bnb");
In d62d49c605f89a325b929e8fb48091b0b56399ee: is there really no other way to know which coin selection algorithm is being used, than to grep output logs for non-existence? This doesn't seem like the best way to test for a condition.
I actually did it in this way per achow request during coredev. My initial version involved returning the coin selection information in a separate struct https://github.com/furszy/bitcoin-core/commit/a1b2c53d1feddf748d7d91a884fe52e50998f61e in the tx creation result.
I do prefer my previous approach because it would allows us to retrieve this information at the RPC level as well. However, I am also fine going with this other option as well. It's not something widely used nowadays anyway. We can also revisit this when another feature/test needs it.
My initial version involved returning the coin selection information in a separate struct https://github.com/furszy/bitcoin-core/commit/a1b2c53d1feddf748d7d91a884fe52e50998f61e in the tx creation result.
Your initial version seems better to me. Looks like about the same amount of code or less for the better outcome. Checking for log messages in tests is a bit brittle and usually results in more churn down the line when log messages change.
For unit tests, having the information in a struct is fine. However I'm not sure that it is really useful information to return in the RPC. IIRC my suggestion for searching the debug log is for functional tests since those already have an assert_debug_log helper.
For end users, it may not be particularly useful. However, I think that additional information at the RPC level could be beneficial for other utilities, like a coin selection metrics tool or for connected applications that uses core as their backend. That said, there's no need to add it unless there's a need for it.
Other than that, will return to the struct commit then.
380 | @@ -377,7 +381,8 @@ BOOST_AUTO_TEST_CASE(bnb_search_test) 381 | expected_result.Clear(); 382 | add_coin(10 * CENT, 2, expected_result); 383 | CCoinControl coin_control; 384 | - const auto result11 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT, coin_control, coin_selection_params_bnb); 385 | + CAmount fee_to_deduce = available_coins.coins[OutputType::BECH32].begin()->GetFee(); 386 | + const auto result11 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT - fee_to_deduce, coin_control, coin_selection_params_bnb);
Nit: I think "deduct" would fit better here than "deduce":
CAmount fee_to_deduct = available_coins.coins[OutputType::BECH32].begin()->GetFee();
const auto result11 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT - fee_to_deduct, coin_control, coin_selection_params_bnb);
Done as suggested
399 | - add_coin(1 * CENT, 2, expected_result); 400 | - const auto result12 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT, coin_control, coin_selection_params_bnb); 401 | + add_coin(9 * CENT, /*nInput=*/0, expected_result); 402 | + add_coin(1 * CENT, /*nInput=*/0, expected_result); 403 | + fee_to_deduce = available_coins.coins[OutputType::BECH32].begin()->GetFee() * 2; // x2 because we expect two inputs 404 | + const auto result12 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT - fee_to_deduce, coin_control, coin_selection_params_bnb);
fee_to_deduct = available_coins.coins[OutputType::BECH32].begin()->GetFee() * 2; // x2 because we expect two inputs
const auto result12 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT - fee_to_deduct, coin_control, coin_selection_params_bnb);
412 | @@ -407,13 +413,14 @@ BOOST_AUTO_TEST_CASE(bnb_search_test) 413 | expected_result.Clear(); 414 | add_coin(9 * CENT, 2, expected_result); 415 | add_coin(1 * CENT, 2, expected_result); 416 | + fee_to_deduce = available_coins.coins[OutputType::BECH32].begin()->GetFee() * 2; // x2 because we expect two inputs
fee_to_deduct = available_coins.coins[OutputType::BECH32].begin()->GetFee() * 2; // x2 because we expect two inputs
Done as suggested
419 | coin_control.Select(select_coin.outpoint);
420 | PreSelectedInputs selected_input;
421 | selected_input.Insert(select_coin, coin_selection_params_bnb.m_subtract_fee_outputs);
422 | available_coins.Erase({(++available_coins.coins[OutputType::BECH32].begin())->outpoint});
423 | - const auto result13 = SelectCoins(*wallet, available_coins, selected_input, 10 * CENT, coin_control, coin_selection_params_bnb);
424 | + const auto result13 = SelectCoins(*wallet, available_coins, selected_input, 10 * CENT - fee_to_deduce, coin_control, coin_selection_params_bnb);
const auto result13 = SelectCoins(*wallet, available_coins, selected_input, 10 * CENT - fee_to_deduct, coin_control, coin_selection_params_bnb);
Done as suggested
1262 | @@ -1260,6 +1263,7 @@ static util::Result<CreatedTransactionResult> CreateTransactionInternal( 1263 | // accidental reuse. 1264 | reservedest.KeepDestination(); 1265 | 1266 | + wallet.WalletLogPrintf("Coin Selection: Algorithm:%s, Waste:%d", GetAlgorithmName(result.GetAlgo()), result.GetWaste());
nit from tidy CI:
tainer_base/ci/scratch/build/bitcoin-x86_64-pc-linux-gnu/src/wallet/spend.cpp
wallet/spend.cpp:1266:28: error: Unterminated format string used with LogPrintf [bitcoin-unterminated-logprintf,-warnings-as-errors]
1266 | wallet.WalletLogPrintf("Coin Selection: Algorithm:%s, Waste:%d", GetAlgorithmName(result.GetAlgo()), result.GetWaste());
| ^
| \n
Thx, fixed.
347 | @@ -345,6 +348,7 @@ BOOST_AUTO_TEST_CASE(bnb_search_test) 348 | 349 | CoinsResult available_coins; 350 | 351 | + coin_selection_params_bnb.m_effective_feerate = CFeeRate(0);
Nit: This test was already a bit weird to me, because it is categorized as belonging to "BnB", but the composition of preset inputs and the selection of additional inputs is a SelectCoins-level functionality that has little to do with specific coin selection algorithms. Composability should be tested at SelectCoins level (which it is in spend_tests and wallet_fundrawtransaction.py, although it could probably be more extensive). Since we already tested whether we can select two UTXOs that exactly match an amount in absence of fees above, I expect that we could remove this test altogether without losing coverage.
Approach ACK: 233a07ade88d13154771417cf7700736ffce5211
482 | + ASSERT_DEBUG_LOG_NOT_FOUND("Coin Selection: Algorithm:bnb"); 483 | + CCoinControl coin_control; 484 | + coin_control.m_feerate = effective_feerate; 485 | + coin_control.destChange = change_dest; 486 | + CRecipient recipient{PubKeyDestination({}), /*target=*/COIN, /*subtract_fee=*/true}; 487 | + BOOST_CHECK(CreateTransaction(*wallet, {recipient}, /*change_pos=*/-1, coin_control));
In d62d49c605f89a325b929e8fb48091b0b56399ee "test: add coverage for BnB-SFFO restriction"
It seems like using CreateTransaction is a bit too high level for the goal of this test. Really this test is targeting the function that runs the various coin selection algorithms and chooses the result to return. This would be ChooseSelectionResult. Although this function is not exposed, its callers are, so this test could use either SelectCoins or AutomaticCoinSelection to test the same behavior. This would also remove the need to have the debug.log helper or even changing CreatedTransactionResult to contain the coin selection algorithm used since both of those functions return a SelectionResult which will contain the algo.
FastRandomContext rand{};
CoinSelectionParams params{
rand,
/*change_output_size=*/ 31,
/*change_spend_size=*/ 68,
/*min_change_target=*/ 0,
/*effective_feerate=*/ CFeeRate(3000),
/*long_term_feerate=*/ CFeeRate(1000),
/*discard_feerate=*/ CFeeRate(1000),
/*tx_noinputs_size=*/ 0,
/*avoid_partial=*/ false,
};
params.m_subtract_fee_outputs = true;
params.m_change_fee = params.m_effective_feerate.GetFee(params.change_output_size);
params.m_cost_of_change = params.m_discard_feerate.GetFee(params.change_spend_size) + params.m_change_fee;
// Add spendable coin at the BnB selection upper bound
CoinsResult available_coins;
add_coin(available_coins, *wallet, COIN + params.m_cost_of_change, /*feerate=*/CFeeRate(0), /*nAge=*/6*24, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true);
// Now verify coin selection does not produce BnB result
auto result = SelectCoins(*wallet, available_coins, {}, COIN, {}, params);
BOOST_CHECK(result.has_value());
BOOST_CHECK(result->GetAlgo() != SelectionAlgorithm::BNB);
Yeah. That would work as well.
The CreateTransaction usage comes from the previous version of this work (before we agreed to disable BnB when SFFO is enabled). Where BnB was enabled and this was verifying that the resulting transaction didn't contain a change output.
Pulled. Thx.
Approach ACK
Updated per feedback. Thanks everyone.
Test wise; replaced the logs debugger approach for a low level function call (per #28994 (review)). And applied the test variables naming suggestions.
462 | + 463 | + FastRandomContext rand{}; 464 | + CoinSelectionParams params{ 465 | + rand, 466 | + /*change_output_size=*/ 31, 467 | + /*change_spend_size=*/ 68,
in https://github.com/bitcoin/bitcoin/pull/28994/commits/06cd7e0bea4408cc508ad4074a44ddced3c773f8:
(nit, more just documenting my own confusion): Why 31 and 68? It's a bit confusing as it seems like these numbers were chosen with intention, but when I changed them both to 0 the test still passed (and also still failed as expected with params.m_subtract_fee_outputs = false).
If there is a reason for choosing these numbers, it's worth documenting the reason in a comment. If the numbers are arbitrary, it would be better to use 0 for both as it better communicates that the choice of numbers is irrelevant to the test.
31 -> p2wpkh output size. 68 -> p2wpkh input size (high-r signature).
The previous test version didn't have any hardcoded value. However, since we are now calling a low-level function, we need to hardcode them. Setting them to 0 would be incorrect. Even though they are not currently in use on this process, the values must align with those used in the wallet. We learned this lesson the hard way; the coinselector_tests is full of invalid values that lack real meaning, affecting the introduction of new features and other changes in the past. This is why #28985 is what it is.
Cool, agree with using real-world values, but I think it's worth documenting why those specific values were chosen in a comment since the choice of values isn't relevant to the test.
Sure. Will add the following comment:
/*change_output_size=*/ 31, // unused value, use p2wpkh output size (wallet default change type)
/*change_spend_size=*/ 68, // unused value, use p2wpkh input size (high-r signature)
Pushed it. Thanks josi.
Looks good! I am uncomfortable with adding the log message in https://github.com/bitcoin/bitcoin/pull/28994/commits/a4c3294b11b78ea0ec6bb19e71aa84a3571df1f5 as it has nothing to do with the bug fix and I think it could confuse (or worse, alarm) users to see "Waste" in their logs in the context of coin selection when waste is a not well-documented, implementation-specific term. Can we drop https://github.com/bitcoin/bitcoin/pull/28994/commits/a4c3294b11b78ea0ec6bb19e71aa84a3571df1f5 for now and revisit debug logging in a separate PR, unrelated to the v26 release?
I am uncomfortable with adding the log message as it has nothing to do with the bug fix and I think it could confuse (or worse, alarm) users to see "Waste" in their logs in the context of coin selection when waste is a not well-documented, implementation-specific term. Can we drop this commit for now and revisit debug logging in a separate PR, unrelated to the v26 release?
Logs aren't meant for end users; logs are useful for us to understand what is going on internally. Debug issues and provide better feedback to our users. This is not different to what we do for the fee calculation. And there is more documentation about the selection waste than doc about each of the logged fee reasons actually.
Right now, the transaction creation process lacks of outputting this information (thus why we are forced to call a low level function to test the bug). Moreover, as coin selection isn't a deterministic process, the lack of this info makes debugging and helping users harder than what it should.
That being said, if you and others agree on removing the logging after reading the rationale I just wrote, could drop it too. I'm not that hard on it.
Logs aren't meant for end users
Strongly disagree with this statement, and regardless of who they are intended for, users (people who run nodes) have access to these logs and do look at them.
This is not different to what we do for the fee calculation. And there is more documentation about the selection waste than doc about each of the logged fee reasons actually.
This is irrelevant to my point that this is not a bug fix and shouldn't be included in a bug fix PR. I also don't agree with the justification and claim that coin selection is well-documented, but I'd rather leave that discussion for a PR related to improving wallet logging and keep this one focused on the bug fix for v26 :)
This is irrelevant to my point that this is not a bug fix and shouldn't be included in a bug fix PR. I also don't agree with the justification and claim that coin selection is well-documented.
Where did I claim that coin selection is well-documented? I said that it is more documented than fee estimation. And fee estimation is being logged.
Strongly disagree with this statement, and regardless of who they are intended for, users (people who run nodes) have access to these logs and do look at them.
Everyone have access. That doesn't mean that they are meant for everyone. Thus why we have logging domains and levels. Moreover, most logging domains are disabled by default. Including the wallet one.
Where did I claim that coin selection is well-documented?
Sorry, my comment should say s/well-documented/more documented/
Where did I claim that coin selection is well-documented?
Sorry, my comment should say
s/well-documented/more documented/
np. Happens on any convo.
I'm not that strong on the new logging introduction, still, sharing the change rationale and opening the convo helps moving forward.
1262 | @@ -1260,6 +1263,7 @@ static util::Result<CreatedTransactionResult> CreateTransactionInternal( 1263 | // accidental reuse. 1264 | reservedest.KeepDestination(); 1265 | 1266 | + wallet.WalletLogPrintf("Coin Selection: Algorithm:%s, Waste:%d\n", GetAlgorithmName(result.GetAlgo()), result.GetWaste());
Looks good! I am uncomfortable with adding the log message in a4c3294 as it has nothing to do with the bug fix and I think it could confuse (or worse, alarm) users to see "Waste" in their logs in the context of coin selection when waste is a not well-documented, implementation-specific term. Can we drop a4c3294 for now and revisit debug logging in a separate PR, unrelated to the v26 release?
Perhaps it would sound less scary to potential end-users if you write:
wallet.WalletLogPrintf("Coin Selection: Algorithm:%s, Waste Metric Score:%d\n", GetAlgorithmName(result.GetAlgo()), result.GetWaste());
"Bitcoin Waste Metric" at least quickly finds some useful resources on the internet.
My concern is less with the specific wording and more that we are logging low-level algorithm internals that at best are not actionable for the node runner and at worst confusing.
For developers, the algorithm and waste metric (along with additional data points) are already captured in TRACE5:
So my questions are:
In general, I think we should have a strong justification for adding logs and I don't see that here.
Tracepoints are OS level hooks that are not part of the software by default. Logging is about keeping the history of events that occurred along the software lifetime. This does not only involve errors, it also involves information about the soft activity. Unlike logging, which can be enabled on-the-fly by simply calling an RPC command, users cannot enable tracepoints on their node without recompiling the software with a specific flag. Which requires compiling knowledge, forces the user to shutdown the node, etc..
Usually, when users encounter an issue, we require further information to assess them properly. Thus we ask for the logs. This events record need to provide us sufficient information to understand the behavior of the system so we can provide better assessment to our users, and also to encounter issues remotely. In the context of this PR, coin selection is not deterministic and its behavior is not recorded anywhere. Thus, we have no way of knowing how the process operated, making it more challenging to understand and find bugs than it should be.
By logging the coin selection algorithm name and the waste score (at least), we gain information that we currently don't have. This information can be useful for identifying issues and explaining behaviors that may occur only once and be hard to replicate.
My concern is less with the specific wording and more that we are logging low-level algorithm internals that at best are not actionable for the node runner and at worst confusing.
Not all logs need to be actionable by the node runner. In fact, most of them are not. The messages that are meant to provide an actionable path for the user are logged by default, the rest are under specific logging domain. Existing to help us detect issues and describe behaviors remotely. What I mean with this is that node runners need to explicitly enable the wallet logging to see the introduced log. Which, usually, they only do upon request when they are facing a problem.
Feels like we are talking past each other a bit here. My point is that for developers, we already have tracepoints as a tool for debugging and observability into low-level details of how the software is working. In many cases, a developer will try to reproduce an issue reported by a user on their own node, at which point debuggers and tracepoints are going to be more useful than logs.
For node runners, if someone provided us with this log I don't see how having this would have helped any of us troubleshoot this specific issue with BnB and SFFO, and I don't think you have provided a compelling argument for how this log helps with this specific issue, which is why I'm pushing back on it being added in this PR.
I don't like seeing logs added in PRs without strong justification because this leads to log bloat over time, which is where I think we currently are in this project. If you feel that logging in the wallet is insufficient, then by all means open a logging improvement PR and we can discuss what to log and at what levels to log on that PR.
The logs are useful for figuring out what happened when a user asks about why their wallet chose a crazy number of UTXOs when one would have been sufficient. As we add more algos, being able to see in the logs what algo was used, and what the resulting waste score was, is helpful for investigating such questions.
wallet chose a crazy number of UTXOs when one would have been sufficient
I don't see how this example is relevant to this PR, which is why I think the logging discussion would be better moved to a logging PR.
This also presumes the user already had the logging enabled before the issue happened. I'm not sure the costs outweigh the benefits of having this log always on to be able to answer questions like your example.
This log line is on by default.
Again, not convinced having this log on all the time is worth it, and don't see how this log is relevant to this PR.
My point is that for developers, we already have tracepoints as a tool for debugging and observability into low-level details of how the software is working. In many cases, a developer will try to reproduce an issue reported by a user on their own node, at which point debuggers and tracepoints are going to be more useful than logs.
Replicate issues without information is by far more challenging than replicating them with information. It is a blind guess.
Also, what you are saying works (up to a certain point) for deterministic procedures but not for non-deterministic ones. Coin selection, like many other processes, isn't deterministic, and usually, we cannot replicate exactly what happened to the user. Moreover, you are not taking into account the sensitivity of the wallet information. There is data we can request in public, and some other data that is safer not to request, affecting how wallet behaviors can be understood and replicated remotely.
Again, not convinced having this log on all the time is worth it, and don't see how this log is relevant to this PR.
Back to the original bug fix PR #28395, this issue provokes the transaction creation process to generate a change output for a set of BnB selected coins, which is unexpected and incorrect. BnB is specialized for changeless solutions.
In case this issue would had arose in one of our users' wallets, logging this information could have helped us to detect the problem remotely. We would have noticed that the transaction creation process produced a change output after selecting coins using BnB. And start our investigation from there. Eliminating any blind guess start.
Looking at #28395, the bug is related to SFFO. If we are going to log something, it would be better to log information related to what options the user selected, such as logging that SFFO was selected (I did a quick grep and didn't see that this was being logged, but might have missed it). In general, I think it's always better to log the parameters that were used to start a process, rather than log the resulting algorithm internals.
If we expect BnB to always produce changeless solutions, why aren't we instead checking this assumption after coin selection and logging an error, or at least a warning, that BnB produced change? That would make more sense to me than what you currently have.
Just to reiterate in case it's not clear: I'm not opposed to logging. I just don't think adding this specific log here helps at all and I think if we are going to add logs, let's take a more holistic look at what's being logged or not logged in the wallet, what's is most actionable for troubleshooting, and decide what levels things should be logged at in separate PR.
I think @josibake is making a good point here. Algorithm and waste score by itself would probably still make it difficult to learn something about what went wrong (although they would be useful if the issue filer also provided the corresponding transaction). It might be better to log the parameters for the coin selection attempt and the outcome:
Don’t log: exact utxos spent or created, payment amount, change amount, count of available UTXOs, wallet balance, etc.
This should probably be at a lower detail level, though. For this PR, perhaps logging a warning if BnB created a change output would be indeed a good way forward.
it would be better to log information related to what options the user selected, such as logging that SFFO was selected (I did a quick grep and didn't see that this was being logged, but might have missed it). In general, I think it's always better to log the parameters that were used to start a process, rather than log the resulting algorithm internals.
That's not correct. The wallet stores its own state linked to the inner node's state. Logging users' RPC command inputs only provides limited information. These inputs can easily be requested on-demand. Anyone can copy-paste the RPC command line in a public place (hiding the sensitive data). What users cannot do is provide all wallet internal information publicly, which is used throughout any wallet process. Furthermore, and once more, the coin selection procedure is not deterministic. Logging only the high-level user inputs wouldn't help with non-deterministic incorrect behaviors, failures, or crashes.
If we expect BnB to always produce changeless solutions, why aren't we instead checking this assumption after coin selection and logging an error, or at least a warning, that BnB produced change? That would make more sense to me than what you currently have.
What you are suggesting is ok for a post-mortem comment. You mindset is set as if we would be knowing all things that could happen, and thats incorrect. I wish we would have a crystal ball to see the future and include the same checks for all possible issues. The truth is that code is written by people, and AIs, and people make mistakes and forget about including checks. And logging certain specific internal events help troubleshooting issues. In this case, the logging would have helped us.
let's take a more holistic look at what's being logged or not logged in the wallet, what's is most actionable for troubleshooting, and decide what levels things should be logged at in separate PR.
Thats a separate topic. Wouldn't be bad to have someone doing it. Go ahead with it.
What you are suggesting is ok for a post-mortem comment.
I think you're misunderstanding my point. I am saying in the context of this PR (which is a bug fix), I don't think the log line you are adding here adds value and that a better thing to add in this PR would be a check that BnB is never returning change, which either errors or logs a warning.
What you are suggesting is ok for a post-mortem comment.
I think you're misunderstanding my point. I am saying in the context of this PR (which is a bug fix), I don't think the log line you are adding here adds value and that a better thing to add in this PR would be a check that BnB is never returning change, which either errors or logs a warning.
I'm following the discussion. The starting point was "the logging line is not useful". So, I presented the arguments for which this line adds value and would have helped us detect this problematic and probably others in the future (because otherwise we don't have such information at all).
Your suggestion about adding an extra check is good as a plus. But, it does not refutes the other points I expressed above (https://github.com/bitcoin/bitcoin/pull/28994#discussion_r1419054827, second paragraph). We can't check for things we not know about. We did not know about this issue or the lack of a changeless solution check before, the log line would had been helpful to notice it. Same could happen with other problematics in the future for other causes. Thats all.
Right, but this is my concern: a bug is found and fixed, and then a log is added that might have helped detect the already fixed bug (in this case, I'm still not convinced this log as written would have helped much). This pattern tends toward log bloat over time.
What I have been suggesting from the beginning is that we keep this PR focused on the bug fix and address logging in a separate PR where we can take a more holistic look. I do think logging the input parameters for coin selection is going to be far more helpful in troubleshooting these types of issues in the future, and also think instead of logs we should prefer adding assumption checks that either fail quickly or warn the user.
At this point, I think we just disagree on the usefulness of logs. I'd still prefer if we left this commit off this PR, but I'm not going to argue the point any further.
Right, but this is my concern: a bug is found and fixed, and then a log is added that might have helped detect the already fixed bug (in this case, I'm still not convinced this log as written would have helped much). This pattern tends toward log bloat over time.
Well, thats not what occurs in practice. Isn't a pattern at all. Could check all solved bugs in the wallet the past ~2 years (since I'm around at least) and see how many log lines were added to the wallet. I'm quite confident that we did not introduce non-useful logging lines there.
I do think logging the input parameters for coin selection is going to be far more helpful in troubleshooting these types of issues in the future
Glad you are on-board about logging internal processes information now :).
instead of logs we should prefer adding assumption checks that either fail quickly or warn the user.
Thats for sure, hard to disagree. But all of us make mistakes writing code; checks could be forgotten. And processes could be none deterministic. Logging certain specific information helps troubleshooting this situations.
At this point, I think we just disagree on the usefulness of logs. I'd still prefer if we left this commit off this PR, but I'm not going to argue the point any further.
Sure. I'm actually stronger for it now.
391 | @@ -390,9 +392,10 @@ BOOST_AUTO_TEST_CASE(bnb_search_test)
392 | add_coin(available_coins, *wallet, 1 * CENT, coin_selection_params_bnb.m_effective_feerate, 6 * 24, false, 0, true);
I just realized that this breaks the test. Deducting the fee of a specific count of inputs from the target breaks the equivalence of the input sets. The two inputs 9+1 now have exactly the target amount, whereas the single input of 10 will lead to an excess of one input fee. This would mean that whatever the feerate and long-term feerate, the solution with 9 and 1 would be preferred.
Instead of deducting the fee of two inputs from the target, this test should be fixed by adding one input fee to the amount of each coin, i.e. replace three add_coin lines with:
input_fee = available_coins.coins[OutputType::BECH32].begin()->GetFee();
add_coin(available_coins, *wallet, 10 * CENT + input_fee, coin_selection_params_bnb.m_effective_feerate, 6 * 24, false, 0, true);
add_coin(available_coins, *wallet, 9 * CENT + input_fee, coin_selection_params_bnb.m_effective_feerate, 6 * 24, false, 0, true);
add_coin(available_coins, *wallet, 1 * CENT + input_fee, coin_selection_params_bnb.m_effective_feerate, 6 * 24, false, 0, true);
And…
Great catch, thanks!. Fixed.
396 | - add_coin(1 * CENT, 2, expected_result); 397 | - const auto result12 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT, coin_control, coin_selection_params_bnb); 398 | + add_coin(9 * CENT, /*nInput=*/0, expected_result); 399 | + add_coin(1 * CENT, /*nInput=*/0, expected_result); 400 | + fee_to_deduct = available_coins.coins[OutputType::BECH32].begin()->GetFee() * 2; // x2 because we expect two inputs 401 | + const auto result12 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT - fee_to_deduct, coin_control, coin_selection_params_bnb);
… drop the deducted fee:
add_coin(9 * CENT + input_fee, /*nInput=*/0, expected_result);
add_coin(1 * CENT + input_fee, /*nInput=*/0, expected_result);
const auto result12 = SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, 10 * CENT, coin_control, coin_selection_params_bnb);
Done
I realized that we need to add the input fee to each UTXO rather than deducting it from the target for the two input set options to have the same waste score.
Co-authored-by: furszy <matiasfurszyfer@protonmail.com>
Useful for understanding what is going on internally
when the software is running. Debug issues, and provide
more accurate feedback to users.
Updated per feedback. Thanks. Applied @murchandamus suggestion of adding inputs fee to each UTXO rather than deduct them from the target. The latter one was breaking the equivalence of the input sets.
Note:
I did not improve the test code organization on purpose. Made the smallest change-set possible to not interfere with #28985. (I just reused the hardcoded number for the p2wpkh input size, just like we do in several other places inside the coinselector_tests file).
Note 2:
Haven't introduced the "BnB never produces change" assertion because it requires further restructuring.
The responsibility of asserting that a certain coin selection algorithm did not produce change shouldn't lie at the wallet's tx creation level. Instead, it should be internal to the selection algorithm. However, to achieve this, we need to modify the way the "create change" decision is made. For instance, it would be good to introduce a field inside SelectionResult that expresses the coin selection algo's expectation in terms of producing change or not.
ACK https://github.com/bitcoin/bitcoin/commit/1d3bc77cbe25a8492a4733841bb7d6ecd6d60d30
Applied @murchandamus suggestion of adding inputs fee to each UTXO rather than deduct them from the target. The latter one was breaking the equivalence of the input sets.
Wasn't the test still passing before, when you were deducting them from the target? If so, I would suggest we take a closer look at this test in #28985 to ensure it's testing the thing it's supposed to be testing.
The BnB search test was passing before as well, because it was expecting that BnB prefer the two input solution over the one input solution at low feerates, and deducting the fee from the target instead of adding the fee to the inputs caused the two input solution to have a better waste score than the one input solution: because the target was reduced the one input solution had an excess of one input fee.
Now that the inputs instead have their fee added to the amount, neither the one-input nor the two-input solution have excess, and only the waste score of the inputs is relevant. I’m not sure if we can explicitly test this assumption, since we only return the result that was finally picked.
Applied @murchandamus suggestion of adding inputs fee to each UTXO rather than deduct them from the target. The latter one was breaking the equivalence of the input sets.
Wasn't the test still passing before, when you were deducting them from the target? If so, I would suggest we take a closer look at this test in #28985 to ensure it's testing the thing it's supposed to be testing.
Yes, it was passing but not for the right reason. Deducting the input fees from the target was equivalent to pre-selecting the expected coins. The explanation is as follows: On the test, there are three UTXOs: UTXO_A of 10, UTXO_B of 9 and UTXO_C of 1, we expect BnB to select UTXO_B and UTXO_C with a target of 10. If we deduce the target by the inputs fee, we set the target to 10 - fee * 2 which is below UTXO_A amount. So, regardless of the feerate, UTXO_A is never picked. Thus why the fix was straightforward; instead of decreasing the target amount by the expected inputs fee, we need to decrease the UTXOs amount equally, letting coin selection pick the UTXOs by its own.
481 | + CoinsResult available_coins; 482 | + add_coin(available_coins, *wallet, COIN + params.m_cost_of_change, /*feerate=*/CFeeRate(0), /*nAge=*/6*24, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true); 483 | + // Now verify coin selection does not produce BnB result 484 | + auto result = WITH_LOCK(wallet->cs_wallet, return SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, COIN, /*coin_control=*/{}, params)); 485 | + BOOST_CHECK(result.has_value()); 486 | + BOOST_CHECK_NE(result->GetAlgo(), SelectionAlgorithm::BNB);
Since there is only a single input, all algorithms that produce a solution would necessarily use the same input set. It was not obvious to me why we expect the BnB solution to be the one returned if it was produced. It seems to me that it is because BnB runs first and we prefer the first equivalent solution if we have multiple. If that is right that feels like a brittle assumption to test. What if e.g. someone introduced another coin selection algorithm later that is run before BnB? The test would still pass, but we would no longer test the absence of BnB at all.
Let’s instead test with a set of UTXOs where we have different predictable input sets for all algorithms and if BnB produced a solution it would be the preferred solution:
add_coin(available_coins, *wallet, COIN + params.m_cost_of_change, /*feerate=*/params.m_effective_feerate, /*nAge=*/6*24, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true);
add_coin(available_coins, *wallet, 0.7 * COIN + params.m_cost_of_change, /*feerate=*/params.m_effective_feerate, /*nAge=*/6*24, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true);
add_coin(available_coins, *wallet, 0.6 * COIN, /*feerate=*/params.m_effective_feerate, /*nAge=*/6*24, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true);
// Knapsack will only find a changeless solution on an exact match to the satoshi, SRD doesn’t look for changeless
// If BnB were run, it would produce a single input solution with the best waste score
auto result = WITH_LOCK(wallet->cs_wallet, return SelectCoins(*wallet, available_coins, /*pre_set_inputs=*/{}, COIN, /*coin_control=*/{}, params));
BOOST_CHECK(result.has_value());
BOOST_CHECK_NE(result->GetAlgo(), SelectionAlgorithm::BNB);
BOOST_CHECK(result->GetInputSet().size() == 2);
// We have only considered BnB, SRD, and Knapsack. Test needs to be reevaluated if new algo is added
BOOST_CHECK(result->GetAlgo() == SelectionAlgorithm::SRD || result->GetAlgo() == SelectionAlgorithm::KNAPSACK);
While I like the idea, I don't think it will work as you expect. We are passing CFeeRate(0) to add_coin(), which generates coins with fee=0, which at the "spending now vs spending in the future" calculation point means a negative waste (because of waste = fee_to_spend_now - fee_to_spend_in_the_future --> waste = 0 - something). And this negative number increases with the number of selected coins. So, at least in a first glance, this means that the process will always prefer the solution with the largest inputs set, and never BnB.
Will give it a deeper look and see how to adapt it to fulfill its purpose.
Ah oops my bad. I was backporting my proposed refactor from https://github.com/bitcoin/bitcoin/pull/28985/commits/5b8c165c2ae0448b802c0c4907303d016f301f0a. I use a feerate of 3000 ṩ/kvB there, but overlooked that it was still set to 0 here. Since the long-term feerate is set to 1000 ṩ/vB here, this makes our transaction building follow high-feerate behavior.
I’ve edited my code suggestion in the above comment to correct the feerate.
Ah oops my bad. I was backporting my proposed refactor from 5b8c165. I use a feerate of 3000 ṩ/kvB there, but overlooked that it was still set to 0 here. Since the long-term feerate is set to 1000 ṩ/vB here, this makes our transaction building follow high-feerate behavior.
I’ve edited my code suggestion in the above comment to correct the feerate.
the approach is better but still fail. Knapsack retrieves the single input solution. The "lower larger" excess is smaller than the two inputs solution excess. So, the BOOST_CHECK(result->GetInputSet().size() == 2); fails.
Will fix it making the excess of the two inputs solution smaller than the "lower larger" one.
I see what happened. Knapsack was finding a changeless solution in the first attempt where it should look for something with change because min_change_target was set to zero. I expected it to find a solution with change, because that’s what knapsack is supposed to do first when the min_change_target is at least 25k sats.
Looks much better. I have another idea how to improve the tx_creation_bnb_sffo_restriction test, which I think would make it clearer what is being tested there
Updated per feedback. Thanks @murchandamus. Test-only changes. Removed the assumption that BnB always executes first.
465 | + FastRandomContext rand{}; 466 | + CoinSelectionParams params{ 467 | + rand, 468 | + /*change_output_size=*/ 31, // unused value, p2wpkh output size (wallet default change type) 469 | + /*change_spend_size=*/ 68, // unused value, p2wpkh input size (high-r signature) 470 | + /*min_change_target=*/ 0,
Setting min_change_target to 0 makes Knapsack always look for changeless solutions
Fixed. Thanks.
ACK 18669d753a15f997f7363dcaf0abf230b851b224
Verify the transaction creation process does not produce
a BnB solution when SFFO is enabled.
This is currently problematic because it could require a
change output. And BnB is specialized on changeless solutions.
Co-authored-by: Andrew Chow <achow101@gmail.com>
Co-authored-by: Murch <murch@murch.one>
482 | + CoinsResult available_coins; 483 | + add_coin(available_coins, *wallet, COIN + params.m_cost_of_change, /*feerate=*/params.m_effective_feerate, /*nAge=*/6, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true); 484 | + add_coin(available_coins, *wallet, 0.5 * COIN + params.m_cost_of_change, /*feerate=*/params.m_effective_feerate, /*nAge=*/6, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true); 485 | + add_coin(available_coins, *wallet, 0.5 * COIN, /*feerate=*/params.m_effective_feerate, /*nAge=*/6, /*fIsFromMe=*/true, /*nInput=*/0, /*spendable=*/true); 486 | + // Knapsack will only find a changeless solution on an exact match to the satoshi, SRD doesn’t look for changeless 487 | + // If BnB were run, it would produce a single input solution with the best waste score
Good, now I’d expect:
Since the feerate is higher than the LFTR, two or three inputs with change are worse than one input without change, even when dropping coc into fees. Ergo, BnB not being the first solution proves that BnB wasn’t run.
ACK 18669d753a15f997f7363dcaf0abf230b851b224
Edit: ACK https://github.com/bitcoin/bitcoin/commit/576bee88fd36e207b7288077626947a1fce0fc33
ACK 18669d7
guessing you meant to ack https://github.com/bitcoin/bitcoin/commit/576bee88fd36e207b7288077626947a1fce0fc33 ? :wink:
ACK 576bee88fd36e207b7288077626947a1fce0fc33
See #28918 (comment). This doesn't seem to have fixed the fuzzer.
See #28918 (comment). This doesn't seem to have fixed the fuzzer.
It fixed the initially reported one (https://github.com/bitcoin/bitcoin/issues/28918#issue-2002147628). The latest one is different.
Milestone
26.1