Merge pull request #8166 from onflow/bastian/log-traces

[Cadence VM] Improve re-execution tools

Author: turbolent

cmd/util/cmd/compare-cadence-vm/cmd.go

@@ -18,6 +18,7 @@ import (
 	"golang.org/x/sync/errgroup"
 
 	debug_tx "github.com/onflow/flow-go/cmd/util/cmd/debug-tx"
+	"github.com/onflow/flow-go/fvm"
 	"github.com/onflow/flow-go/model/flow"
 	"github.com/onflow/flow-go/module/grpcclient"
 	"github.com/onflow/flow-go/utils/debug"
@@ -31,6 +32,7 @@ var (
 	flagUseExecutionDataAPI bool
 	flagBlockIDs            string
 	flagBlockCount          int
+	flagLogTraces           bool
 	flagWriteTraces         bool
 	flagParallel            int
 )
@@ -65,6 +67,8 @@ func init() {
 
 	Cmd.Flags().IntVar(&flagBlockCount, "block-count", 1, "number of blocks to process (default: 1). if > 1, provide a single block ID with --block-ids")
 
+	Cmd.Flags().BoolVar(&flagLogTraces, "log-traces", false, "log traces")
+
 	Cmd.Flags().BoolVar(&flagWriteTraces, "write-traces", false, "write traces for mismatched transactions")
 
 	Cmd.Flags().IntVar(&flagParallel, "parallel", 1, "number of blocks to process in parallel (default: 1)")
@@ -210,6 +214,12 @@ func compareBlock(
 
 	interBlockSnapshot := debug_tx.NewBlockSnapshot(remoteClient, header)
 
+	fvmOptions := []fvm.Option{
+		fvm.WithEntropyProvider(debug_tx.BlockHashEntropyProvider{
+			BlockHash: blockID,
+		}),
+	}
+
 	var (
 		interSpanExporters []*debug.InterestingCadenceSpanExporter
 		interTxSnapshots   []*debug.CapturingStorageSnapshot
@@ -228,11 +238,14 @@ func compareBlock(
 			return txSnapshot
 		},
 		func(_ flow.Identifier) otelTrace.SpanExporter {
-			exporter := &debug.InterestingCadenceSpanExporter{}
+			exporter := &debug.InterestingCadenceSpanExporter{
+				Log: flagLogTraces,
+			}
 			interSpanExporters = append(interSpanExporters, exporter)
 			return exporter
 		},
 		flagComputeLimit,
+		fvmOptions,
 	)
 
 	log.Info().Msg("Running with VM ...")
@@ -257,11 +270,14 @@ func compareBlock(
 			return txSnapshot
 		},
 		func(_ flow.Identifier) otelTrace.SpanExporter {
-			exporter := &debug.InterestingCadenceSpanExporter{}
+			exporter := &debug.InterestingCadenceSpanExporter{
+				Log: flagLogTraces,
+			}
 			vmSpanExporters = append(vmSpanExporters, exporter)
 			return exporter
 		},
 		flagComputeLimit,
+		fvmOptions,
 	)
 
 	var mismatch bool

cmd/util/cmd/debug-tx/cmd.go

@@ -31,7 +31,9 @@ var (
 	flagBlockID             string
 	flagUseVM               bool
 	flagTracePath           string
+	flagLogTraces           bool
 	flagOnlyTraceCadence    bool
+	flagEntropyProvider     string
 )
 
 var Cmd = &cobra.Command{
@@ -67,7 +69,11 @@ func init() {
 
 	Cmd.Flags().StringVar(&flagTracePath, "trace", "", "enable tracing to given path")
 
+	Cmd.Flags().BoolVar(&flagLogTraces, "log-cadence-traces", false, "log Cadence traces. requires --trace and --only-trace-cadence to be set (default: false)")
+
 	Cmd.Flags().BoolVar(&flagOnlyTraceCadence, "only-trace-cadence", false, "when tracing, only include spans related to Cadence execution (default: false)")
+
+	Cmd.Flags().StringVar(&flagEntropyProvider, "entropy-provider", "none", "entropy provider to use (default: none; options: none, block-hash)")
 }
 
 func run(_ *cobra.Command, args []string) {
@@ -112,7 +118,9 @@ func run(_ *cobra.Command, args []string) {
 	var spanExporter otelTrace.SpanExporter
 	if traceFile != nil {
 		if flagOnlyTraceCadence {
-			cadenceSpanExporter := &debug.InterestingCadenceSpanExporter{}
+			cadenceSpanExporter := &debug.InterestingCadenceSpanExporter{
+				Log: flagLogTraces,
+			}
 			defer func() {
 				err = cadenceSpanExporter.WriteSpans(traceFile)
 				if err != nil {
@@ -169,6 +177,7 @@ func run(_ *cobra.Command, args []string) {
 			nil,
 			newSpanExporter,
 			flagComputeLimit,
+			fvmOptions(blockID),
 		)
 
 		if flagShowResult {
@@ -215,6 +224,22 @@ func run(_ *cobra.Command, args []string) {
 	}
 }
 
+func fvmOptions(blockID flow.Identifier) []fvm.Option {
+	var options []fvm.Option
+
+	switch flagEntropyProvider {
+	case "block-hash":
+		options = append(
+			options,
+			fvm.WithEntropyProvider(BlockHashEntropyProvider{
+				BlockHash: blockID,
+			}),
+		)
+	}
+
+	return options
+}
+
 func RunSingleTransaction(
 	remoteClient debug.RemoteClient,
 	txID flow.Identifier,
@@ -268,6 +293,7 @@ func RunSingleTransaction(
 		nil,
 		newSpanExporter,
 		computeLimit,
+		fvmOptions(blockID),
 	)
 
 	for i, blockTx := range blockTransactions {
@@ -359,6 +385,7 @@ func RunBlock(
 	wrapTxSnapshot func(blockTxID flow.Identifier, snapshot debug.UpdatableStorageSnapshot) debug.UpdatableStorageSnapshot,
 	newSpanExporter func(blockTxID flow.Identifier) otelTrace.SpanExporter,
 	computeLimit uint64,
+	additionalFVMOptions []fvm.Option,
 ) (
 	results []debug.Result,
 ) {
@@ -390,6 +417,7 @@ func RunBlock(
 			useVM,
 			spanExporter,
 			computeLimit,
+			additionalFVMOptions,
 		)
 
 		updatedRegisters := result.Snapshot.UpdatedRegisters()
@@ -419,6 +447,7 @@ func RunTransaction(
 	useVM bool,
 	spanExporter otelTrace.SpanExporter,
 	computeLimit uint64,
+	additionalFVMOptions []fvm.Option,
 ) debug.Result {
 
 	log := log.With().
@@ -452,6 +481,8 @@ func RunTransaction(
 		)
 	}
 
+	fvmOptions = append(fvmOptions, additionalFVMOptions...)
+
 	debugger := debug.NewRemoteDebugger(
 		chain,
 		log,
@@ -479,3 +510,14 @@ func RunTransaction(
 
 	return result
 }
+
+// BlockHashEntropyProvider implements environment.EntropyProvider
+// which provides a source of entropy to fvm context (required for Cadence's randomness),
+// by using the given block hash.
+type BlockHashEntropyProvider struct {
+	BlockHash flow.Identifier
+}
+
+func (p BlockHashEntropyProvider) RandomSource() ([]byte, error) {
+	return p.BlockHash[:], nil
+}

fvm/environment/programs.go

@@ -5,6 +5,7 @@ import (
 
 	"github.com/hashicorp/go-multierror"
 	"github.com/onflow/cadence/runtime"
+	"go.opentelemetry.io/otel/attribute"
 	"golang.org/x/xerrors"
 
 	"github.com/onflow/cadence"
@@ -91,7 +92,16 @@ func (programs *Programs) GetOrLoadProgram(
 	location common.Location,
 	load func() (*runtime.Program, error),
 ) (*runtime.Program, error) {
-	defer programs.tracer.StartChildSpan(trace.FVMEnvGetOrLoadProgram).End()
+	span := programs.tracer.StartChildSpan(trace.FVMEnvGetOrLoadProgram)
+	defer func() {
+		if span.Tracer != nil {
+			span.SetAttributes(
+				attribute.String("location", location.ID()),
+			)
+		}
+		span.End()
+	}()
+
 	err := programs.meter.MeterComputation(
 		common.ComputationUsage{
 			Kind:      ComputationKindGetOrLoadProgram,

utils/debug/cadence.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 	"io"
+	"os"
 	"slices"
 	"strings"
 
@@ -14,6 +15,7 @@ import (
 
 type InterestingCadenceSpanExporter struct {
 	Spans []otelTrace.ReadOnlySpan
+	Log   bool
 }
 
 var _ otelTrace.SpanExporter = &InterestingCadenceSpanExporter{}
@@ -23,6 +25,7 @@ var interestingSpanNamePrefixes = []trace.SpanName{
 	trace.FVMEnvAllocateSlabIndex,
 	trace.FVMEnvGetValue,
 	trace.FVMEnvSetValue,
+	trace.FVMEnvGetOrLoadProgram,
 }
 
 var uninterestingSpanNames = []trace.SpanName{
@@ -40,6 +43,14 @@ func (s *InterestingCadenceSpanExporter) ExportSpans(_ context.Context, spans []
 				!slices.Contains(uninterestingSpanNames, trace.SpanName(name)) {
 
 				s.Spans = append(s.Spans, span)
+
+				if s.Log {
+					err := writeSpan(os.Stderr, span)
+					if err != nil {
+						return err
+					}
+				}
+
 				break
 			}
 		}
@@ -53,26 +64,34 @@ func (s *InterestingCadenceSpanExporter) Shutdown(_ context.Context) error {
 
 func (s *InterestingCadenceSpanExporter) WriteSpans(writer io.Writer) error {
 	for _, span := range s.Spans {
-		_, err := fmt.Fprintf(writer, "- %s: ", span.Name())
+		err := writeSpan(writer, span)
 		if err != nil {
 			return err
 		}
-		for i, attr := range span.Attributes() {
-			if i > 0 {
-				_, err = fmt.Fprintf(writer, ", ")
-				if err != nil {
-					return err
-				}
-			}
-			_, err = fmt.Fprintf(writer, "%s=%v", attr.Key, attr.Value.AsInterface())
+	}
+	return nil
+}
+
+func writeSpan(writer io.Writer, span otelTrace.ReadOnlySpan) error {
+	_, err := fmt.Fprintf(writer, "- %s: ", span.Name())
+	if err != nil {
+		return err
+	}
+	for i, attr := range span.Attributes() {
+		if i > 0 {
+			_, err = fmt.Fprintf(writer, ", ")
 			if err != nil {
 				return err
 			}
 		}
-		_, err = fmt.Fprintln(writer)
+		_, err = fmt.Fprintf(writer, "%s=%v", attr.Key, attr.Value.AsInterface())
 		if err != nil {
 			return err
 		}
 	}
+	_, err = fmt.Fprintln(writer)
+	if err != nil {
+		return err
+	}
 	return nil
 }