Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Better logging for token splits #1285

Merged
merged 7 commits into from
May 25, 2022
Merged

Better logging for token splits #1285

Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
7b4b465
Fix collateral test (#1283)
Bushstar May 24, 2022
09f491a
Better logging
prasannavl May 25, 2022
34a0266
Merge branch 'pvl/better_logging' of ssh://github.com/DeFiCh/ain into…
prasannavl May 25, 2022
06effc5
Fix lints
prasannavl May 25, 2022
5125060
Minor improvements
prasannavl May 25, 2022
22af2a0
Merge branch 'master' into pvl/better_logging
prasannavl May 25, 2022
cc6a0f8
Update validation.cpp
prasannavl May 25, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
129 changes: 90 additions & 39 deletions src/validation.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2570,8 +2570,7 @@ bool CChainState::ConnectBlock(const CBlock& block, CValidationState& state, CBl
for (const auto& tx : block.vtx) {
for (size_t o = 0; o < tx->vout.size(); o++) {
if (view.HaveCoin(COutPoint(tx->GetHash(), o))) {
return state.Invalid(ValidationInvalidReason::CONSENSUS, error("ConnectBlock(): tried to overwrite transaction"),
REJECT_INVALID, "bad-txns-BIP30");
return state.Invalid(ValidationInvalidReason::CONSENSUS, error("ConnectBlock(): tried to overwrite transaction"), REJECT_INVALID, "bad-txns-BIP30");
}
}
}
Expand Down Expand Up @@ -2607,7 +2606,6 @@ bool CChainState::ConnectBlock(const CBlock& block, CValidationState& state, CBl
for (unsigned int i = 0; i < block.vtx.size(); i++)
{
const CTransaction &tx = *(block.vtx[i]);

nInputs += tx.vin.size();

if (!tx.IsCoinBase())
Expand Down Expand Up @@ -2769,13 +2767,17 @@ bool CChainState::ConnectBlock(const CBlock& block, CValidationState& state, CBl
CDataStructureV0 splitKey{AttributeTypes::Oracles, OracleIDs::Splits, static_cast<uint32_t>(pindex->nHeight)};
const auto splits = attributes->GetValue(splitKey, OracleSplits{});

auto isSplitsBlock = splits.size() > 0 ? true : false;

CreationTxs creationTxs;
auto counter_n = 1;
for (const auto& [id, multiplier] : splits) {
LogPrintf("Preparing for token split (id=%d, mul=%d, n=%d/%d, height: %d)\n",
id, multiplier, counter_n++, splits.size(), pindex->nHeight);
uint256 tokenCreationTx{};
std::vector<uint256> poolCreationTx;
if (!GetCreationTransactions(block, id, multiplier, tokenCreationTx, poolCreationTx)) {
return state.Invalid(ValidationInvalidReason::CONSENSUS, error("%s: coinbase missing split token creation TX", __func__),
REJECT_INVALID, "bad-cb-token-split");
return state.Invalid(ValidationInvalidReason::CONSENSUS, error("%s: coinbase missing split token creation TX", __func__), REJECT_INVALID, "bad-cb-token-split");
}

std::vector<DCT_ID> poolsToMigrate;
Expand All @@ -2793,15 +2795,23 @@ bool CChainState::ConnectBlock(const CBlock& block, CValidationState& state, CBl
return true;
});

std::stringstream poolIdStr;
for (auto i=0; i < poolsToMigrate.size(); i++) {
if (i != 0) poolIdStr << ", ";
poolIdStr << poolsToMigrate[i].ToString();
}

LogPrintf("Pools to migrate for token %d: (count: %d, ids: %s)\n", id, poolsToMigrate.size(), poolIdStr.str());

if (poolsToMigrate.size() != poolCreationTx.size()) {
return state.Invalid(ValidationInvalidReason::CONSENSUS, error("%s: coinbase missing split pool creation TX", __func__),
REJECT_INVALID, "bad-cb-pool-split");
return state.Invalid(ValidationInvalidReason::CONSENSUS, error("%s: coinbase missing split pool creation TX", __func__), REJECT_INVALID, "bad-cb-pool-split");
}

std::vector<std::pair<DCT_ID, uint256>> poolPairs;
poolPairs.reserve(poolsToMigrate.size());
std::transform(poolsToMigrate.begin(), poolsToMigrate.end(), poolCreationTx.begin(), std::back_inserter(poolPairs),
[](DCT_ID a, uint256 b) { return std::make_pair(a, b); });
std::transform(poolsToMigrate.begin(), poolsToMigrate.end(),
poolCreationTx.begin(), std::back_inserter(poolPairs),
[](DCT_ID a, uint256 b) { return std::make_pair(a, b); });

creationTxs.emplace(id, std::make_pair(tokenCreationTx, poolPairs));
}
Expand Down Expand Up @@ -3069,6 +3079,10 @@ bool CChainState::ConnectBlock(const CBlock& block, CValidationState& state, CBl
}
}

if (isSplitsBlock) {
LogPrintf("Token split block validation time: %.2fms\n", MILLI * (GetTimeMicros() - nTime1));
}

int64_t nTime5 = GetTimeMicros(); nTimeIndex += nTime5 - nTime4;
LogPrint(BCLog::BENCH, " - Index writing: %.2fms [%.2fs (%.2fms/blk)]\n", MILLI * (nTime5 - nTime4), nTimeIndex * MICRO, nTimeIndex * MILLI / nBlocksTotal);

Expand Down Expand Up @@ -3473,6 +3487,9 @@ void CChainState::ProcessFutures(const CBlockIndex* pindex, CCustomCSView& cache
return;
}

auto time = GetTimeMillis();
LogPrintf("Future swap settlement in progress.. (height: %d)\n", pindex->nHeight);

const auto rewardPct = attributes->GetValue(rewardKey, CAmount{});
const auto discount{COIN - rewardPct};
const auto premium{COIN + rewardPct};
Expand Down Expand Up @@ -3540,6 +3557,9 @@ void CChainState::ProcessFutures(const CBlockIndex* pindex, CCustomCSView& cache

auto txn = std::numeric_limits<uint32_t>::max();

auto dUsdToTokenSwapsCounter = 0;
auto tokenTodUsdSwapsCounter = 0;

cache.ForEachFuturesUserValues([&](const CFuturesUserKey& key, const CFuturesUserValue& futuresValues){

CHistoryWriters writers{paccountHistoryDB.get(), nullptr, nullptr};
Expand All @@ -3553,8 +3573,7 @@ void CChainState::ProcessFutures(const CBlockIndex* pindex, CCustomCSView& cache
if (source->symbol == "DUSD") {
const DCT_ID destId{futuresValues.destination};
const auto destToken = view.GetLoanTokenByID(destId);
assert(destToken);

assert(destToken);
try {
const auto& premiumPrice = futuresPrices.at(destId).premium;
if (premiumPrice > 0) {
Expand All @@ -3564,8 +3583,9 @@ void CChainState::ProcessFutures(const CBlockIndex* pindex, CCustomCSView& cache
view.AddBalance(key.owner, destination);
burned.Add(futuresValues.source);
minted.Add(destination);
dUsdToTokenSwapsCounter++;
LogPrint(BCLog::FUTURESWAP, "ProcessFutures(): Owner %s source %s destination %s\n",
key.owner.GetHex(), futuresValues.source.ToString(), destination.ToString());
key.owner.GetHex(), futuresValues.source.ToString(), destination.ToString());
}
} catch (const std::out_of_range&) {
unpaidContracts.emplace(key, futuresValues);
Expand All @@ -3583,8 +3603,9 @@ void CChainState::ProcessFutures(const CBlockIndex* pindex, CCustomCSView& cache
view.AddBalance(key.owner, destination);
burned.Add(futuresValues.source);
minted.Add(destination);
tokenTodUsdSwapsCounter++;
LogPrint(BCLog::FUTURESWAP, "ProcessFutures(): Payment Owner %s source %s destination %s\n",
key.owner.GetHex(), futuresValues.source.ToString(), destination.ToString());
key.owner.GetHex(), futuresValues.source.ToString(), destination.ToString());
} catch (const std::out_of_range&) {
unpaidContracts.emplace(key, futuresValues);
}
Expand All @@ -3602,6 +3623,8 @@ void CChainState::ProcessFutures(const CBlockIndex* pindex, CCustomCSView& cache

auto balances = attributes->GetValue(liveKey, CBalances{});

auto failedContractsCounter = unpaidContracts.size();

// Refund unpaid contracts
for (const auto& [key, value] : unpaidContracts) {

Expand Down Expand Up @@ -3631,6 +3654,11 @@ void CChainState::ProcessFutures(const CBlockIndex* pindex, CCustomCSView& cache
attributes->SetValue(liveKey, std::move(balances));
}

LogPrintf("Future swap settlement completed: (%d DUSD->Token swaps," /* Continued */
" %d Token->DUSD swaps, %d refunds (height: %d, time: %d)\n",
dUsdToTokenSwapsCounter, tokenTodUsdSwapsCounter, failedContractsCounter,
pindex->nHeight, GetTimeMillis() - time);

cache.SetVariable(*attributes);
}

Expand Down Expand Up @@ -3689,6 +3717,9 @@ void CChainState::ProcessTokenToGovVar(const CBlockIndex* pindex, CCustomCSView&
return;
}

auto time = GetTimeMillis();
LogPrintf("Token attributes migration in progress.. (height: %d)\n", pindex->nHeight);

std::map<DCT_ID, CLoanSetLoanToken> loanTokens;
std::vector<CLoanSetCollateralTokenImplementation> collateralTokens;

Expand Down Expand Up @@ -3742,7 +3773,10 @@ void CChainState::ProcessTokenToGovVar(const CBlockIndex* pindex, CCustomCSView&
}
}

LogPrintf("Migrated %d loan tokens and %d collateral tokens (height: %d)\n", loanCount, collateralCount, pindex->nHeight);
LogPrintf("Token attributes migration complete: " /* Continued */
"(%d loan tokens, %d collateral tokens, height: %d, time: %dms)\n",
loanCount, collateralCount, pindex->nHeight, GetTimeMillis() - time);

} catch(std::out_of_range&) {
LogPrintf("Non-existant map entry referenced in loan/collateral token to Gov var migration\n");
}
Expand Down Expand Up @@ -3804,6 +3838,10 @@ static inline T CalculateNewAmount(const int multiplier, const T amount) {
static Res PoolSplits(CCustomCSView& view, CAmount& totalBalance, ATTRIBUTES& attributes, const DCT_ID oldTokenId, const DCT_ID newTokenId,
const CBlockIndex* pindex, const CreationTxs& creationTxs, const int32_t multiplier) {

auto time = GetTimeMillis();
LogPrintf("Pool migration in progress.. (token %d -> %d, height: %d)\n",
oldTokenId.v, newTokenId.v, pindex->nHeight);

try {
assert(creationTxs.count(oldTokenId.v));
for (const auto& [oldPoolId, creationTx] : creationTxs.at(oldTokenId.v).second) {
Expand Down Expand Up @@ -3856,8 +3894,9 @@ static Res PoolSplits(CCustomCSView& view, CAmount& totalBalance, ATTRIBUTES& at
throw std::runtime_error(strprintf("Failed to get related pool: %d", oldPoolId.v));
}

LogPrintf("Old pool pair (a: %d / b: %d), reserve (a: %d, b: %d), liquidity: %d\n",
oldPoolPair->idTokenA.v, oldPoolPair->idTokenB.v, oldPoolPair->reserveA, oldPoolPair->reserveB, oldPoolPair->totalLiquidity);
LogPrintf("Pool migration: Old pair (id: %d, token a: %d, b: %d, reserve a: %d, b: %d, liquidity: %d)\n",
oldPoolId.v, oldPoolPair->idTokenA.v, oldPoolPair->idTokenB.v,
oldPoolPair->reserveA, oldPoolPair->reserveB, oldPoolPair->totalLiquidity);

CPoolPair newPoolPair{*oldPoolPair};
if (oldPoolPair->idTokenA == oldTokenId) {
Expand All @@ -3884,15 +3923,14 @@ static Res PoolSplits(CCustomCSView& view, CAmount& totalBalance, ATTRIBUTES& at
return true;
});

LogPrintf("Migrating %d balances from old pool\n", balancesToMigrate.size());
LogPrintf("Pool migration: Migrating %d balances.. \n", balancesToMigrate.size());

// Largest first to make sure we are over MINIMUM_LIQUIDITY on first call to AddLiquidity
std::sort(balancesToMigrate.begin(), balancesToMigrate.end(), [](const std::pair<CScript, CAmount>&a, const std::pair<CScript, CAmount>& b){
return a.second > b.second;
});

for (auto& [owner, amount] : balancesToMigrate) {

if (oldPoolPair->totalLiquidity < CPoolPair::MINIMUM_LIQUIDITY) {
throw std::runtime_error("totalLiquidity less than minimum.");
}
Expand Down Expand Up @@ -3993,8 +4031,10 @@ static Res PoolSplits(CCustomCSView& view, CAmount& totalBalance, ATTRIBUTES& at
throw std::runtime_error(strprintf("totalLiquidity should be zero. Remainder: %d", oldPoolPair->totalLiquidity));
}

LogPrintf("New pool pair (a: %d / b: %d), reserve (a: %d, b: %d), liquidity: %d\n",
newPoolPair.idTokenA.v, newPoolPair.idTokenB.v, newPoolPair.reserveA, newPoolPair.reserveB, newPoolPair.totalLiquidity);
LogPrintf("Pool migration: New pair (id: %d, token a: %d, b: %d, reserve a: %d, b: %d, liquidity: %d)\n",
newPoolId.v,
newPoolPair.idTokenA.v, newPoolPair.idTokenB.v,
newPoolPair.reserveA, newPoolPair.reserveB, newPoolPair.totalLiquidity);

res = view.SetPoolPair(newPoolId, pindex->nHeight, newPoolPair);
if (!res) {
Expand Down Expand Up @@ -4033,16 +4073,20 @@ static Res PoolSplits(CCustomCSView& view, CAmount& totalBalance, ATTRIBUTES& at
if (!res) {
throw std::runtime_error(res.msg);
}
LogPrintf("Pool migration complete: (%d -> %d, height: %d, time: %dms)\n",
oldPoolId.v, newPoolId.v, pindex->nHeight, GetTimeMillis() - time);
}

} catch (const std::runtime_error& e) {
return Res::Err(e.what());
}

return Res::Ok();
}

static Res VaultSplits(CCustomCSView& view, ATTRIBUTES& attributes, const DCT_ID oldTokenId, const DCT_ID newTokenId, const int height, const int multiplier) {

auto time = GetTimeMillis();
LogPrintf("Vaults rebalance in progress.. (token %d -> %d, height: %d)\n",
oldTokenId.v, newTokenId.v, height);
std::vector<std::pair<CVaultId, CAmount>> loanTokenAmounts;
view.ForEachLoanTokenAmount([&](const CVaultId& vaultId, const CBalances& balances){
for (const auto& [tokenId, amount] : balances.balances) {
Expand Down Expand Up @@ -4126,6 +4170,9 @@ static Res VaultSplits(CCustomCSView& view, ATTRIBUTES& attributes, const DCT_ID
view.WriteInterestRate(std::make_pair(vaultId, newTokenId), rate, rate.height);
}

LogPrintf("Vaults rebalance completed: (token %d -> %d, height: %d, time: %dms)\n",
oldTokenId.v, newTokenId.v, height, GetTimeMillis() - time);

return Res::Ok();
}

Expand All @@ -4147,9 +4194,11 @@ void CChainState::ProcessTokenSplits(const CBlock& block, const CBlockIndex* pin
}

for (const auto& [id, multiplier] : splits) {

auto time = GetTimeMillis();
LogPrintf("Token split in progress.. (id: %d, mul: %d, height: %d)\n", id, multiplier, pindex->nHeight);

if (!cache.AreTokensLocked({id})) {
LogPrintf("%s: Token split failed. Token %d not locked\n", __func__, id);
LogPrintf("Token split failed. No locks.\n");
continue;
}

Expand All @@ -4159,14 +4208,14 @@ void CChainState::ProcessTokenSplits(const CBlock& block, const CBlockIndex* pin

auto token = view.GetToken(oldTokenId);
if (!token) {
LogPrintf("%s: Token split failed. Token %d not found\n", __func__, oldTokenId.v);
LogPrintf("Token split failed. Token %d not found\n", oldTokenId.v);
continue;
}

std::string newTokenSuffix = "/v";
auto res = GetTokenSuffix(cache, *attributes, oldTokenId.v, newTokenSuffix);
if (!res) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Token split failed on GetTokenSuffix %s\n", res.msg);
continue;
}

Expand All @@ -4184,24 +4233,24 @@ void CChainState::ProcessTokenSplits(const CBlock& block, const CBlockIndex* pin

res = view.SubMintedTokens(oldTokenId, token->minted);
if (!res) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Token split failed on SubMintedTokens %s\n", res.msg);
continue;
}

res = view.UpdateToken(*token, false, true);
if (!res) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Token split failed on UpdateToken %s\n", res.msg);
continue;
}

auto resVal = view.CreateToken(newToken);
if (!resVal) {
LogPrintf("%s: Token split failed. %s\n", __func__, resVal.msg);
LogPrintf("Token split failed on CreateToken %s\n", resVal.msg);
continue;
}

const DCT_ID newTokenId{resVal.val->v};
LogPrintf("Token split %d (symbol: %s, old token id: %d, new token id: %d)\n", id, token->symbol, oldTokenId.v, newTokenId.v);
LogPrintf("Token split info: (symbol: %s, id: %d -> %d)\n", newToken.symbol, oldTokenId.v, newTokenId.v);

std::vector<CDataStructureV0> eraseKeys;
for (const auto& [key, value] : attributes->GetAttributesMap()) {
Expand Down Expand Up @@ -4236,13 +4285,14 @@ void CChainState::ProcessTokenSplits(const CBlock& block, const CBlockIndex* pin

res = PoolSplits(view, totalBalance, *attributes, oldTokenId, newTokenId, pindex, creationTxs, multiplier);
if (!res) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Pool splits failed %s\n", res.msg);
continue;
}

CAccounts addAccounts;
CAccounts subAccounts;


view.ForEachBalance([&, multiplier = multiplier](CScript const& owner, const CTokenAmount& balance) {
if (oldTokenId.v == balance.nTokenId.v) {
const auto newBalance = CalculateNewAmount(multiplier, balance.nValue);
Expand All @@ -4253,11 +4303,13 @@ void CChainState::ProcessTokenSplits(const CBlock& block, const CBlockIndex* pin
return true;
});

LogPrintf("Token split %d (symbol: %s, add: %d, sub: %d, balance: %d)\n",
id, token->symbol, addAccounts.size(), subAccounts.size(), totalBalance);
LogPrintf("Token split info: Rebalance " /* Continued */
"(id: %d, symbol: %s, add: %d, sub: %d, total: %d)\n",
id, newToken.symbol, addAccounts.size(), subAccounts.size(), totalBalance);

res = view.AddMintedTokens(newTokenId, totalBalance);
if (!res) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Token split failed on AddMintedTokens %s\n", res.msg);
continue;
}

Expand All @@ -4275,22 +4327,21 @@ void CChainState::ProcessTokenSplits(const CBlock& block, const CBlockIndex* pin
throw std::runtime_error(res.msg);
}
}

} catch (const std::runtime_error& e) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Token split failed. %s\n", res.msg);
continue;
}

if (view.GetLoanTokenByID(oldTokenId)) {
res = VaultSplits(view, *attributes, oldTokenId, newTokenId, pindex->nHeight, multiplier);
if (!res) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Vault splits failed: %s\n", res.msg);
continue;
}
} else {
auto res = attributes->Apply(view, pindex->nHeight);
if (!res) {
LogPrintf("%s: Token split failed. %s\n", __func__, res.msg);
LogPrintf("Token split failed on Apply: %s\n", res.msg);
continue;
}
}
Expand Down Expand Up @@ -4319,9 +4370,9 @@ void CChainState::ProcessTokenSplits(const CBlock& block, const CBlockIndex* pin
attributes->SetValue(key, value);
}
}

view.SetVariable(*attributes);
view.Flush();
LogPrintf("Token split completed: (id: %d, mul: %d, time: %dms)\n", id, multiplier, GetTimeMillis() - time);
}
}

Expand Down