Merge branch 'debugging' into enrfilter

.gitignore

@@ -64,3 +64,4 @@ testnet.g
 dist/
 /docker/networksimulator/docker-compose.yaml
 /docker/networksimulator/prometheus/prometheus.yml
+/docker/networksimulator/.env

cmd/opera/main.go

@@ -2,12 +2,15 @@ package main
 
 import (
 	"fmt"
+	"github.com/ethereum/go-ethereum/log"
 	"os"
 
 	"github.com/Fantom-foundation/go-opera/cmd/opera/launcher"
 )
 
 func main() {
+	log.Root().SetHandler(log.LvlFilterHandler(log.LvlInfo, log.StreamHandler(os.Stdout, log.TerminalFormat(true))))
+
 	if err := launcher.Launch(os.Args); err != nil {
 		fmt.Fprintln(os.Stderr, err)
 		os.Exit(1)

docker/networksimulator/requirements.txt

@@ -1,2 +1,3 @@
 jinja2
 web3
+dotenv

docker/networksimulator/txblaster.py

@@ -65,7 +65,7 @@ def generate_accounts(self, num_accounts: int, menmonic: str, fund_value: int):
                 tx_hashes.append(tx_hash)
             accounts.append(acc)
         for tx_hash in tx_hashes:
-            self.web3.eth.wait_for_transaction_receipt(tx_hash)
+            self.web3.eth.wait_for_transaction_receipt(tx_hash, timeout=60000)
         return accounts
 
     def run_transactions(self, private_key, args):
@@ -104,7 +104,7 @@ def run_transactions(self, private_key, args):
                 continue
 
             start_time = time()
-            self.web3.eth.wait_for_transaction_receipt(tx_hash)
+            self.web3.eth.wait_for_transaction_receipt(tx_hash, timeout=60000)
             logging.info("tx confirmed tx_receipt=%s time=%f", tx_hash.hex(), time() - start_time)
 
     def sig_int(self, signum, frame):

ethapi/api.go

@@ -22,6 +22,7 @@ import (
 	"fmt"
 	"math/big"
 	"math/rand"
+	"os"
 	"time"
 
 	"github.com/Fantom-foundation/lachesis-base/hash"
@@ -2122,6 +2123,12 @@ func (api *PrivateDebugAPI) ChaindbProperty(property string) (string, error) {
 	return api.b.ChainDb().Stat(property)
 }
 
+// Verbosity sets the log level of the node.
+func (api *PrivateDebugAPI) Verbosity(level int) {
+	log.Info("Setting log level", "level", log.Lvl(level).String())
+	log.Root().SetHandler(log.LvlFilterHandler(log.Lvl(level), log.StreamHandler(os.Stdout, log.TerminalFormat(true))))
+}
+
 // ChaindbCompact flattens the entire key-value database into a single level,
 // removing all unused slots and merging all keys.
 func (api *PrivateDebugAPI) ChaindbCompact() error {

gossip/emitter/control.go

@@ -1,6 +1,7 @@
 package emitter
 
 import (
+	"github.com/ethereum/go-ethereum/metrics"
 	"time"
 
 	"github.com/Fantom-foundation/lachesis-base/emitter/ancestor"
@@ -11,6 +12,11 @@ import (
 	"github.com/Fantom-foundation/go-opera/inter"
 )
 
+var (
+	allowedToEmitCount    = metrics.GetOrRegisterGauge("opera/control/allowedToEmit", nil)
+	notAllowedToEmitCount = metrics.GetOrRegisterGauge("opera/control/notAllowedToEmit", nil)
+)
+
 func scalarUpdMetric(diff idx.Event, weight pos.Weight, totalWeight pos.Weight) ancestor.Metric {
 	return ancestor.Metric(scalarUpdMetricF(uint64(diff)*piecefunc.DecimalUnit)) * ancestor.Metric(weight) / ancestor.Metric(totalWeight)
 }
@@ -73,6 +79,7 @@ func (em *Emitter) isAllowedToEmit(e inter.EventI, eTxs bool, metric ancestor.Me
 					"power", e.GasPowerLeft().String(),
 					"selfParentPower", selfParent.GasPowerLeft().String(),
 					"stake%", 100*float64(em.validators.Get(e.Creator()))/float64(em.validators.TotalWeight()))
+				notAllowedToEmitCount.Inc(1)
 				return false
 			}
 		}
@@ -87,6 +94,7 @@ func (em *Emitter) isAllowedToEmit(e inter.EventI, eTxs bool, metric ancestor.Me
 		if passedTime >= em.intervals.Max ||
 			passedBlocks >= maxBlocks*4/5 && metric >= piecefunc.DecimalUnit/2 ||
 			passedBlocks >= maxBlocks {
+			allowedToEmitCount.Inc(1)
 			return true
 		}
 	}
@@ -109,6 +117,7 @@ func (em *Emitter) isAllowedToEmit(e inter.EventI, eTxs bool, metric ancestor.Me
 		if passedTime < em.intervals.Max &&
 			em.idle() &&
 			!eTxs {
+			notAllowedToEmitCount.Inc(1)
 			return false
 		}
 	}
@@ -119,15 +128,18 @@ func (em *Emitter) isAllowedToEmit(e inter.EventI, eTxs bool, metric ancestor.Me
 		}
 		if adjustedPassedTime < em.intervals.Min &&
 			!em.idle() {
+			notAllowedToEmitCount.Inc(1)
 			return false
 		}
 		if adjustedPassedIdleTime < em.intervals.Confirming &&
 			!em.idle() &&
 			!eTxs {
+			notAllowedToEmitCount.Inc(1)
 			return false
 		}
 	}
 
+	allowedToEmitCount.Inc(1)
 	return true
 }
 

gossip/emitter/emitter.go

@@ -31,6 +31,9 @@ const (
 )
 
 var eventCounter = metrics.GetOrRegisterCounter("opera/events", nil)
+var callCreatedCounter = metrics.GetOrRegisterCounter("opera/events/callCreated", nil)
+var callEmitCounter = metrics.GetOrRegisterCounter("opera/events/callEmit", nil)
+var worldBusyGauge = metrics.GetOrRegisterGauge("opera/events/worldBusy", nil)
 
 type Emitter struct {
 	config Config
@@ -189,7 +192,10 @@ func (em *Emitter) tick() {
 		em.busyRate.Mark(1)
 	}
 	if em.world.IsBusy() {
+		worldBusyGauge.Update(1)
 		return
+	} else {
+		worldBusyGauge.Update(0)
 	}
 
 	em.recheckChallenges()
@@ -233,6 +239,8 @@ func (em *Emitter) EmitEvent() (*inter.EventPayload, error) {
 		// short circuit if not a validator
 		return nil, nil
 	}
+	callEmitCounter.Inc(1)
+
 	sortedTxs := em.getSortedTxs()
 
 	if em.world.IsBusy() {
@@ -295,6 +303,7 @@ func (em *Emitter) createEvent(sortedTxs *types.TransactionsByPriceAndNonce) (*i
 	if !em.isValidator() {
 		return nil, nil
 	}
+	callCreatedCounter.Inc(1)
 
 	if synced := em.logSyncStatus(em.isSyncedToEmit()); !synced {
 		// I'm reindexing my old events, so don't create events until connect all the existing self-events

gossip/emitter/txs.go

@@ -1,6 +1,8 @@
 package emitter
 
 import (
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"time"
 
 	"github.com/Fantom-foundation/lachesis-base/common/bigendian"
@@ -24,6 +26,19 @@ const (
 	TxTurnNonces        = 32
 )
 
+var (
+	outOfGasPowerCounter        = metrics.GetOrRegisterCounter("opera/txs/outOfGasPower", nil)
+	conflictedOriginatedCounter = metrics.GetOrRegisterCounter("opera/txs/conflictedOriginated", nil)
+	isMyTurnCounter             = metrics.GetOrRegisterCounter("opera/txs/isMyTurn", nil)
+	isNotMyTurnCounter          = metrics.GetOrRegisterCounter("opera/txs/isNotMyTurn", nil)
+	outdatedCounter             = metrics.GetOrRegisterCounter("opera/txs/outdated", nil)
+	invalidTxCounter            = metrics.GetOrRegisterCounter("opera/txs/invalidTxCounter", nil)
+
+	gasPowerUsedGauge      = metrics.GetOrRegisterGauge("opera/txs/gasPowerUsed", nil)
+	gasPowerLeftShortGauge = metrics.GetOrRegisterGauge("opera/txs/gasPowerLeftShort", nil)
+	gasPowerLeftLongGauge  = metrics.GetOrRegisterGauge("opera/txs/gasPowerLeftLong", nil)
+)
+
 func max64(a, b uint64) uint64 {
 	if a > b {
 		return a
@@ -123,6 +138,10 @@ func (em *Emitter) isMyTxTurn(txHash common.Hash, sender common.Address, account
 
 	roundsHash := hash.Of(sender.Bytes(), bigendian.Uint64ToBytes(accountNonce/TxTurnNonces), epoch.Bytes())
 	rounds := utils.WeightedPermutation(roundIndex+1, validators.SortedWeights(), roundsHash)
+
+	chosen := validators.GetID(idx.Validator(rounds[roundIndex]))
+	log.Debug("tx turn", "roundIndex", roundIndex, "rounds", rounds, "chosen", chosen, "me", me, "txTime", txTime, "now", now, "txHash", txHash, "sender", sender, "accountNonce", accountNonce, "epoch", epoch)
+
 	return validators.GetID(idx.Validator(rounds[roundIndex])) == me
 }
 
@@ -138,11 +157,14 @@ func (em *Emitter) addTxs(e *inter.MutableEventPayload, sorted *types.Transactio
 		sender, _ := types.Sender(em.world.TxSigner, tx)
 		// check transaction epoch rules
 		if epochcheck.CheckTxs(types.Transactions{tx}, rules) != nil {
+			invalidTxCounter.Inc(1)
 			sorted.Pop()
 			continue
 		}
 		// check there's enough gas power to originate the transaction
 		if tx.Gas() >= e.GasPowerLeft().Min() || e.GasPowerUsed()+tx.Gas() >= maxGasUsed {
+			log.Debug("not enough gas power to originate the transaction")
+			outOfGasPowerCounter.Inc(1)
 			if params.TxGas >= e.GasPowerLeft().Min() || e.GasPowerUsed()+params.TxGas >= maxGasUsed {
 				// stop if cannot originate even an empty transaction
 				break
@@ -152,22 +174,38 @@ func (em *Emitter) addTxs(e *inter.MutableEventPayload, sorted *types.Transactio
 		}
 		// check not conflicted with already originated txs (in any connected event)
 		if em.originatedTxs.TotalOf(sender) != 0 {
+			conflictedOriginatedCounter.Inc(1)
+			log.Debug("conflicted with already originated txs")
 			sorted.Pop()
 			continue
 		}
 		// my turn, i.e. try to not include the same tx simultaneously by different validators
 		if !em.isMyTxTurn(tx.Hash(), sender, tx.Nonce(), time.Now(), em.validators, e.Creator(), em.epoch) {
 			sorted.Pop()
+			isNotMyTurnCounter.Inc(1)
 			continue
+		} else {
+			isMyTurnCounter.Inc(1)
 		}
+
 		// check transaction is not outdated
 		if !em.world.TxPool.Has(tx.Hash()) {
+			outdatedCounter.Inc(1)
 			sorted.Pop()
+			log.Debug("transaction is outdated")
 			continue
 		}
+		gasPowerUsed := e.GasPowerUsed() + tx.Gas()
+		gasPowerLeft := e.GasPowerLeft().Sub(tx.Gas())
+		log.Debug("gas power", "used", gasPowerUsed, "left", gasPowerLeft)
+
+		gasPowerUsedGauge.Update(int64(gasPowerUsed))
+		gasPowerLeftShortGauge.Update(int64(gasPowerLeft.Gas[inter.ShortTermGas]))
+		gasPowerLeftLongGauge.Update(int64(gasPowerLeft.Gas[inter.LongTermGas]))
+
 		// add
-		e.SetGasPowerUsed(e.GasPowerUsed() + tx.Gas())
-		e.SetGasPowerLeft(e.GasPowerLeft().Sub(tx.Gas()))
+		e.SetGasPowerUsed(gasPowerUsed)
+		e.SetGasPowerLeft(gasPowerLeft)
 		e.SetTxs(append(e.Txs(), tx))
 		sorted.Shift()
 	}

gossip/emitter/validators.go

@@ -1,6 +1,8 @@
 package emitter
 
 import (
+	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"time"
 
 	"github.com/Fantom-foundation/lachesis-base/inter/idx"
@@ -12,6 +14,10 @@ const (
 	validatorChallenge = 4 * time.Second
 )
 
+var (
+	offlineValidatorsGauge = metrics.GetOrRegisterGauge("opera/validators/offline", nil)
+)
+
 func (em *Emitter) recountConfirmingIntervals(validators *pos.Validators) {
 	// validators with lower stake should emit fewer events to reduce network load
 	// confirmingEmitInterval = piecefunc(totalStakeBeforeMe / totalStake) * MinEmitInterval
@@ -55,6 +61,7 @@ func (em *Emitter) recheckChallenges() {
 	recount := false
 	for vid, challengeDeadline := range em.challenges {
 		if now.After(challengeDeadline) {
+			log.Debug("validator is offline", "validator", vid)
 			em.offlineValidators[vid] = true
 			recount = true
 		}
@@ -63,4 +70,8 @@ func (em *Emitter) recheckChallenges() {
 		em.recountConfirmingIntervals(em.validators)
 	}
 	em.prevRecheckedChallenges = now
+
+	numOfOfflineVals := int64(len(em.offlineValidators))
+	log.Debug("offline validators", "num", numOfOfflineVals)
+	offlineValidatorsGauge.Update(numOfOfflineVals)
 }

logger/logger.go

@@ -47,3 +47,10 @@ func SetLevel(l string) {
 			lvl,
 			log.Root().GetHandler()))
 }
+
+func SetLevelInt(l log.Lvl) {
+	log.Root().SetHandler(
+		log.LvlFilterHandler(
+			l,
+			log.Root().GetHandler()))
+}