diff --git a/domain/consensus/processes/consensusstatemanager/add_block_to_virtual.go b/domain/consensus/processes/consensusstatemanager/add_block_to_virtual.go index b55d04f3e..6eca25669 100644 --- a/domain/consensus/processes/consensusstatemanager/add_block_to_virtual.go +++ b/domain/consensus/processes/consensusstatemanager/add_block_to_virtual.go @@ -9,33 +9,53 @@ import ( // current virtual. This process may result in a new virtual block // getting created func (csm *consensusStateManager) AddBlockToVirtual(blockHash *externalapi.DomainHash) error { + log.Tracef("AddBlockToVirtual start for block %s", blockHash) + defer log.Tracef("AddBlockToVirtual end for block %s", blockHash) + + log.Tracef("Resolving whether the block %s is the next virtual selected parent", blockHash) isNextVirtualSelectedParent, err := csm.isNextVirtualSelectedParent(blockHash) if err != nil { return err } if isNextVirtualSelectedParent { + log.Tracef("Block %s is the new virtual. Resolving its block status", blockHash) blockStatus, err := csm.resolveBlockStatus(blockHash) if err != nil { return err } if blockStatus == externalapi.StatusValid { + log.Tracef("Block %s is tentatively valid. Resolving whether it violates finality", blockHash) err = csm.checkFinalityViolation(blockHash) if err != nil { return err } + + // Re-fetch the block status for logging purposes + // because it could've been changed in + // checkFinalityViolation + blockStatus, err = csm.blockStatusStore.Get(csm.databaseContext, blockHash) + if err != nil { + return err + } } + + log.Debugf("Block %s is the next virtual selected parent. "+ + "Its resolved status is `%s`", blockHash, blockStatus) } else { - log.Debugf("Block %s is not next virtual selected parent. Therefore leaving him with status `%s`", - blockHash, externalapi.StatusUTXOPendingVerification) + log.Debugf("Block %s is not the next virtual selected parent, "+ + "therefore its status remains `%s`", blockHash, externalapi.StatusUTXOPendingVerification) } + log.Tracef("Adding block %s to the DAG tips", blockHash) newTips, err := csm.addTip(blockHash) if err != nil { return err } + log.Tracef("After adding %s, the new tips are %s", blockHash, newTips) + log.Tracef("Updating the virtual with the new tips") err = csm.updateVirtual(blockHash, newTips) if err != nil { return err @@ -45,7 +65,12 @@ func (csm *consensusStateManager) AddBlockToVirtual(blockHash *externalapi.Domai } func (csm *consensusStateManager) isNextVirtualSelectedParent(blockHash *externalapi.DomainHash) (bool, error) { + log.Tracef("isNextVirtualSelectedParent start for block %s", blockHash) + defer log.Tracef("isNextVirtualSelectedParent end for block %s", blockHash) + if *blockHash == *csm.genesisHash { + log.Tracef("Block %s is the genesis block, therefore it is "+ + "the selected parent by definition", blockHash) return true, nil } @@ -54,30 +79,43 @@ func (csm *consensusStateManager) isNextVirtualSelectedParent(blockHash *externa return false, err } + log.Tracef("Selecting the next selected parent between "+ + "the block %s the current selected parent %s", blockHash, virtualGhostdagData.SelectedParent) nextVirtualSelectedParent, err := csm.ghostdagManager.ChooseSelectedParent(virtualGhostdagData.SelectedParent, blockHash) if err != nil { return false, err } + log.Tracef("The next selected parent is: %s", nextVirtualSelectedParent) return *blockHash == *nextVirtualSelectedParent, nil } func (csm *consensusStateManager) addTip(newTipHash *externalapi.DomainHash) (newTips []*externalapi.DomainHash, err error) { + log.Tracef("addTip start for new tip %s", newTipHash) + defer log.Tracef("addTip end for new tip %s", newTipHash) + + log.Tracef("Calculating the new tips for new tip %s", newTipHash) newTips, err = csm.calculateNewTips(newTipHash) if err != nil { return nil, err } + log.Tracef("The new tips are: %s", newTips) err = csm.consensusStateStore.StageTips(newTips) if err != nil { return nil, err } + log.Tracef("Staged the new tips %s", newTips) return newTips, nil } func (csm *consensusStateManager) calculateNewTips(newTipHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) { + log.Tracef("calculateNewTips start for new tip %s", newTipHash) + defer log.Tracef("calculateNewTips end for new tip %s", newTipHash) + if *newTipHash == *csm.genesisHash { + log.Tracef("The new tip is the genesis block, therefore it is the only tip by definition") return []*externalapi.DomainHash{newTipHash}, nil } @@ -85,11 +123,13 @@ func (csm *consensusStateManager) calculateNewTips(newTipHash *externalapi.Domai if err != nil { return nil, err } + log.Tracef("The current tips are: %s", currentTips) newTipParents, err := csm.dagTopologyManager.Parents(newTipHash) if err != nil { return nil, err } + log.Tracef("The parents of the new tip are: %s", newTipParents) newTips := []*externalapi.DomainHash{newTipHash} @@ -105,6 +145,7 @@ func (csm *consensusStateManager) calculateNewTips(newTipHash *externalapi.Domai newTips = append(newTips, currentTip) } } + log.Tracef("The calculated new tips are: %s", newTips) return newTips, nil } diff --git a/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go b/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go index 417468732..c2e2ffdba 100644 --- a/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go +++ b/domain/consensus/processes/consensusstatemanager/calculate_past_utxo.go @@ -1,6 +1,7 @@ package consensusstatemanager import ( + "github.com/kaspanet/kaspad/domain/consensus/utils/consensusserialization" "github.com/kaspanet/kaspad/domain/consensus/utils/constants" "github.com/kaspanet/kaspad/domain/consensus/utils/multiset" "github.com/pkg/errors" @@ -15,8 +16,12 @@ import ( func (csm *consensusStateManager) CalculatePastUTXOAndAcceptanceData(blockHash *externalapi.DomainHash) ( *model.UTXODiff, model.AcceptanceData, model.Multiset, error) { - // The genesis block has an empty UTXO diff, empty acceptance data, and a blank multiset + log.Tracef("CalculatePastUTXOAndAcceptanceData start for block %s", blockHash) + defer log.Tracef("CalculatePastUTXOAndAcceptanceData end for block %s", blockHash) + if *blockHash == *csm.genesisHash { + log.Tracef("Block %s is the genesis. By definition, "+ + "it has an empty UTXO diff, empty acceptance data, and a blank multiset", blockHash) return &model.UTXODiff{}, model.AcceptanceData{}, multiset.New(), nil } @@ -24,40 +29,56 @@ func (csm *consensusStateManager) CalculatePastUTXOAndAcceptanceData(blockHash * if err != nil { return nil, nil, nil, err } + + log.Tracef("Restoring the past UTXO of block %s with selectedParent %s", + blockHash, blockGHOSTDAGData.SelectedParent) selectedParentPastUTXO, err := csm.restorePastUTXO(blockGHOSTDAGData.SelectedParent) if err != nil { return nil, nil, nil, err } + + log.Tracef("Applying blue blocks to the selected parent past UTXO of block %s", blockHash) acceptanceData, utxoDiff, err := csm.applyBlueBlocks(blockHash, selectedParentPastUTXO, blockGHOSTDAGData) if err != nil { return nil, nil, nil, err } + + log.Tracef("Calculating the multiset of %s", blockHash) multiset, err := csm.calculateMultiset(acceptanceData, blockGHOSTDAGData) if err != nil { return nil, nil, nil, err } + log.Tracef("The multiset of block %s resolved to: %s", blockHash, multiset.Hash()) return utxoDiff, acceptanceData, multiset, nil } func (csm *consensusStateManager) restorePastUTXO(blockHash *externalapi.DomainHash) (*model.UTXODiff, error) { + log.Tracef("restorePastUTXO start for block %s", blockHash) + defer log.Tracef("restorePastUTXO end for block %s", blockHash) + var err error - // collect the UTXO diffs + log.Tracef("Collecting UTXO diffs for block %s", blockHash) var utxoDiffs []*model.UTXODiff nextBlockHash := blockHash for { + log.Tracef("Collecting UTXO diff for block %s", nextBlockHash) utxoDiff, err := csm.utxoDiffStore.UTXODiff(csm.databaseContext, nextBlockHash) if err != nil { return nil, err } utxoDiffs = append(utxoDiffs, utxoDiff) + log.Tracef("Collected UTXO diff for block %s: %s", nextBlockHash, utxoDiff) exists, err := csm.utxoDiffStore.HasUTXODiffChild(csm.databaseContext, nextBlockHash) if err != nil { return nil, err } if !exists { + log.Tracef("Block %s does not have a UTXO diff child, "+ + "meaning we reached the virtual. Returning the collected "+ + "UTXO diffs: %s", nextBlockHash, utxoDiffs) break } @@ -66,11 +87,15 @@ func (csm *consensusStateManager) restorePastUTXO(blockHash *externalapi.DomainH return nil, err } if nextBlockHash == nil { + log.Tracef("Block %s does not have a UTXO diff child, "+ + "meaning we reached the virtual. Returning the collected "+ + "UTXO diffs: %s", nextBlockHash, utxoDiffs) break } } // apply the diffs in reverse order + log.Tracef("Applying the collected UTXO diffs for block %s in reverse order", blockHash) accumulatedDiff := model.NewUTXODiff() for i := len(utxoDiffs) - 1; i >= 0; i-- { accumulatedDiff, err = utxoalgebra.WithDiff(accumulatedDiff, utxoDiffs[i]) @@ -78,6 +103,7 @@ func (csm *consensusStateManager) restorePastUTXO(blockHash *externalapi.DomainH return nil, err } } + log.Tracef("The accumulated diff for block %s is: %s", blockHash, accumulatedDiff) return accumulatedDiff, nil } @@ -86,6 +112,9 @@ func (csm *consensusStateManager) applyBlueBlocks(blockHash *externalapi.DomainH selectedParentPastUTXODiff *model.UTXODiff, ghostdagData *model.BlockGHOSTDAGData) ( model.AcceptanceData, *model.UTXODiff, error) { + log.Tracef("applyBlueBlocks start for block %s", blockHash) + defer log.Tracef("applyBlueBlocks end for block %s", blockHash) + blueBlocks, err := csm.blockStore.Blocks(csm.databaseContext, ghostdagData.MergeSetBlues) if err != nil { return nil, nil, err @@ -95,30 +124,39 @@ func (csm *consensusStateManager) applyBlueBlocks(blockHash *externalapi.DomainH if err != nil { return nil, nil, err } + log.Tracef("The past median time for block %s is: %d", blockHash, selectedParentMedianTime) multiblockAcceptanceData := make(model.AcceptanceData, len(blueBlocks)) accumulatedUTXODiff := utxoalgebra.DiffClone(selectedParentPastUTXODiff) accumulatedMass := uint64(0) for i, blueBlock := range blueBlocks { + blueBlockHash := consensusserialization.BlockHash(blueBlock) + log.Tracef("Applying blue block %s", blueBlockHash) blockAcceptanceData := &model.BlockAcceptanceData{ TransactionAcceptanceData: make([]*model.TransactionAcceptanceData, len(blueBlock.Transactions)), } isSelectedParent := i == 0 + log.Tracef("Is blue block %s the selected parent: %t", blueBlockHash, isSelectedParent) for j, transaction := range blueBlock.Transactions { var isAccepted bool - var fee uint64 + + transactionID := consensusserialization.TransactionID(transaction) + log.Tracef("Attempting to accept transaction %s in block %s", + transactionID, blueBlockHash) isAccepted, accumulatedMass, err = csm.maybeAcceptTransaction(transaction, blockHash, isSelectedParent, accumulatedUTXODiff, accumulatedMass, selectedParentMedianTime, ghostdagData.BlueScore) if err != nil { return nil, nil, err } + log.Tracef("Transaction %s in block %s isAccepted: %t, fee: %d", + transactionID, blueBlockHash, isAccepted, transaction.Fee) blockAcceptanceData.TransactionAcceptanceData[j] = &model.TransactionAcceptanceData{ Transaction: transaction, - Fee: fee, + Fee: transaction.Fee, IsAccepted: isAccepted, } } @@ -133,6 +171,11 @@ func (csm *consensusStateManager) maybeAcceptTransaction(transaction *externalap accumulatedMassBefore uint64, selectedParentPastMedianTime int64, blockBlueScore uint64) ( isAccepted bool, accumulatedMassAfter uint64, err error) { + transactionID := consensusserialization.TransactionID(transaction) + log.Tracef("maybeAcceptTransaction start for transaction %s in block %s", transactionID, blockHash) + defer log.Tracef("maybeAcceptTransaction end for transaction %s in block %s", transactionID, blockHash) + + log.Tracef("Populating transaction %s with UTXO entries", transactionID) err = csm.populateTransactionWithUTXOEntriesFromVirtualOrDiff(transaction, accumulatedUTXODiff) if err != nil { if !errors.As(err, &(ruleerrors.RuleError{})) { @@ -145,9 +188,14 @@ func (csm *consensusStateManager) maybeAcceptTransaction(transaction *externalap // Coinbase transaction outputs are added to the UTXO-set only if they are in the selected parent chain. if transactionhelper.IsCoinBase(transaction) { if !isSelectedParent { + log.Tracef("Transaction %s is the coinbase of block %s "+ + "but said block is not in the selected parent chain. "+ + "As such, it is not accepted", transactionID, blockHash) return false, accumulatedMassBefore, nil } + log.Tracef("Transaction %s is the coinbase of block %s", transactionID, blockHash) } else { + log.Tracef("Validating transaction %s in block %s", transactionID, blockHash) err = csm.transactionValidator.ValidateTransactionInContextAndPopulateMassAndFee( transaction, blockHash, selectedParentPastMedianTime) if err != nil { @@ -155,15 +203,22 @@ func (csm *consensusStateManager) maybeAcceptTransaction(transaction *externalap return false, 0, err } + log.Tracef("Validation failed for transaction %s "+ + "in block %s: %s", transactionID, blockHash, err) return false, accumulatedMassBefore, nil } + log.Tracef("Validation passed for transaction %s in block %s", transactionID, blockHash) + log.Tracef("Check mass for transaction %s in block %s", transactionID, blockHash) isAccepted, accumulatedMassAfter = csm.checkTransactionMass(transaction, accumulatedMassBefore) if !isAccepted { + log.Tracef("Transaction %s in block %s has too much mass, "+ + "and cannot be accepted", transactionID, blockHash) return false, accumulatedMassBefore, nil } } + log.Tracef("Adding transaction %s in block %s to the accumulated diff", transactionID, blockHash) err = utxoalgebra.DiffAddTransaction(accumulatedUTXODiff, transaction, blockBlueScore) if err != nil { return false, 0, err @@ -176,7 +231,14 @@ func (csm *consensusStateManager) checkTransactionMass( transaction *externalapi.DomainTransaction, accumulatedMassBefore uint64) ( isAccepted bool, accumulatedMassAfter uint64) { + transactionID := consensusserialization.TransactionID(transaction) + log.Tracef("checkTransactionMass start for transaction %s", transactionID) + defer log.Tracef("checkTransactionMass end for transaction %s", transactionID) + + log.Tracef("Adding transaction %s with mass %d to the "+ + "so-far accumulated mass of %d", transactionID, transaction.Mass, accumulatedMassBefore) accumulatedMassAfter = accumulatedMassBefore + transaction.Mass + log.Tracef("Accumulated mass including transaction %s: %d", transactionID, accumulatedMassAfter) // We could potentially overflow the accumulator so check for // overflow as well. @@ -187,7 +249,13 @@ func (csm *consensusStateManager) checkTransactionMass( return true, accumulatedMassAfter } -func (csm *consensusStateManager) RestorePastUTXOSetIterator(blockHash *externalapi.DomainHash) (model.ReadOnlyUTXOSetIterator, error) { +func (csm *consensusStateManager) RestorePastUTXOSetIterator(blockHash *externalapi.DomainHash) ( + model.ReadOnlyUTXOSetIterator, error) { + + log.Tracef("RestorePastUTXOSetIterator start for block %s", blockHash) + defer log.Tracef("RestorePastUTXOSetIterator end for block %s", blockHash) + + log.Tracef("Calculating UTXO diff for block %s", blockHash) blockDiff, _, _, err := csm.CalculatePastUTXOAndAcceptanceData(blockHash) if err != nil { return nil, err diff --git a/domain/consensus/processes/consensusstatemanager/finality.go b/domain/consensus/processes/consensusstatemanager/finality.go index f568733de..88c77612e 100644 --- a/domain/consensus/processes/consensusstatemanager/finality.go +++ b/domain/consensus/processes/consensusstatemanager/finality.go @@ -8,7 +8,12 @@ import ( func (csm *consensusStateManager) checkFinalityViolation( blockHash *externalapi.DomainHash) error { + log.Tracef("checkFinalityViolation start for block %s", blockHash) + defer log.Tracef("checkFinalityViolation end for block %s", blockHash) + if *blockHash == *csm.genesisHash { + log.Tracef("Block %s is the genesis block, "+ + "and does not violate finality by definition", blockHash) return nil } @@ -20,7 +25,9 @@ func (csm *consensusStateManager) checkFinalityViolation( if isViolatingFinality { csm.blockStatusStore.Stage(blockHash, externalapi.StatusUTXOPendingVerification) log.Warnf("Finality Violation Detected! Block %s violates finality!", blockHash) + return nil } + log.Tracef("Block %s does not violate finality", blockHash) return nil } @@ -28,21 +35,37 @@ func (csm *consensusStateManager) checkFinalityViolation( func (csm *consensusStateManager) virtualFinalityPoint() ( *externalapi.DomainHash, error) { - return csm.dagTraversalManager.BlockAtDepth( + log.Tracef("virtualFinalityPoint start") + defer log.Tracef("virtualFinalityPoint end") + + virtualFinalityPoint, err := csm.dagTraversalManager.BlockAtDepth( model.VirtualBlockHash, csm.finalityDepth) + if err != nil { + return nil, err + } + log.Tracef("The current virtual finality block is: %s", virtualFinalityPoint) + + return virtualFinalityPoint, nil } func (csm *consensusStateManager) isViolatingFinality( blockHash *externalapi.DomainHash) (bool, error) { + log.Tracef("isViolatingFinality start for block %s", blockHash) + defer log.Tracef("isViolatingFinality end for block %s", blockHash) + virtualFinalityPoint, err := csm.virtualFinalityPoint() if err != nil { return false, err } + log.Tracef("The virtual finality point is: %s", virtualFinalityPoint) isInSelectedParentChain, err := csm.dagTopologyManager.IsInSelectedParentChainOf(virtualFinalityPoint, blockHash) if err != nil { return false, err } + log.Tracef("Is the virtual finality point %s "+ + "in the selected parent chain of %s: %t", virtualFinalityPoint, blockHash, isInSelectedParentChain) + return !isInSelectedParentChain, nil } diff --git a/domain/consensus/processes/consensusstatemanager/multisets.go b/domain/consensus/processes/consensusstatemanager/multisets.go index f1b131ea1..fc77e95d2 100644 --- a/domain/consensus/processes/consensusstatemanager/multisets.go +++ b/domain/consensus/processes/consensusstatemanager/multisets.go @@ -11,7 +11,12 @@ import ( func (csm *consensusStateManager) calculateMultiset( acceptanceData model.AcceptanceData, blockGHOSTDAGData *model.BlockGHOSTDAGData) (model.Multiset, error) { + log.Tracef("calculateMultiset start for block with selected parent %s", blockGHOSTDAGData.SelectedParent) + defer log.Tracef("calculateMultiset end for block with selected parent %s", blockGHOSTDAGData.SelectedParent) + if blockGHOSTDAGData.SelectedParent == nil { + log.Tracef("Selected parent is nil, which could only happen for the genesis. " + + "The genesis, by definition, has an empty multiset") return multiset.New(), nil } @@ -19,21 +24,26 @@ func (csm *consensusStateManager) calculateMultiset( if err != nil { return nil, err } + log.Tracef("The multiset for the selected parent %s is: %s", blockGHOSTDAGData.SelectedParent, ms.Hash()) for _, blockAcceptanceData := range acceptanceData { for i, transactionAcceptanceData := range blockAcceptanceData.TransactionAcceptanceData { + transaction := transactionAcceptanceData.Transaction + transactionID := consensusserialization.TransactionID(transaction) if !transactionAcceptanceData.IsAccepted { + log.Tracef("Skipping transaction %s because it was not accepted", transactionID) continue } - transaction := transactionAcceptanceData.Transaction - isCoinbase := i == 0 + log.Tracef("Is transaction %s a coinbase transaction: %t", transactionID, isCoinbase) + var err error err = addTransactionToMultiset(ms, transaction, blockGHOSTDAGData.BlueScore, isCoinbase) if err != nil { return nil, err } + log.Tracef("Added transaction %s to the multiset", transactionID) } } @@ -43,7 +53,13 @@ func (csm *consensusStateManager) calculateMultiset( func addTransactionToMultiset(multiset model.Multiset, transaction *externalapi.DomainTransaction, blockBlueScore uint64, isCoinbase bool) error { + transactionID := consensusserialization.TransactionID(transaction) + log.Tracef("addTransactionToMultiset start for transaction %s", transactionID) + defer log.Tracef("addTransactionToMultiset end for transaction %s", transactionID) + for _, input := range transaction.Inputs { + log.Tracef("Removing input %s at index %d from the multiset", + input.PreviousOutpoint.TransactionID, input.PreviousOutpoint.Index) err := removeUTXOFromMultiset(multiset, input.UTXOEntry, &input.PreviousOutpoint) if err != nil { return err @@ -52,7 +68,7 @@ func addTransactionToMultiset(multiset model.Multiset, transaction *externalapi. for i, output := range transaction.Outputs { outpoint := &externalapi.DomainOutpoint{ - TransactionID: *consensusserialization.TransactionID(transaction), + TransactionID: *transactionID, Index: uint32(i), } utxoEntry := &externalapi.UTXOEntry{ @@ -61,6 +77,7 @@ func addTransactionToMultiset(multiset model.Multiset, transaction *externalapi. BlockBlueScore: blockBlueScore, IsCoinbase: isCoinbase, } + log.Tracef("Adding input %s at index %d from the multiset", transactionID, i) err := addUTXOToMultiset(multiset, utxoEntry, outpoint) if err != nil { return err diff --git a/domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go b/domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go index 3e123ef26..bf86175da 100644 --- a/domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go +++ b/domain/consensus/processes/consensusstatemanager/pick_virtual_parents.go @@ -10,6 +10,10 @@ import ( ) func (csm *consensusStateManager) pickVirtualParents(tips []*externalapi.DomainHash) ([]*externalapi.DomainHash, error) { + log.Tracef("pickVirtualParents start for tips: %s", tips) + defer log.Tracef("pickVirtualParents end for tips: %s", tips) + + log.Tracef("Pushing all tips into a DownHeap") candidatesHeap := csm.dagTraversalManager.NewDownHeap() for _, tip := range tips { err := candidatesHeap.Push(tip) @@ -26,6 +30,7 @@ func (csm *consensusStateManager) pickVirtualParents(tips []*externalapi.DomainH if err != nil { return nil, err } + log.Tracef("The selected parent of the virtual is: %s", virtualSelectedParent) selectedVirtualParents := hashset.NewFromSlice(virtualSelectedParent) @@ -33,28 +38,44 @@ func (csm *consensusStateManager) pickVirtualParents(tips []*externalapi.DomainH for candidatesHeap.Len() > 0 && len(selectedVirtualParents) < constants.MaxBlockParents { candidate := candidatesHeap.Pop() + + log.Tracef("Attempting to add %s to the virtual parents", candidate) + log.Tracef("The current merge set size is %d", mergeSetSize) + mergeSetIncrease, err := csm.mergeSetIncrease(candidate, selectedVirtualParents) if err != nil { return nil, err } + log.Tracef("The merge set would increase by %d with block %s", mergeSetIncrease, candidate) if mergeSetSize+mergeSetIncrease > constants.MergeSetSizeLimit { + log.Tracef("Cannot add block %s since that would violate the merge set size limit", candidate) continue } selectedVirtualParents.Add(candidate) mergeSetSize += mergeSetIncrease + log.Tracef("Added block %s to the virtual parents set", candidate) } boundedMergeBreakingParents, err := csm.boundedMergeBreakingParents(selectedVirtualParents.ToSlice()) if err != nil { return nil, err } + log.Tracef("The following parents are omitted for "+ + "breaking the bounded merge set: %s", boundedMergeBreakingParents) - return selectedVirtualParents.Subtract(boundedMergeBreakingParents).ToSlice(), nil + virtualParents := selectedVirtualParents.Subtract(boundedMergeBreakingParents).ToSlice() + log.Tracef("The virtual parents resolved to be: %s", virtualParents) + return virtualParents, nil } -func (csm *consensusStateManager) selectVirtualSelectedParent(candidatesHeap model.BlockHeap) (*externalapi.DomainHash, error) { +func (csm *consensusStateManager) selectVirtualSelectedParent( + candidatesHeap model.BlockHeap) (*externalapi.DomainHash, error) { + + log.Tracef("selectVirtualSelectedParent start") + defer log.Tracef("selectVirtualSelectedParent end") + disqualifiedCandidates := hashset.New() for { @@ -63,20 +84,24 @@ func (csm *consensusStateManager) selectVirtualSelectedParent(candidatesHeap mod } selectedParentCandidate := candidatesHeap.Pop() + log.Tracef("Checking block %s for selected parent eligibility", selectedParentCandidate) selectedParentCandidateStatus, err := csm.blockStatusStore.Get(csm.databaseContext, selectedParentCandidate) if err != nil { return nil, err } if selectedParentCandidateStatus == externalapi.StatusValid { + log.Tracef("Block %s is valid. Returning it as the selected parent", selectedParentCandidate) return selectedParentCandidate, nil } + log.Tracef("Block %s is not valid. Adding it to the disqualified set", selectedParentCandidate) disqualifiedCandidates.Add(selectedParentCandidate) candidateParents, err := csm.dagTopologyManager.Parents(selectedParentCandidate) if err != nil { return nil, err } + log.Tracef("The parents of block %s are: %s", selectedParentCandidate, candidateParents) for _, parent := range candidateParents { parentChildren, err := csm.dagTopologyManager.Children(parent) if err != nil { @@ -90,8 +115,11 @@ func (csm *consensusStateManager) selectVirtualSelectedParent(candidatesHeap mod break } } + log.Tracef("The children of block %s are: %s", parent, parentChildren) if disqualifiedCandidates.ContainsAllInSlice(parentChildren) { + log.Tracef("The disqualified set contains all the "+ + "children of %s. Adding it to the candidate heap", parentChildren) err := candidatesHeap.Push(parent) if err != nil { return nil, err @@ -104,6 +132,9 @@ func (csm *consensusStateManager) selectVirtualSelectedParent(candidatesHeap mod func (csm *consensusStateManager) mergeSetIncrease( candidate *externalapi.DomainHash, selectedVirtualParents hashset.HashSet) (int, error) { + log.Tracef("mergeSetIncrease start") + defer log.Tracef("mergeSetIncrease end") + visited := hashset.New() queue := csm.dagTraversalManager.NewDownHeap() err := queue.Push(candidate) @@ -114,15 +145,20 @@ func (csm *consensusStateManager) mergeSetIncrease( for queue.Len() > 0 { current := queue.Pop() + log.Tracef("Attempting to increment the merge set size increase for block %s", current) + isInPastOfSelectedVirtualParents, err := csm.dagTopologyManager.IsAncestorOfAny( current, selectedVirtualParents.ToSlice()) if err != nil { return 0, err } if isInPastOfSelectedVirtualParents { + log.Tracef("Skipping block %s because it's in the past of one "+ + "(or more) of the selected virtual parents", current) continue } + log.Tracef("Incrementing the merge set size increase") mergeSetIncrease++ parents, err := csm.dagTopologyManager.Parents(current) @@ -139,12 +175,18 @@ func (csm *consensusStateManager) mergeSetIncrease( } } } + log.Tracef("The resolved merge set size increase is: %d", mergeSetIncrease) return mergeSetIncrease, nil } -func (csm *consensusStateManager) boundedMergeBreakingParents(parents []*externalapi.DomainHash) (hashset.HashSet, error) { - // Temporarily set virtual to all parents, so that we can run ghostdag on it +func (csm *consensusStateManager) boundedMergeBreakingParents( + parents []*externalapi.DomainHash) (hashset.HashSet, error) { + + log.Tracef("boundedMergeBreakingParents start for parents: %s", parents) + defer log.Tracef("boundedMergeBreakingParents end for parents: %s", parents) + + log.Tracef("Temporarily setting virtual to all parents, so that we can run ghostdag on it") err := csm.dagTopologyManager.SetParents(model.VirtualBlockHash, parents) if err != nil { return nil, err @@ -159,24 +201,29 @@ func (csm *consensusStateManager) boundedMergeBreakingParents(parents []*externa if err != nil { return nil, err } + log.Tracef("The potentially kosherizing blocks are: %s", potentiallyKosherizingBlocks) virtualFinalityPoint, err := csm.virtualFinalityPoint() if err != nil { return nil, err } + log.Tracef("The finality point of the virtual is: %s", virtualFinalityPoint) - badReds := []*externalapi.DomainHash{} + var badReds []*externalapi.DomainHash virtualGHOSTDAGData, err := csm.ghostdagDataStore.Get(csm.databaseContext, model.VirtualBlockHash) if err != nil { return nil, err } for _, redBlock := range virtualGHOSTDAGData.MergeSetReds { + log.Tracef("Check whether red block %s is kosherized", redBlock) isFinalityPointInPast, err := csm.dagTopologyManager.IsAncestorOf(virtualFinalityPoint, redBlock) if err != nil { return nil, err } if isFinalityPointInPast { + log.Tracef("Skipping red block %s because it has the virtual's"+ + " finality point in its past", redBlock) continue } @@ -186,17 +233,21 @@ func (csm *consensusStateManager) boundedMergeBreakingParents(parents []*externa if err != nil { return nil, err } + log.Tracef("Red block %s is an ancestor of potentially kosherizing "+ + "block %s, therefore the red block is kosher", redBlock, potentiallyKosherizingBlock) if isKosherized { break } } if !isKosherized { + log.Tracef("Red block %s is not kosher. Adding it to the bad reds set", redBlock) badReds = append(badReds, redBlock) } } boundedMergeBreakingParents := hashset.New() for _, parent := range parents { + log.Tracef("Checking whether parent %s breaks the bounded merge set", parent) isBadRedInPast := false for _, badRedBlock := range badReds { isBadRedInPast, err = csm.dagTopologyManager.IsAncestorOf(parent, badRedBlock) @@ -204,10 +255,12 @@ func (csm *consensusStateManager) boundedMergeBreakingParents(parents []*externa return nil, err } if isBadRedInPast { + log.Tracef("Parent %s is an ancestor of bad red %s", parent, badRedBlock) break } } if isBadRedInPast { + log.Tracef("Adding parent %s to the bounded merge breaking parents set", parent) boundedMergeBreakingParents.Add(parent) } } diff --git a/domain/consensus/processes/consensusstatemanager/populate_tx_with_utxo_entries.go b/domain/consensus/processes/consensusstatemanager/populate_tx_with_utxo_entries.go index 08006f55e..08147f004 100644 --- a/domain/consensus/processes/consensusstatemanager/populate_tx_with_utxo_entries.go +++ b/domain/consensus/processes/consensusstatemanager/populate_tx_with_utxo_entries.go @@ -5,6 +5,7 @@ import ( "github.com/kaspanet/kaspad/domain/consensus/model/externalapi" "github.com/kaspanet/kaspad/domain/consensus/processes/consensusstatemanager/utxoalgebra" "github.com/kaspanet/kaspad/domain/consensus/ruleerrors" + "github.com/kaspanet/kaspad/domain/consensus/utils/consensusserialization" ) // PopulateTransactionWithUTXOEntries populates the transaction UTXO entries with data from the virtual's UTXO set. @@ -18,22 +19,31 @@ func (csm *consensusStateManager) PopulateTransactionWithUTXOEntries(transaction func (csm *consensusStateManager) populateTransactionWithUTXOEntriesFromVirtualOrDiff( transaction *externalapi.DomainTransaction, utxoDiff *model.UTXODiff) error { - missingOutpoints := []*externalapi.DomainOutpoint{} + transactionID := consensusserialization.TransactionID(transaction) + log.Tracef("populateTransactionWithUTXOEntriesFromVirtualOrDiff start for transaction %s", transactionID) + defer log.Tracef("populateTransactionWithUTXOEntriesFromVirtualOrDiff end for transaction %s", transactionID) + var missingOutpoints []*externalapi.DomainOutpoint for _, transactionInput := range transaction.Inputs { // skip all inputs that have a pre-filled utxo entry if transactionInput.UTXOEntry != nil { + log.Tracef("Skipping outpoint %s:%d because it is already populated", + transactionInput.PreviousOutpoint.TransactionID, transactionInput.PreviousOutpoint.Index) continue } // check if utxoDiff says anything about the input's outpoint if utxoDiff != nil { if utxoEntry, ok := utxoalgebra.CollectionGet(utxoDiff.ToAdd, &transactionInput.PreviousOutpoint); ok { + log.Tracef("Populating outpoint %s:%d from the given utxoDiff", + transactionInput.PreviousOutpoint.TransactionID, transactionInput.PreviousOutpoint.Index) transactionInput.UTXOEntry = utxoEntry continue } if utxoalgebra.CollectionContains(utxoDiff.ToRemove, &transactionInput.PreviousOutpoint) { + log.Tracef("Outpoint %s:%d is missing in the given utxoDiff", + transactionInput.PreviousOutpoint.TransactionID, transactionInput.PreviousOutpoint.Index) missingOutpoints = append(missingOutpoints, &transactionInput.PreviousOutpoint) continue } @@ -45,10 +55,14 @@ func (csm *consensusStateManager) populateTransactionWithUTXOEntriesFromVirtualO return err } if !hasUTXOEntry { + log.Tracef("Outpoint %s:%d is missing in the database", + transactionInput.PreviousOutpoint.TransactionID, transactionInput.PreviousOutpoint.Index) missingOutpoints = append(missingOutpoints, &transactionInput.PreviousOutpoint) continue } + log.Tracef("Populating outpoint %s:%d from the database", + transactionInput.PreviousOutpoint.TransactionID, transactionInput.PreviousOutpoint.Index) utxoEntry, err := csm.consensusStateStore.UTXOByOutpoint(csm.databaseContext, &transactionInput.PreviousOutpoint) if err != nil { return err diff --git a/domain/consensus/processes/consensusstatemanager/resolve_block_status.go b/domain/consensus/processes/consensusstatemanager/resolve_block_status.go index 2b5d993e4..086748ad6 100644 --- a/domain/consensus/processes/consensusstatemanager/resolve_block_status.go +++ b/domain/consensus/processes/consensusstatemanager/resolve_block_status.go @@ -9,25 +9,40 @@ import ( ) func (csm *consensusStateManager) resolveBlockStatus(blockHash *externalapi.DomainHash) (externalapi.BlockStatus, error) { - // get list of all blocks in the selected parent chain that have not yet resolved their status + log.Tracef("resolveBlockStatus start for block %s", blockHash) + defer log.Tracef("resolveBlockStatus end for block %s", blockHash) + + log.Tracef("Getting a list of all blocks in the selected "+ + "parent chain of %s that have no yet resolved their status", blockHash) unverifiedBlocks, err := csm.getUnverifiedChainBlocks(blockHash) if err != nil { return 0, err } + log.Tracef("Got %d unverified blocks in the selected parent "+ + "chain of %s: %s", len(unverifiedBlocks), blockHash, unverifiedBlocks) // If there's no unverified blocks in the given block's chain - this means the given block already has a // UTXO-verified status, and therefore it should be retrieved from the store and returned if len(unverifiedBlocks) == 0 { - return csm.blockStatusStore.Get(csm.databaseContext, blockHash) + log.Tracef("There are not unverified blocks in %s's selected parent chain. "+ + "This means that the block already has a UTXO-verified status.", blockHash) + status, err := csm.blockStatusStore.Get(csm.databaseContext, blockHash) + if err != nil { + return 0, err + } + log.Tracef("Block %s's status resolved to: %s", blockHash, status) + return status, nil } + log.Tracef("Finding the status of the selected parent of %s", blockHash) selectedParentStatus, err := csm.findSelectedParentStatus(unverifiedBlocks) if err != nil { return 0, err } + log.Tracef("The status of the selected parent of %s is: %s", blockHash, selectedParentStatus) + log.Tracef("Resolving the unverified blocks' status in reverse order (past to present)") var blockStatus externalapi.BlockStatus - // resolve the unverified blocks' statuses in opposite order for i := len(unverifiedBlocks) - 1; i >= 0; i-- { unverifiedBlockHash := unverifiedBlocks[i] @@ -51,8 +66,14 @@ func (csm *consensusStateManager) resolveBlockStatus(blockHash *externalapi.Doma // findSelectedParentStatus returns the status of the selectedParent of the last block in the unverifiedBlocks chain func (csm *consensusStateManager) findSelectedParentStatus(unverifiedBlocks []*externalapi.DomainHash) ( externalapi.BlockStatus, error) { + + log.Tracef("findSelectedParentStatus start") + defer log.Tracef("findSelectedParentStatus end") + lastUnverifiedBlock := unverifiedBlocks[len(unverifiedBlocks)-1] if *lastUnverifiedBlock == *csm.genesisHash { + log.Tracef("the most recent unverified block is the genesis block, "+ + "which by definition has status: %s", externalapi.StatusValid) return externalapi.StatusValid, nil } lastUnverifiedBlockGHOSTDAGData, err := csm.ghostdagDataStore.Get(csm.databaseContext, lastUnverifiedBlock) @@ -65,17 +86,24 @@ func (csm *consensusStateManager) findSelectedParentStatus(unverifiedBlocks []*e func (csm *consensusStateManager) getUnverifiedChainBlocks( blockHash *externalapi.DomainHash) ([]*externalapi.DomainHash, error) { - unverifiedBlocks := []*externalapi.DomainHash{} + log.Tracef("getUnverifiedChainBlocks start for block %s", blockHash) + defer log.Tracef("getUnverifiedChainBlocks end for block %s", blockHash) + + var unverifiedBlocks []*externalapi.DomainHash currentHash := blockHash for { + log.Tracef("Getting status for block %s", currentHash) currentBlockStatus, err := csm.blockStatusStore.Get(csm.databaseContext, currentHash) if err != nil { return nil, err } if currentBlockStatus != externalapi.StatusUTXOPendingVerification { + log.Tracef("Block %s has status %s. Returning all the "+ + "unverified blocks prior to it: %s", currentHash, currentBlockStatus, unverifiedBlocks) return unverifiedBlocks, nil } + log.Tracef("Block %s is unverified. Adding it to the unverified block collection", currentHash) unverifiedBlocks = append(unverifiedBlocks, currentHash) currentBlockGHOSTDAGData, err := csm.ghostdagDataStore.Get(csm.databaseContext, currentHash) @@ -84,7 +112,9 @@ func (csm *consensusStateManager) getUnverifiedChainBlocks( } if currentBlockGHOSTDAGData.SelectedParent == nil { - return unverifiedBlocks, nil // this means we reached genesis + log.Tracef("Genesis block reached. Returning all the "+ + "unverified blocks prior to it: %s", unverifiedBlocks) + return unverifiedBlocks, nil } currentHash = currentBlockGHOSTDAGData.SelectedParent @@ -92,11 +122,16 @@ func (csm *consensusStateManager) getUnverifiedChainBlocks( } func (csm *consensusStateManager) resolveSingleBlockStatus(blockHash *externalapi.DomainHash) (externalapi.BlockStatus, error) { + log.Tracef("resolveSingleBlockStatus start for block %s", blockHash) + defer log.Tracef("resolveSingleBlockStatus end for block %s", blockHash) + + log.Tracef("Calculating pastUTXO and acceptance data and multiset for block %s", blockHash) pastUTXODiff, acceptanceData, multiset, err := csm.CalculatePastUTXOAndAcceptanceData(blockHash) if err != nil { return 0, err } + log.Tracef("Staging the calculated acceptance data of block %s", blockHash) err = csm.acceptanceDataStore.Stage(blockHash, acceptanceData) if err != nil { return 0, err @@ -107,20 +142,27 @@ func (csm *consensusStateManager) resolveSingleBlockStatus(blockHash *externalap return 0, err } + log.Tracef("verifying the UTXO of block %s", blockHash) err = csm.verifyUTXO(block, blockHash, pastUTXODiff, acceptanceData, multiset) if err != nil { if errors.As(err, &ruleerrors.RuleError{}) { + log.Debugf("UTXO verification for block %s failed: %s", blockHash, err) return externalapi.StatusDisqualifiedFromChain, nil } return 0, err } + log.Debugf("UTXO verification for block %s passed", blockHash) + log.Tracef("Staging the multiset of block %s", blockHash) csm.multisetStore.Stage(blockHash, multiset) + + log.Tracef("Staging the utxoDiff of block %s", blockHash) err = csm.utxoDiffStore.Stage(blockHash, pastUTXODiff, nil) if err != nil { return 0, err } + log.Tracef("Updating the parent utxoDiffs of block %s", blockHash) err = csm.updateParentDiffs(blockHash, pastUTXODiff) if err != nil { return 0, err @@ -130,10 +172,15 @@ func (csm *consensusStateManager) resolveSingleBlockStatus(blockHash *externalap } func (csm *consensusStateManager) updateParentDiffs( blockHash *externalapi.DomainHash, pastUTXODiff *model.UTXODiff) error { + log.Tracef("updateParentDiffs start for block %s", blockHash) + defer log.Tracef("updateParentDiffs end for block %s", blockHash) + parentHashes, err := csm.dagTopologyManager.Parents(blockHash) if err != nil { return err } + log.Tracef("Parent hashes for block %s are: %s", blockHash, parentHashes) + for _, parentHash := range parentHashes { // skip all parents that already have a utxo-diff child parentHasUTXODiffChild, err := csm.utxoDiffStore.HasUTXODiffChild(csm.databaseContext, parentHash) @@ -141,6 +188,8 @@ func (csm *consensusStateManager) updateParentDiffs( return err } if parentHasUTXODiffChild { + log.Tracef("Skipping parent %s of block %s because it "+ + "already has a UTXO diff-child", parentHash, blockHash) continue } @@ -149,11 +198,14 @@ func (csm *consensusStateManager) updateParentDiffs( return err } if parentStatus != externalapi.StatusValid { + log.Tracef("Skipping parent %s of block %s because it "+ + "has a non-valid status %s", parentHash, blockHash, parentStatus) continue } - // parents that till now didn't have a utxo-diff child - were actually virtual's diffParents. + // parents that didn't have a utxo-diff child until now were actually virtual's diffParents. // Update them to have the new block as their utxo-diff child + log.Tracef("Resolving new UTXO diff of parent %s", parentHash) parentCurrentDiff, err := csm.utxoDiffStore.UTXODiff(csm.databaseContext, parentHash) if err != nil { return err @@ -162,7 +214,9 @@ func (csm *consensusStateManager) updateParentDiffs( if err != nil { return err } + log.Tracef("The new UTXO diff parent %s resolved to: %s", parentHash, parentNewDiff) + log.Tracef("Staging the new UTXO diff and diff child for parent %s", parentHash) err = csm.utxoDiffStore.Stage(parentHash, parentNewDiff, blockHash) if err != nil { return err diff --git a/domain/consensus/processes/consensusstatemanager/set_pruning_utxo_set.go b/domain/consensus/processes/consensusstatemanager/set_pruning_utxo_set.go index 59a65a9ab..7ccfee5c8 100644 --- a/domain/consensus/processes/consensusstatemanager/set_pruning_utxo_set.go +++ b/domain/consensus/processes/consensusstatemanager/set_pruning_utxo_set.go @@ -32,10 +32,14 @@ func (csm *consensusStateManager) SetPruningPointUTXOSet(serializedUTXOSet []byt } func (csm *consensusStateManager) setPruningPointUTXOSet(serializedUTXOSet []byte) error { + log.Tracef("setPruningPointUTXOSet start") + defer log.Tracef("setPruningPointUTXOSet end") + headerTipsPruningPoint, err := csm.HeaderTipsPruningPoint() if err != nil { return err } + log.Tracef("The pruning point of the header tips is: %s", headerTipsPruningPoint) protoUTXOSet := &utxoserialization.ProtoUTXOSet{} err = proto.Unmarshal(serializedUTXOSet, protoUTXOSet) @@ -47,27 +51,34 @@ func (csm *consensusStateManager) setPruningPointUTXOSet(serializedUTXOSet []byt if err != nil { return err } + log.Tracef("Calculated multiset for given UTXO set: %s", utxoSetMultiSet.Hash()) headerTipsPruningPointHeader, err := csm.blockHeaderStore.BlockHeader(csm.databaseContext, headerTipsPruningPoint) if err != nil { return err } + log.Tracef("The multiset in the header of the header tip pruning point: %s", + headerTipsPruningPointHeader.UTXOCommitment) if headerTipsPruningPointHeader.UTXOCommitment != *utxoSetMultiSet.Hash() { return errors.Wrapf(ruleerrors.ErrBadPruningPointUTXOSet, "the expected multiset hash of the pruning "+ "point UTXO set is %s but got %s", headerTipsPruningPointHeader.UTXOCommitment, *utxoSetMultiSet.Hash()) } + log.Tracef("Header tip pruning point multiset validation passed") + log.Tracef("Staging the parent hashes for the header tips pruning point as the DAG tips") err = csm.consensusStateStore.StageTips(headerTipsPruningPointHeader.ParentHashes) if err != nil { return err } + log.Tracef("Setting the parent hashes for the header tips pruning point as the virtual parents") err = csm.dagTopologyManager.SetParents(model.VirtualBlockHash, headerTipsPruningPointHeader.ParentHashes) if err != nil { return err } + log.Tracef("Staging the virtual UTXO set") err = csm.consensusStateStore.StageVirtualUTXOSet(protoUTXOSetToReadOnlyUTXOSetIterator(protoUTXOSet)) if err != nil { return err @@ -78,11 +89,13 @@ func (csm *consensusStateManager) setPruningPointUTXOSet(serializedUTXOSet []byt return err } + log.Tracef("Updating the header tips pruning point diff parents with an empty UTXO diff") err = csm.updateVirtualDiffParents(headerTipsPruningPoint, model.NewUTXODiff()) if err != nil { return err } + log.Tracef("Staging the status of the header tips pruning point as %s", externalapi.StatusValid) csm.blockStatusStore.Stage(headerTipsPruningPoint, externalapi.StatusValid) return nil } @@ -136,18 +149,22 @@ func protoUTXOSetToReadOnlyUTXOSetIterator(protoUTXOSet *utxoserialization.Proto } func (csm *consensusStateManager) HeaderTipsPruningPoint() (*externalapi.DomainHash, error) { + log.Tracef("HeaderTipsPruningPoint start") + defer log.Tracef("HeaderTipsPruningPoint end") + headerTips, err := csm.headerTipsStore.Tips(csm.databaseContext) if err != nil { return nil, err } + log.Tracef("The current header tips are: %s", headerTips) + log.Tracef("Temporarily staging the parents of the virtual header to be the header tips: %s", headerTips) err = csm.blockRelationStore.StageBlockRelation(virtualHeaderHash, &model.BlockRelations{ Parents: headerTips, }) if err != nil { return nil, err } - defer csm.blockRelationStore.Discard() err = csm.ghostdagManager.GHOSTDAG(virtualHeaderHash) @@ -156,5 +173,10 @@ func (csm *consensusStateManager) HeaderTipsPruningPoint() (*externalapi.DomainH } defer csm.ghostdagDataStore.Discard() - return csm.dagTraversalManager.BlockAtDepth(virtualHeaderHash, csm.pruningDepth) + pruningPoint, err := csm.dagTraversalManager.BlockAtDepth(virtualHeaderHash, csm.pruningDepth) + if err != nil { + return nil, err + } + log.Tracef("The block at depth %d from %s is: %s", csm.pruningDepth, virtualHeaderHash, pruningPoint) + return pruningPoint, nil } diff --git a/domain/consensus/processes/consensusstatemanager/update_virtual.go b/domain/consensus/processes/consensusstatemanager/update_virtual.go index fb0df7df4..ee7471510 100644 --- a/domain/consensus/processes/consensusstatemanager/update_virtual.go +++ b/domain/consensus/processes/consensusstatemanager/update_virtual.go @@ -8,38 +8,49 @@ import ( ) func (csm *consensusStateManager) updateVirtual(newBlockHash *externalapi.DomainHash, tips []*externalapi.DomainHash) error { + log.Tracef("updateVirtual start for block %s", newBlockHash) + defer log.Tracef("updateVirtual end for block %s", newBlockHash) + + log.Tracef("Picking virtual parents from the tips: %s", tips) virtualParents, err := csm.pickVirtualParents(tips) if err != nil { return err } + log.Tracef("Picked virtual parents: %s", virtualParents) err = csm.dagTopologyManager.SetParents(model.VirtualBlockHash, virtualParents) if err != nil { return err } + log.Tracef("Set new parents for the virtual block hash") err = csm.ghostdagManager.GHOSTDAG(model.VirtualBlockHash) if err != nil { return err } + log.Tracef("Calculating past UTXO, acceptance data, and multiset for the new virtual block") virtualUTXODiff, virtualAcceptanceData, virtualMultiset, err := csm.CalculatePastUTXOAndAcceptanceData(model.VirtualBlockHash) if err != nil { return err } + log.Tracef("Staging new acceptance data for the virtual block") err = csm.acceptanceDataStore.Stage(model.VirtualBlockHash, virtualAcceptanceData) if err != nil { return err } + log.Tracef("Staging new multiset for the virtual block") csm.multisetStore.Stage(model.VirtualBlockHash, virtualMultiset) + log.Tracef("Staging new UTXO diff for the virtual block") err = csm.consensusStateStore.StageVirtualUTXODiff(virtualUTXODiff) if err != nil { return err } + log.Tracef("Updating the virtual diff parents after adding %s to the DAG", newBlockHash) err = csm.updateVirtualDiffParents(newBlockHash, virtualUTXODiff) if err != nil { return err @@ -51,14 +62,20 @@ func (csm *consensusStateManager) updateVirtual(newBlockHash *externalapi.Domain func (csm *consensusStateManager) updateVirtualDiffParents( newBlockHash *externalapi.DomainHash, virtualUTXODiff *model.UTXODiff) error { + log.Tracef("updateVirtualDiffParents start for block %s", newBlockHash) + defer log.Tracef("updateVirtualDiffParents end for block %s", newBlockHash) + var newVirtualDiffParents []*externalapi.DomainHash if *newBlockHash == *csm.genesisHash { + log.Tracef("Block %s is the genesis, so by definition "+ + "it is the only member of the new virtual diff parents set", newBlockHash) newVirtualDiffParents = []*externalapi.DomainHash{newBlockHash} } else { oldVirtualDiffParents, err := csm.consensusStateStore.VirtualDiffParents(csm.databaseContext) if err != nil { return err } + log.Tracef("The old virtual's diff parents are: %s", oldVirtualDiffParents) // If the status of the new block is not `Valid` - virtualDiffParents didn't change status, err := csm.blockStatusStore.Get(csm.databaseContext, newBlockHash) @@ -66,8 +83,11 @@ func (csm *consensusStateManager) updateVirtualDiffParents( return err } if status != externalapi.StatusValid { + log.Tracef("The status of the new block %s is non-valid. "+ + "As such, don't change the diff parents of the virtual", newBlockHash) newVirtualDiffParents = oldVirtualDiffParents } else { + log.Tracef("Block %s is valid. Updating the virtual diff parents", newBlockHash) newBlockParentsSlice, err := csm.dagTopologyManager.Parents(newBlockHash) if err != nil { return err @@ -82,8 +102,10 @@ func (csm *consensusStateManager) updateVirtualDiffParents( } } } + log.Tracef("The new virtual diff parents are: %s", newVirtualDiffParents) for _, virtualDiffParent := range newVirtualDiffParents { + log.Tracef("Calculating new UTXO diff for virtual diff parent %s", virtualDiffParent) virtualDiffParentUTXODiff, err := csm.utxoDiffStore.UTXODiff(csm.databaseContext, virtualDiffParent) if err != nil { return err @@ -92,11 +114,13 @@ func (csm *consensusStateManager) updateVirtualDiffParents( if err != nil { return err } + log.Tracef("Staging new UTXO diff for virtual diff parent %s: %s", virtualDiffParent, newDiff) err = csm.utxoDiffStore.Stage(virtualDiffParent, newDiff, nil) if err != nil { return err } } + log.Tracef("Staging the new virtual UTXO diff parents") return csm.consensusStateStore.StageVirtualDiffParents(newVirtualDiffParents) } diff --git a/domain/consensus/processes/consensusstatemanager/verify_and_build_utxo.go b/domain/consensus/processes/consensusstatemanager/verify_and_build_utxo.go index 2b7b72b20..0b6966209 100644 --- a/domain/consensus/processes/consensusstatemanager/verify_and_build_utxo.go +++ b/domain/consensus/processes/consensusstatemanager/verify_and_build_utxo.go @@ -21,26 +21,38 @@ import ( func (csm *consensusStateManager) verifyUTXO(block *externalapi.DomainBlock, blockHash *externalapi.DomainHash, pastUTXODiff *model.UTXODiff, acceptanceData model.AcceptanceData, multiset model.Multiset) error { + log.Tracef("verifyUTXO start for block %s", blockHash) + defer log.Tracef("verifyUTXO end for block %s", blockHash) + + log.Tracef("Validating UTXO commitment for block %s", blockHash) err := csm.validateUTXOCommitment(block, blockHash, multiset) if err != nil { return err } + log.Tracef("UTXO commitment validation passed for block %s", blockHash) + log.Tracef("Validating acceptedIDMerkleRoot for block %s", blockHash) err = csm.validateAcceptedIDMerkleRoot(block, blockHash, acceptanceData) if err != nil { return err } + log.Tracef("AcceptedIDMerkleRoot validation passed for block %s", blockHash) coinbaseTransaction := block.Transactions[0] + log.Tracef("Validating coinbase transaction %s for block %s", + consensusserialization.TransactionID(coinbaseTransaction), blockHash) err = csm.validateCoinbaseTransaction(blockHash, coinbaseTransaction) if err != nil { return err } + log.Tracef("Coinbase transaction validation passed for block %s", blockHash) + log.Tracef("Validating transactions against past UTXO for block %s", blockHash) err = csm.validateBlockTransactionsAgainstPastUTXO(block, blockHash, pastUTXODiff, err) if err != nil { return err } + log.Tracef("Transactions against past UTXO validation passed for block %s", blockHash) return nil } @@ -48,25 +60,38 @@ func (csm *consensusStateManager) verifyUTXO(block *externalapi.DomainBlock, blo func (csm *consensusStateManager) validateBlockTransactionsAgainstPastUTXO(block *externalapi.DomainBlock, blockHash *externalapi.DomainHash, pastUTXODiff *model.UTXODiff, err error) error { + log.Tracef("validateBlockTransactionsAgainstPastUTXO start for block %s", blockHash) + defer log.Tracef("validateBlockTransactionsAgainstPastUTXO end for block %s", blockHash) + selectedParentMedianTime, err := csm.pastMedianTimeManager.PastMedianTime(blockHash) if err != nil { return err } + log.Tracef("The past median time of %s is %d", blockHash, selectedParentMedianTime) for i, transaction := range block.Transactions { + transactionID := consensusserialization.TransactionID(transaction) + log.Tracef("Validating transaction %s in block %s against "+ + "the block's past UTXO", transactionID, blockHash) if i == transactionhelper.CoinbaseTransactionIndex { + log.Tracef("Skipping transaction %s because it is the coinbase", transactionID) continue } + + log.Tracef("Populating transaction %s with UTXO entries", transactionID) err = csm.populateTransactionWithUTXOEntriesFromVirtualOrDiff(transaction, pastUTXODiff) if err != nil { return err } + log.Tracef("Validating transaction %s and populating it with mass and fee", transactionID) err = csm.transactionValidator.ValidateTransactionInContextAndPopulateMassAndFee( transaction, blockHash, selectedParentMedianTime) if err != nil { return err } + log.Tracef("Validation against the block's past UTXO "+ + "passed for transaction %s in block %s", transactionID, blockHash) } return nil } @@ -74,6 +99,9 @@ func (csm *consensusStateManager) validateBlockTransactionsAgainstPastUTXO(block func (csm *consensusStateManager) validateAcceptedIDMerkleRoot(block *externalapi.DomainBlock, blockHash *externalapi.DomainHash, acceptanceData model.AcceptanceData) error { + log.Tracef("validateAcceptedIDMerkleRoot start for block %s", blockHash) + defer log.Tracef("validateAcceptedIDMerkleRoot end for block %s", blockHash) + calculatedAcceptedIDMerkleRoot := calculateAcceptedIDMerkleRoot(acceptanceData) if block.Header.AcceptedIDMerkleRoot != *calculatedAcceptedIDMerkleRoot { return errors.Wrapf(ruleerrors.ErrBadMerkleRoot, "block %s accepted ID merkle root is invalid - block "+ @@ -87,6 +115,9 @@ func (csm *consensusStateManager) validateAcceptedIDMerkleRoot(block *externalap func (csm *consensusStateManager) validateUTXOCommitment( block *externalapi.DomainBlock, blockHash *externalapi.DomainHash, multiset model.Multiset) error { + log.Tracef("validateUTXOCommitment start for block %s", blockHash) + defer log.Tracef("validateUTXOCommitment end for block %s", blockHash) + multisetHash := multiset.Hash() if block.Header.UTXOCommitment != *multisetHash { return errors.Wrapf(ruleerrors.ErrBadUTXOCommitment, "block %s UTXO commitment is invalid - block "+ @@ -97,6 +128,9 @@ func (csm *consensusStateManager) validateUTXOCommitment( } func calculateAcceptedIDMerkleRoot(multiblockAcceptanceData model.AcceptanceData) *externalapi.DomainHash { + log.Tracef("calculateAcceptedIDMerkleRoot start") + defer log.Tracef("calculateAcceptedIDMerkleRoot end") + var acceptedTransactions []*externalapi.DomainTransaction for _, blockAcceptanceData := range multiblockAcceptanceData { @@ -117,11 +151,18 @@ func calculateAcceptedIDMerkleRoot(multiblockAcceptanceData model.AcceptanceData } func (csm *consensusStateManager) validateCoinbaseTransaction(blockHash *externalapi.DomainHash, coinbaseTransaction *externalapi.DomainTransaction) error { + + log.Tracef("validateCoinbaseTransaction start for block %s", blockHash) + defer log.Tracef("validateCoinbaseTransaction end for block %s", blockHash) + + log.Tracef("Extracting coinbase data for coinbase transaction %s in block %s", + consensusserialization.TransactionID(coinbaseTransaction), blockHash) _, coinbaseData, err := coinbase.ExtractCoinbaseDataAndBlueScore(coinbaseTransaction) if err != nil { return err } + log.Tracef("Calculating the expected coinbase transaction for the given coinbase data and block %s", blockHash) expectedCoinbaseTransaction, err := csm.coinbaseManager.ExpectedCoinbaseTransaction(blockHash, coinbaseData) if err != nil { return err @@ -129,6 +170,9 @@ func (csm *consensusStateManager) validateCoinbaseTransaction(blockHash *externa coinbaseTransactionHash := consensusserialization.TransactionHash(coinbaseTransaction) expectedCoinbaseTransactionHash := consensusserialization.TransactionHash(expectedCoinbaseTransaction) + log.Tracef("given coinbase hash: %s, expected coinbase hash: %s", + coinbaseTransactionHash, expectedCoinbaseTransactionHash) + if *coinbaseTransactionHash != *expectedCoinbaseTransactionHash { return errors.Wrap(ruleerrors.ErrBadCoinbaseTransaction, "coinbase transaction is not built as expected") }