Skip to content

Commit

Permalink
More accurate logs
Browse files Browse the repository at this point in the history
  • Loading branch information
@0ersted @qdddddd
0ersted authored and qdddddd committed Oct 25, 2019
1 parent 83dc3fb commit d1117cb
Show file tree
Hide file tree
Showing 4 changed files with 32 additions and 29 deletions.
20 changes: 12 additions & 8 deletions src/consensus/chain.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -153,7 +153,7 @@ std::vector<ConstBlockPtr> Chain::GetSortedSubgraph(const ConstBlockPtr& pblock)
}

result.shrink_to_fit();
spdlog::debug("{} blocks sorted, {} pending blocks left. Total ratio: {}", result.size(), pendingBlocks_.size(),
spdlog::debug("[Validation] {} blocks sorted, {} pending blocks left. Total ratio: {}", result.size(), pendingBlocks_.size(),
static_cast<double>(result.size()) / (result.size() + pendingBlocks_.size()));
return result;
}
Expand Down Expand Up @@ -229,7 +229,7 @@ void Chain::CheckTxPartition(Vertex& b, float ms_hashrate) {
VertexPtr Chain::Verify(const ConstBlockPtr& pblock) {
auto height = GetChainHead()->height + 1;

spdlog::debug("Verifying milestone block {} at height {}", pblock->GetHash().to_substr(), height);
spdlog::debug("[Validation] Validating level set of ms {} at height {}", pblock->GetHash().to_substr(), height);

// get a path for validation by the post ordered DFS search
std::vector<ConstBlockPtr> blocksToValidate = GetSortedSubgraph(pblock);
Expand Down Expand Up @@ -284,6 +284,9 @@ VertexPtr Chain::Verify(const ConstBlockPtr& pblock) {
}

CreateNextMilestone(GetChainHead(), *vtcs.back(), std::move(wvtcs), std::move(regChange), std::move(txoc));
const auto& ms = vtcs.back()->snapshot;
spdlog::debug("[Validate] New milestone {} has milestone difficulty target in compact form {} as difficulty {}",
vtcs.back()->cblock->GetHash().to_substr(), ms->milestoneTarget.GetCompact(), ms->GetMsDifficulty());
vtcs.back()->UpdateMilestoneReward();

recentHistory_.merge(std::move(verifying_));
Expand All @@ -297,7 +300,7 @@ std::pair<TXOC, TXOC> Chain::Validate(Vertex& vertex, RegChange& regChange) {

// update miner chain height
vertex.minerChainHeight = GetVertex(prevHash)->minerChainHeight + 1;
spdlog::trace("Validating {} at its miner chain {}", blkHash.to_substr(), vertex.minerChainHeight);
spdlog::trace("[Validate] Validating {} at its miner chain {}", blkHash.to_substr(), vertex.minerChainHeight);

// update the key of the prev redemption hashes
uint256 oldRedempHash;
Expand All @@ -307,7 +310,7 @@ std::pair<TXOC, TXOC> Chain::Validate(Vertex& vertex, RegChange& regChange) {
oldRedempHash = STORE->GetPrevRedemHash(prevHash);

if (oldRedempHash.IsNull()) {
spdlog::warn("Peer chain forks here [{}]", std::to_string(blkHash));
spdlog::warn("[Validate] Peer chain forks here [{}]", std::to_string(blkHash));
auto b = GetVertex(prevHash);
while (!b->cblock->IsRegistration() || b->validity[0] != Vertex::VALID) {
b = GetVertex(b->cblock->GetPrevHash());
Expand Down Expand Up @@ -348,7 +351,7 @@ std::pair<TXOC, TXOC> Chain::Validate(Vertex& vertex, RegChange& regChange) {
// invalidate transactions that still have validity == UNKNOWN
const auto& txns = vertex.cblock->GetTransactions();
for (size_t i = 0; i < txns.size(); ++i) {
if (!vertex.validity[i]) { // if UNKNOWN
if (vertex.validity[i] == Vertex::Validity::UNKNOWN) {
vertex.validity[i] = Vertex::Validity::INVALID;
invalidTXOC.Merge(CreateTXOCFromInvalid(*txns[i], i));
}
Expand All @@ -373,7 +376,7 @@ uint256 Chain::GetPrevRedempHash(const uint256& h) const {
std::optional<TXOC> Chain::ValidateRedemption(Vertex& vertex, RegChange& regChange) {
const auto& blkHash = vertex.cblock->GetHash();
const auto hashstr = std::to_string(blkHash);
spdlog::trace("Validating redemption {}", blkHash.to_substr());
spdlog::trace("[Validate] Validating redemption in block {}", blkHash.to_substr());

uint256 prevRedempHash = GetPrevRedempHash(blkHash);
auto prevReg = GetVertex(prevRedempHash);
Expand Down Expand Up @@ -422,6 +425,7 @@ std::optional<TXOC> Chain::ValidateRedemption(Vertex& vertex, RegChange& regChan

bool Chain::ValidateTx(const Transaction& tx, uint32_t index, TXOC& txoc, Coin& fee) {
const auto& blkHash = tx.GetParentBlock()->GetHash();
spdlog::trace("[Validate] Validating Transactions in block {}", blkHash.to_substr());

Coin valueIn{};
Coin valueOut{};
Expand Down Expand Up @@ -483,13 +487,13 @@ bool Chain::ValidateTx(const Transaction& tx, uint32_t index, TXOC& txoc, Coin&

TXOC Chain::ValidateTxns(Vertex& vertex) {
const auto& blkHash = vertex.cblock->GetHash();
spdlog::trace("Validating transactions in block {}", blkHash.to_substr());
spdlog::trace("[Validation] Validating transactions in block {}", blkHash.to_substr());

TXOC validTXOC{};

const auto& txns = vertex.cblock->GetTransactions();
for (size_t i = 0; i < txns.size(); ++i) {
if (vertex.validity[i]) { // if not UNKNWON
if (vertex.validity[i] != Vertex::Validity::UNKNOWN) {
// Skipping, because this txn is either redemption
// or has been marked invalid by CheckTxPartition
continue;
Expand Down
26 changes: 15 additions & 11 deletions src/consensus/dag_manager.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -260,6 +260,7 @@ void DAGManager::EnableOBC() {
//
void DAGManager::AddNewBlock(ConstBlockPtr blk, PeerPtr peer) {
verifyThread_.Execute([=, blk = std::move(blk), peer = std::move(peer)]() mutable {
spdlog::trace("[Verify Thread] Adding blocks to pending {}", blk->GetHash().to_substr());
if (*blk == *GENESIS) {
spdlog::trace("Adding new block aborted: genesis");
return;
Expand Down Expand Up @@ -343,6 +344,7 @@ void DAGManager::AddNewBlock(ConstBlockPtr blk, PeerPtr peer) {

AddBlockToPending(blk);
STORE->ReleaseBlocks(blk->GetHash());
spdlog::trace("[Verify Thread] End of adding block to pending {}", blk->GetHash().to_substr());
});
}

Expand Down Expand Up @@ -371,8 +373,6 @@ bool DAGManager::CheckPuntuality(const ConstBlockPtr& blk, const VertexPtr& ms)
}

void DAGManager::AddBlockToPending(const ConstBlockPtr& block) {
spdlog::trace("AddBlockToPending {}", block->GetHash().to_substr());

// Extract utxos from outputs and pass their pointers to chains
std::vector<UTXOPtr> utxos;
const auto& txns = block->GetTransactions();
Expand Down Expand Up @@ -405,15 +405,16 @@ void DAGManager::AddBlockToPending(const ConstBlockPtr& block) {
if (CheckMsPOW(block, ms)) {
if (*msBlock->cblock == *GetMilestoneHead()->cblock) {
// new milestone on mainchain
spdlog::debug("Updating main chain MS block {} pre MS {}", block->GetHash().to_substr(),
spdlog::debug("[Verify Thread] Updating main chain MS block {} pre MS {}", block->GetHash().to_substr(),
block->GetMilestoneHash().to_substr());
ProcessMilestone(mainchain, block);
EnableOBC();
DeleteFork();
FlushTrigger();
} else {
// new fork
spdlog::debug("A fork created which points to MS block {} pre main chain MS {} total chains {}",
spdlog::debug("[Verify Thread] A fork created which points to MS block {} pre main chain MS {} --- "
"total chains {}",
block->GetHash().to_substr(), block->GetMilestoneHash().to_substr(),
milestoneChains.size());
auto new_fork = std::make_unique<Chain>(*milestoneChains.best(), block);
Expand Down Expand Up @@ -443,17 +444,18 @@ void DAGManager::AddBlockToPending(const ConstBlockPtr& block) {
if (CheckMsPOW(block, ms)) {
if (msBlock->cblock->GetHash() == chain->GetChainHead()->GetMilestoneHash()) {
// new milestone on fork
spdlog::debug("A fork grows MS block {} pre MS {}", block->GetHash().to_substr(),
spdlog::debug("[Verify Thread] A fork grows MS block {} pre MS {}", block->GetHash().to_substr(),
block->GetMilestoneHash().to_substr());
ProcessMilestone(*chainIt, block);
if (milestoneChains.update_best(chainIt)) {
spdlog::debug("Switched to the best chain: head = {}",
spdlog::debug("[Verify Thread] Switched to the best chain: head = {}",
milestoneChains.best()->GetChainHead()->GetMilestoneHash().to_substr());
}
return;
} else {
// new fork
spdlog::debug("A fork created which points to MS block {} pre forked chain MS {} total chains {}",
spdlog::debug("[Verify Thread] A fork created which points to MS block {} pre forked chain MS {} --- "
"total chains {}",
block->GetHash().to_substr(), block->GetMilestoneHash().to_substr(),
milestoneChains.size());
auto new_fork = std::make_unique<Chain>(*chain, block);
Expand All @@ -471,7 +473,7 @@ void DAGManager::ProcessMilestone(const ChainPtr& chain, const ConstBlockPtr& bl
chain->AddNewState(*newMs);

if (EraseDownloading(block->GetHash())) {
spdlog::debug("Size of downloading = {}, removed successfully", downloading.size());
spdlog::debug("[Verify Thread] Size of downloading = {}, removed successfully", downloading.size());
}
}

Expand All @@ -494,8 +496,8 @@ void DAGManager::DeleteFork() {
}
globalStates_.erase((*it)->GetMilestoneHash());
}
spdlog::info("Deleting fork with chain head {}",
(*chain_it)->GetChainHead()->GetMilestoneHash().to_substr());
spdlog::info("[Verify Thread] Deleting fork with chain head {} --- total chains {}",
(*chain_it)->GetChainHead()->GetMilestoneHash().to_substr(), milestoneChains.size());
chain_it = milestoneChains.erase(chain_it);
} else {
chain_it++;
Expand Down Expand Up @@ -582,7 +584,7 @@ void DAGManager::FlushToSTORE(MilestonePtr ms) {
auto [vtxToStore, utxoToStore, utxoToRemove] = milestoneChains.best()->GetDataToSTORE(ms);
ms->stored = true;

spdlog::debug("Flushing at height {}", ms->height);
spdlog::debug("[Verify Thread] Flushing {} at height {}", ms->GetMilestoneHash().to_substr(), ms->height);

storagePool_.Execute([=, vtxToStore = std::move(vtxToStore), utxoToStore = std::move(utxoToStore),
utxoToRemove = std::move(utxoToRemove)]() mutable {
Expand Down Expand Up @@ -631,11 +633,13 @@ void DAGManager::FlushToSTORE(MilestonePtr ms) {

verifyThread_.Execute([=, msHash = ms.cblock->GetHash(), vtxHashes = std::move(vtxHashes),
txocToRemove = std::move(txocToRemove)]() {
spdlog::trace("[Verify Thread] Removing level set {} cache", msHash.to_substr());
globalStates_.erase(msHash);
for (auto& chain : milestoneChains) {
chain->PopOldest(vtxHashes, txocToRemove);
}
});
spdlog::trace("[Storage Pool] End of flushing {}", ms.cblock->GetHash().to_substr());
});
}

Expand Down
9 changes: 2 additions & 7 deletions src/messages/block.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -149,22 +149,20 @@ void Block::UnCache() {
}

bool Block::Verify() const {
spdlog::trace("[Syntax] Syntactically checking block {}", hash_.to_substr());
// check version
spdlog::trace("Block::Verify version {}", hash_.to_substr());
if (header_.version != GetParams().version) {
spdlog::info("[Syntax] Wrong version {} v.s. expected {} [{}]", header_.version, GetParams().version,
std::to_string(hash_));
return false;
}

// check pow
spdlog::trace("Block::Verify pow {}", hash_.to_substr());
if (!CheckPOW()) {
return false;
}

// check merkle
spdlog::trace("Block::Verify merkle {}", hash_.to_substr());
bool mutated;
auto root = ComputeMerkleRoot(&mutated);
if (mutated) {
Expand All @@ -177,7 +175,6 @@ bool Block::Verify() const {
}

// check if the timestamp is too far in the future
spdlog::trace("Block::Verify allowed time {}", hash_.to_substr());
time_t allowedTime = std::time(nullptr) + ALLOWED_TIME_DRIFT;
if (header_.timestamp > allowedTime) {
time_t t = header_.timestamp;
Expand All @@ -188,14 +185,12 @@ bool Block::Verify() const {
}

// verify content of the block
spdlog::trace("Block::Verify number of txns {}", hash_.to_substr());
if (transactions_.size() > GetParams().blockCapacity) {
spdlog::info("[Syntax] The number of transactions ({}) greater than the block capacity ({}) [{}]",
transactions_.size(), GetParams().blockCapacity, std::to_string(hash_));
return false;
}

spdlog::trace("Block::Verify content {}", hash_.to_substr());
if (GetOptimalEncodingSize() > MAX_BLOCK_SIZE) {
spdlog::info("[Syntax] Size {} larger than the maximum allowed size ({} bytes) [{}]", optimalEncodingSize_,
MAX_BLOCK_SIZE, std::to_string(hash_));
Expand All @@ -218,7 +213,6 @@ bool Block::Verify() const {
}

// check the conditions of the first registration block
spdlog::trace("Block::Verify first reg {}", hash_.to_substr());
if (header_.prevBlockHash == GENESIS->GetHash()) {
// Must contain a tx
if (!HasTransaction()) {
Expand All @@ -233,6 +227,7 @@ bool Block::Verify() const {
}
}

spdlog::trace("[Syntax] End of syntactical checking on {}", hash_.to_substr());
return true;
}

Expand Down
6 changes: 3 additions & 3 deletions src/storage/block_store.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ BlockStore::BlockStore(const std::string& dbPath) : obcThread_(1), obcEnabled_(f
obcThread_.Execute([this]() {
auto n = obc_.Prune(3600);
if (n) {
spdlog::info("Erased {} outdated entries from OBC.", n);
spdlog::info("[OBC] Erased {} outdated entries from OBC.", n);
}
});
});
Expand All @@ -26,7 +26,7 @@ BlockStore::BlockStore(const std::string& dbPath) : obcThread_(1), obcEnabled_(f

void BlockStore::AddBlockToOBC(ConstBlockPtr&& blk, const uint8_t& mask) {
obcThread_.Execute([blk = std::move(blk), mask, this]() mutable {
spdlog::trace("AddBlockToOBC {}", blk->GetHash().to_substr());
spdlog::trace("[OBC] AddBlockToOBC {}", blk->GetHash().to_substr());
if (!obcEnabled_.load()) {
return;
}
Expand Down Expand Up @@ -363,7 +363,7 @@ bool BlockStore::StoreLevelSet(const std::vector<VertexWPtr>& lvs) {
SaveHeadHeight(height);
SaveBestChainWork(ArithToUint256(ms.snapshot->chainwork));

spdlog::trace("Storing LVS with MS hash {} of height {} with current file pos {}", ms.height, height,
spdlog::trace("[STORE] Storing LVS with MS hash {} of height {} with current file pos {}", ms.height, height,
std::to_string(*dbStore_.GetMsBlockPos(height)));
} catch (const std::exception&) {
return false;
Expand Down

0 comments on commit d1117cb

Please sign in to comment.