manu's comments

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,37 +88,46 @@ 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")
+		log.WithFields(moreFields).Info("Synced new block")
+		return nil
 	} 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(lessFields).WithField(logs.LogTargetField, logs.LogTargetUser).Info("Synced new block")
+		log.WithFields(moreFields).WithField(logs.LogTargetField, logs.LogTargetEphemeral).Info("Synced new block")
+		return nil
 	}
-	return nil
 }
 
 // logs payload related data every slot.

changelog/bastin_fix-logging-issue.md

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

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"