Fix gen-logs.sh - gitignore bug (#16328)

**What does this PR do? Why is it needed?**
`gen-logs.sh` was skipping `cmd/beacon-chain/execution/` due to a rule
in `.gitignore`.
Added a fix in `gen-logs.sh` to ignore `.gitignore` entries by
specification.

beacon-chain/blockchain/BUILD.bazel

@@ -85,6 +85,7 @@ go_library(
         "//consensus-types/primitives:go_default_library",
         "//crypto/bls:go_default_library",
         "//encoding/bytesutil:go_default_library",
+        "//io/logs:go_default_library",
         "//math:go_default_library",
         "//monitoring/tracing:go_default_library",
         "//monitoring/tracing/trace:go_default_library",

beacon-chain/blockchain/log_helpers.go

@@ -10,6 +10,7 @@ import (
 	consensus_types "github.com/OffchainLabs/prysm/v7/consensus-types"
 	"github.com/OffchainLabs/prysm/v7/consensus-types/interfaces"
 	"github.com/OffchainLabs/prysm/v7/encoding/bytesutil"
+	"github.com/OffchainLabs/prysm/v7/io/logs"
 	ethpb "github.com/OffchainLabs/prysm/v7/proto/prysm/v1alpha1"
 	"github.com/OffchainLabs/prysm/v7/runtime/version"
 	prysmTime "github.com/OffchainLabs/prysm/v7/time"
@@ -87,36 +88,45 @@ func logStateTransitionData(b interfaces.ReadOnlyBeaconBlock) error {
 func logBlockSyncStatus(block interfaces.ReadOnlyBeaconBlock, blockRoot [32]byte, justified, finalized *ethpb.Checkpoint, receivedTime time.Time, genesis time.Time, daWaitedTime time.Duration) error {
 	startTime, err := slots.StartTime(genesis, block.Slot())
 	if err != nil {
-		return err
+		return errors.Wrap(err, "failed to get slot start time")
 	}
-	level := log.Logger.GetLevel()
+	parentRoot := block.ParentRoot()
+	blkRoot := fmt.Sprintf("0x%s...", hex.EncodeToString(blockRoot[:])[:8])
+	finalizedRoot := fmt.Sprintf("0x%s...", hex.EncodeToString(finalized.Root)[:8])
+	sinceSlotStartTime := prysmTime.Now().Sub(startTime)
+
+	lessFields := logrus.Fields{
+		"slot":               block.Slot(),
+		"block":              blkRoot,
+		"finalizedEpoch":     finalized.Epoch,
+		"finalizedRoot":      finalizedRoot,
+		"epoch":              slots.ToEpoch(block.Slot()),
+		"sinceSlotStartTime": sinceSlotStartTime,
+	}
+	moreFields := logrus.Fields{
+		"slot":                       block.Slot(),
+		"slotInEpoch":                block.Slot() % params.BeaconConfig().SlotsPerEpoch,
+		"block":                      blkRoot,
+		"epoch":                      slots.ToEpoch(block.Slot()),
+		"justifiedEpoch":             justified.Epoch,
+		"justifiedRoot":              fmt.Sprintf("0x%s...", hex.EncodeToString(justified.Root)[:8]),
+		"finalizedEpoch":             finalized.Epoch,
+		"finalizedRoot":              finalizedRoot,
+		"parentRoot":                 fmt.Sprintf("0x%s...", hex.EncodeToString(parentRoot[:])[:8]),
+		"version":                    version.String(block.Version()),
+		"sinceSlotStartTime":         sinceSlotStartTime,
+		"chainServiceProcessedTime":  prysmTime.Now().Sub(receivedTime) - daWaitedTime,
+		"dataAvailabilityWaitedTime": daWaitedTime,
+	}
+
+	level := logs.PackageVerbosity("beacon-chain/blockchain")
 	if level >= logrus.DebugLevel {
-		parentRoot := block.ParentRoot()
-		lf := logrus.Fields{
-			"slot":                       block.Slot(),
-			"slotInEpoch":                block.Slot() % params.BeaconConfig().SlotsPerEpoch,
-			"block":                      fmt.Sprintf("0x%s...", hex.EncodeToString(blockRoot[:])[:8]),
-			"epoch":                      slots.ToEpoch(block.Slot()),
-			"justifiedEpoch":             justified.Epoch,
-			"justifiedRoot":              fmt.Sprintf("0x%s...", hex.EncodeToString(justified.Root)[:8]),
-			"finalizedEpoch":             finalized.Epoch,
-			"finalizedRoot":              fmt.Sprintf("0x%s...", hex.EncodeToString(finalized.Root)[:8]),
-			"parentRoot":                 fmt.Sprintf("0x%s...", hex.EncodeToString(parentRoot[:])[:8]),
-			"version":                    version.String(block.Version()),
-			"sinceSlotStartTime":         prysmTime.Now().Sub(startTime),
-			"chainServiceProcessedTime":  prysmTime.Now().Sub(receivedTime) - daWaitedTime,
-			"dataAvailabilityWaitedTime": daWaitedTime,
-		}
-		log.WithFields(lf).Debug("Synced new block")
-	} else {
-		log.WithFields(logrus.Fields{
-			"slot":           block.Slot(),
-			"block":          fmt.Sprintf("0x%s...", hex.EncodeToString(blockRoot[:])[:8]),
-			"finalizedEpoch": finalized.Epoch,
-			"finalizedRoot":  fmt.Sprintf("0x%s...", hex.EncodeToString(finalized.Root)[:8]),
-			"epoch":          slots.ToEpoch(block.Slot()),
-		}).Info("Synced new block")
+		log.WithFields(moreFields).Info("Synced new block")
+		return nil
 	}
+
+	log.WithFields(lessFields).WithField(logs.LogTargetField, logs.LogTargetUser).Info("Synced new block")
+	log.WithFields(moreFields).WithField(logs.LogTargetField, logs.LogTargetEphemeral).Info("Synced new block")
 	return nil
 }
 

beacon-chain/forkchoice/doubly-linked-tree/forkchoice.go

@@ -32,7 +32,6 @@ func New() *ForkChoice {
 		finalizedCheckpoint:           &forkchoicetypes.Checkpoint{},
 		proposerBoostRoot:             [32]byte{},
 		nodeByRoot:                    make(map[[fieldparams.RootLength]byte]*Node),
-		nodeByPayload:                 make(map[[fieldparams.RootLength]byte]*Node),
 		slashedIndices:                make(map[primitives.ValidatorIndex]bool),
 		receivedBlocksLastEpoch:       [fieldparams.SlotsPerEpoch]primitives.Slot{},
 	}

beacon-chain/forkchoice/doubly-linked-tree/optimistic_sync.go

@@ -94,6 +94,5 @@ func (s *Store) removeNodeAndChildren(ctx context.Context, node *Node, invalidRo
 		s.previousProposerBoostScore = 0
 	}
 	delete(s.nodeByRoot, node.root)
-	delete(s.nodeByPayload, node.payloadHash)
 	return invalidRoots, nil
 }

beacon-chain/forkchoice/doubly-linked-tree/store.go

@@ -113,7 +113,6 @@ func (s *Store) insert(ctx context.Context,
 		}
 	}
 
-	s.nodeByPayload[payloadHash] = n
 	s.nodeByRoot[root] = n
 	if parent == nil {
 		if s.treeRootNode == nil {
@@ -122,7 +121,6 @@ func (s *Store) insert(ctx context.Context,
 			s.highestReceivedNode = n
 		} else {
 			delete(s.nodeByRoot, root)
-			delete(s.nodeByPayload, payloadHash)
 			return nil, errInvalidParentRoot
 		}
 	} else {
@@ -191,7 +189,6 @@ func (s *Store) pruneFinalizedNodeByRootMap(ctx context.Context, node, finalized
 
 	node.children = nil
 	delete(s.nodeByRoot, node.root)
-	delete(s.nodeByPayload, node.payloadHash)
 	return nil
 }
 

beacon-chain/forkchoice/doubly-linked-tree/store_test.go

@@ -128,10 +128,9 @@ func TestStore_Insert(t *testing.T) {
 	// The new node does not have a parent.
 	treeRootNode := &Node{slot: 0, root: indexToHash(0)}
 	nodeByRoot := map[[32]byte]*Node{indexToHash(0): treeRootNode}
-	nodeByPayload := map[[32]byte]*Node{indexToHash(0): treeRootNode}
 	jc := &forkchoicetypes.Checkpoint{Epoch: 0}
 	fc := &forkchoicetypes.Checkpoint{Epoch: 0}
-	s := &Store{nodeByRoot: nodeByRoot, treeRootNode: treeRootNode, nodeByPayload: nodeByPayload, justifiedCheckpoint: jc, finalizedCheckpoint: fc, highestReceivedNode: &Node{}}
+	s := &Store{nodeByRoot: nodeByRoot, treeRootNode: treeRootNode, justifiedCheckpoint: jc, finalizedCheckpoint: fc, highestReceivedNode: &Node{}}
 	payloadHash := [32]byte{'a'}
 	ctx := t.Context()
 	_, blk, err := prepareForkchoiceState(ctx, 100, indexToHash(100), indexToHash(0), payloadHash, 1, 1)
@@ -238,7 +237,6 @@ func TestStore_Prune_NoDanglingBranch(t *testing.T) {
 	s.finalizedCheckpoint.Root = indexToHash(1)
 	require.NoError(t, s.prune(t.Context()))
 	require.Equal(t, len(s.nodeByRoot), 1)
-	require.Equal(t, len(s.nodeByPayload), 1)
 }
 
 // This test starts with the following branching diagram
@@ -319,8 +317,6 @@ func TestStore_PruneMapsNodes(t *testing.T) {
 	s.finalizedCheckpoint.Root = indexToHash(1)
 	require.NoError(t, s.prune(t.Context()))
 	require.Equal(t, len(s.nodeByRoot), 1)
-	require.Equal(t, len(s.nodeByPayload), 1)
-
 }
 
 func TestForkChoice_ReceivedBlocksLastEpoch(t *testing.T) {

beacon-chain/forkchoice/doubly-linked-tree/types.go

@@ -36,7 +36,6 @@ type Store struct {
 	treeRootNode                  *Node                                  // the root node of the store tree.
 	headNode                      *Node                                  // last head Node
 	nodeByRoot                    map[[fieldparams.RootLength]byte]*Node // nodes indexed by roots.
-	nodeByPayload                 map[[fieldparams.RootLength]byte]*Node // nodes indexed by payload Hash
 	slashedIndices                map[primitives.ValidatorIndex]bool     // the list of equivocating validator indices
 	originRoot                    [fieldparams.RootLength]byte           // The genesis block root
 	genesisTime                   time.Time

changelog/bastin_fix-logging-issue.md

@@ -0,0 +1,3 @@
+### Changed
+
+- Fixed the logging issue described in #16314.

changelog/potuz_remove_unused_map.md

@@ -0,0 +1,2 @@
+### Ignored
+- Remove unused map in forkchoice.

cmd/beacon-chain/execution/log.go

@@ -0,0 +1,9 @@
+// Code generated by hack/gen-logs.sh; DO NOT EDIT.
+// This file is created and regenerated automatically. Anything added here might get removed.
+package execution
+
+import "github.com/sirupsen/logrus"
+
+// The prefix for logs from this package will be the text after the last slash in the package path.
+// If you wish to change this, you should add your desired name in the runtime/logging/logrus-prefixed-formatter/prefix-replacement.go file.
+var log = logrus.WithField("package", "cmd/beacon-chain/execution")

cmd/beacon-chain/main.go

@@ -188,8 +188,8 @@ func before(ctx *cli.Context) error {
 		return errors.Wrap(err, "failed to parse log vmodule")
 	}
 
-	// set the global logging level to allow for the highest verbosity requested
-	logs.SetLoggingLevel(max(verbosityLevel, maxLevel))
+	// set the global logging level and data
+	logs.SetLoggingLevelAndData(verbosityLevel, vmodule, maxLevel, ctx.Bool(flags.DisableEphemeralLogFile.Name))
 
 	format := ctx.String(cmd.LogFormat.Name)
 	switch format {
@@ -210,6 +210,7 @@ func before(ctx *cli.Context) error {
 			Formatter:     formatter,
 			Writer:        os.Stderr,
 			AllowedLevels: logrus.AllLevels[:max(verbosityLevel, maxLevel)+1],
+			Identifier:    logs.LogTargetUser,
 		})
 	case "fluentd":
 		f := joonix.NewFormatter()

cmd/validator/main.go

@@ -164,8 +164,8 @@ func main() {
 				return errors.Wrap(err, "failed to parse log vmodule")
 			}
 
-			// set the global logging level to allow for the highest verbosity requested
-			logs.SetLoggingLevel(max(maxLevel, verbosityLevel))
+			// set the global logging level and data
+			logs.SetLoggingLevelAndData(verbosityLevel, vmodule, maxLevel, ctx.Bool(flags.DisableEphemeralLogFile.Name))
 
 			logFileName := ctx.String(cmd.LogFileName.Name)
 
@@ -188,6 +188,7 @@ func main() {
 					Formatter:     formatter,
 					Writer:        os.Stderr,
 					AllowedLevels: logrus.AllLevels[:max(verbosityLevel, maxLevel)+1],
+					Identifier:    logs.LogTargetUser,
 				})
 			case "fluentd":
 				f := joonix.NewFormatter()

io/logs/hook.go

@@ -6,20 +6,28 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
+type HookIdentifier string
+
 type WriterHook struct {
 	AllowedLevels []logrus.Level
 	Writer        io.Writer
 	Formatter     logrus.Formatter
+	Identifier    HookIdentifier
 }
 
 func (hook *WriterHook) Levels() []logrus.Level {
-	if hook.AllowedLevels == nil || len(hook.AllowedLevels) == 0 {
+	if len(hook.AllowedLevels) == 0 {
 		return logrus.AllLevels
 	}
 	return hook.AllowedLevels
 }
 
 func (hook *WriterHook) Fire(entry *logrus.Entry) error {
+	val, ok := entry.Data[LogTargetField]
+	if ok && val != hook.Identifier {
+		return nil
+	}
+
 	line, err := hook.Formatter.Format(entry)
 	if err != nil {
 		return err

io/logs/logutil.go

@@ -17,11 +17,43 @@ import (
 	"gopkg.in/natefinch/lumberjack.v2"
 )
 
-var ephemeralLogFileVerbosity = logrus.DebugLevel
+var (
+	userVerbosity = logrus.InfoLevel
+	vmodule       = make(map[string]logrus.Level)
+)
 
-// SetLoggingLevel sets the base logging level for logrus.
-func SetLoggingLevel(lvl logrus.Level) {
-	logrus.SetLevel(max(lvl, ephemeralLogFileVerbosity))
+const (
+	ephemeralLogFileVerbosity                = logrus.DebugLevel
+	LogTargetField                           = "log_target"
+	LogTargetEphemeral        HookIdentifier = "ephemeral"
+	LogTargetUser             HookIdentifier = "user"
+)
+
+// SetLoggingLevelAndData sets the base logging level for logrus.
+func SetLoggingLevelAndData(baseVerbosity logrus.Level, vmoduleMap map[string]logrus.Level, maxVmoduleLevel logrus.Level, disableEphemeral bool) {
+	userVerbosity = baseVerbosity
+	vmodule = vmoduleMap
+
+	globalLevel := max(baseVerbosity, maxVmoduleLevel)
+	if !disableEphemeral {
+		globalLevel = max(globalLevel, ephemeralLogFileVerbosity)
+	}
+	logrus.SetLevel(globalLevel)
+}
+
+// PackageVerbosity returns the verbosity of a given package.
+func PackageVerbosity(packagePath string) logrus.Level {
+	bestLen := 0
+	bestLevel := userVerbosity
+	for k, v := range vmodule {
+		if k == packagePath || strings.HasPrefix(packagePath, k+"/") {
+			if len(k) > bestLen {
+				bestLen = len(k)
+				bestLevel = v
+			}
+		}
+	}
+	return bestLevel
 }
 
 func addLogWriter(w io.Writer) {
@@ -68,6 +100,7 @@ func ConfigurePersistentLogging(logFileName string, format string, lvl logrus.Le
 		Formatter:     formatter,
 		Writer:        f,
 		AllowedLevels: logrus.AllLevels[:max(lvl, maxVmoduleLevel)+1],
+		Identifier:    LogTargetUser,
 	})
 
 	logrus.Debug("File logging initialized")
@@ -101,6 +134,7 @@ func ConfigureEphemeralLogFile(datadirPath string, app string) error {
 		Formatter:     formatter,
 		Writer:        debugWriter,
 		AllowedLevels: logrus.AllLevels[:ephemeralLogFileVerbosity+1],
+		Identifier:    LogTargetEphemeral,
 	})
 
 	logrus.WithField("path", logFilePath).Debug("Ephemeral log file initialized")

runtime/logging/logrus-prefixed-formatter/formatter.go

@@ -334,7 +334,7 @@ func (f *TextFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys
 		_, err = fmt.Fprintf(b, "%s %s%s "+messageFormat, colorScheme.TimestampColor(timestamp), level, prefix, message)
 	}
 	for _, k := range keys {
-		if k != "package" {
+		if k != "package" && k != "log_target" {
 			v := entry.Data[k]
 
 			format := "%+v"