Replace --debug parameter with --logLevel; trim debug logs (#133)

This moves some of the wordier debug logs to trace-level and replaces the `--debug` parameter with a `--logLevel` so that callers that want trace-level logs can access them.

Author: FGasper

README.md

@@ -139,7 +139,7 @@ The verifier will now check to completion to make sure that there are no inconsi
 | `--clean`                               | If set, drop all previous verification metadata before starting                                                                                                                             |
 | `--readPreference <value>`              | Read preference for reading data from clusters. May be 'primary', 'secondary', 'primaryPreferred', 'secondaryPreferred', or 'nearest' (default: "primary")                                  |
 | `--partitionSizeMB <Megabytes>`         | Megabytes to use for a partition.  Change only for debugging. 0 means use partitioner default. (default: 0)                                                                                 |
-| `--debug`                               | Turn on debug logging                                                                                                                                                                       |
+| `--logLevel`                               | Set the logging to `info`, `debug`, or `trace` level.                                                                                                                                                                       |
 | `--checkOnly`                           | Do not run the webserver or recheck, just run the check (for debugging)                                                                                                                     |
 | `--failureDisplaySize <value>`          | Number of failures to display. Will display all failures if the number doesn’t exceed this limit by 25% (default: 20)                                                                       |
 | `--ignoreReadConcern`                   | Use connection-default read concerns rather than setting majority read concern. This option may degrade consistency, so only enable it if majority read concern (the default) doesn’t work. |

internal/verifier/change_stream.go

@@ -263,7 +263,7 @@ func (verifier *Verifier) HandleChangeStreamEvents(ctx context.Context, batch ch
 	latestTimestampTime := time.Unix(int64(latestTimestamp.T), 0)
 	lag := time.Unix(int64(batch.clusterTime.T), 0).Sub(latestTimestampTime)
 
-	verifier.logger.Debug().
+	verifier.logger.Trace().
 		Str("origin", string(eventOrigin)).
 		Int("count", len(docIDs)).
 		Any("latestTimestamp", latestTimestamp).

internal/verifier/compare.go

@@ -656,20 +656,20 @@ func (verifier *Verifier) getDocumentsCursor(ctx mongo.SessionContext, collectio
 	// Suppress this log for recheck tasks because the list of IDs can be
 	// quite long.
 	if !task.IsRecheck() {
+		if verifier.logger.Trace().Enabled() {
+			evt := verifier.logger.Trace().
+				Any("task", task.PrimaryKey)
 
-		evt := verifier.logger.Debug().
-			Any("task", task.PrimaryKey)
+			cmdStr, err := bson.MarshalExtJSON(cmd, true, false)
+			if err != nil {
+				cmdStr = fmt.Appendf(nil, "%s", cmd)
+			}
 
-		extJSON, err := bson.MarshalExtJSON(cmd, true, false)
-		if err != nil {
-			evt = evt.Str("cmd", fmt.Sprintf("%s", cmd))
-		} else {
-			evt = evt.RawJSON("cmd", extJSON)
+			evt.
+				Str("cmd", string(cmdStr)).
+				Str("options", fmt.Sprintf("%v", *runCommandOptions)).
+				Msg("getDocuments command.")
 		}
-
-		evt.
-			Str("options", fmt.Sprintf("%v", *runCommandOptions)).
-			Msg("getDocuments command.")
 	}
 
 	return collection.Database().RunCommandCursor(ctx, cmd, runCommandOptions)

internal/verifier/migration_verifier.go

@@ -457,7 +457,7 @@ func (verifier *Verifier) getGenerationWhileLocked() (int, bool) {
 
 func (verifier *Verifier) maybeAppendGlobalFilterToPredicates(predicates bson.A) bson.A {
 	if len(verifier.globalFilter) == 0 {
-		verifier.logger.Debug().Msg("No filter to append; globalFilter is nil")
+		verifier.logger.Trace().Msg("No filter to append; globalFilter is nil")
 		return predicates
 	}
 	verifier.logger.Debug().Str("filter", fmt.Sprintf("%v", verifier.globalFilter)).Msg("Appending filter to find query")

internal/verifier/recheck.go

@@ -169,7 +169,7 @@ func (verifier *Verifier) insertRecheckDocs(
 		)
 	}
 
-	verifier.logger.Debug().
+	verifier.logger.Trace().
 		Int("generation", generation).
 		Int("count", len(documentIDs)).
 		Msg("Persisted rechecks.")

main/migration_verifier.go

@@ -11,6 +11,7 @@ import (
 	"time"
 
 	"github.com/10gen/migration-verifier/internal/verifier"
+	"github.com/10gen/migration-verifier/mslices"
 	"github.com/pkg/errors"
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
@@ -39,7 +40,7 @@ const (
 	partitionSizeMB       = "partitionSizeMB"
 	recheckMaxSizeMB      = "recheckMaxSizeMB"
 	checkOnly             = "checkOnly"
-	debugFlag             = "debug"
+	logLevelFlag          = "logLevel"
 	failureDisplaySize    = "failureDisplaySize"
 	ignoreReadConcernFlag = "ignoreReadConcern"
 	configFileFlag        = "configFile"
@@ -52,6 +53,17 @@ const (
 var Revision = buildVarDefaultStr
 var BuildTime = buildVarDefaultStr
 
+var logLevelStrs = lo.Map(
+	mslices.Of(
+		zerolog.InfoLevel,
+		zerolog.DebugLevel,
+		zerolog.TraceLevel,
+	),
+	func(lv zerolog.Level, _ int) string {
+		return lv.String()
+	},
+)
+
 func main() {
 	zerolog.ErrorStackMarshaler = pkgerrors.MarshalStack
 
@@ -153,9 +165,10 @@ func main() {
 			Value: 0,
 			Usage: "`Megabytes` to use for a partition.  Change only for debugging. 0 means use partitioner default.",
 		}),
-		altsrc.NewBoolFlag(cli.BoolFlag{
-			Name:  debugFlag,
-			Usage: "Turn on debug logging",
+		altsrc.NewStringFlag(cli.StringFlag{
+			Name:  logLevelFlag,
+			Value: zerolog.InfoLevel.String(),
+			Usage: "Level of detail to include in logs. One of: " + strings.Join(logLevelStrs, ", "),
 		}),
 		altsrc.NewBoolFlag(cli.BoolFlag{
 			Name:  checkOnly,
@@ -196,9 +209,11 @@ func main() {
 			if err != nil {
 				return err
 			}
-			if cCtx.Bool(debugFlag) {
-				zerolog.SetGlobalLevel(zerolog.DebugLevel)
+
+			if err := handleLogLevelArg(cCtx); err != nil {
+				return err
 			}
+
 			if cCtx.Bool(checkOnly) {
 				err := verifier.WritesOff(ctx)
 				if err != nil {
@@ -217,6 +232,21 @@ func main() {
 	}
 }
 
+func handleLogLevelArg(cCtx *cli.Context) error {
+	logLevelStr := cCtx.String(logLevelFlag)
+	if !slices.Contains(logLevelStrs, logLevelStr) {
+		return errors.Errorf("invalid %#q", logLevelFlag)
+	}
+	logLevel, err := zerolog.ParseLevel(logLevelStr)
+	if err != nil {
+		return errors.Wrapf(err, "parsing %#q", logLevelFlag)
+	}
+
+	zerolog.SetGlobalLevel(logLevel)
+
+	return nil
+}
+
 func handleArgs(ctx context.Context, cCtx *cli.Context) (*verifier.Verifier, error) {
 	verifierSettings := verifier.VerifierSettings{}
 	if cCtx.Bool(ignoreReadConcernFlag) {