From 706b5a5bb5325fe42f43f67dd2c059d0e7dfb132 Mon Sep 17 00:00:00 2001 From: Faye Amacker <33205765+fxamacker@users.noreply.github.com> Date: Tue, 9 Jan 2024 13:27:27 -0600 Subject: [PATCH] Add flag for verbose validation error logging Added flag --log-verbose-validation-error to enable logging of entire Cadence values on validation error during atree migration. --- cmd/util/cmd/execution-state-extract/cmd.go | 32 ++-- .../execution_state_extract.go | 1 + .../migrations/atree_register_migration.go | 15 +- .../atree_register_migration_test.go | 2 +- .../migrations/cadence_value_validation.go | 159 ++++++++++++++---- .../cadence_value_validation_test.go | 113 ++++++++++++- 6 files changed, 260 insertions(+), 62 deletions(-) diff --git a/cmd/util/cmd/execution-state-extract/cmd.go b/cmd/util/cmd/execution-state-extract/cmd.go index 1f36fcb1634..b22ed8c5da3 100644 --- a/cmd/util/cmd/execution-state-extract/cmd.go +++ b/cmd/util/cmd/execution-state-extract/cmd.go @@ -15,16 +15,17 @@ import ( ) var ( - flagExecutionStateDir string - flagOutputDir string - flagBlockHash string - flagStateCommitment string - flagDatadir string - flagChain string - flagNWorker int - flagNoMigration bool - flagNoReport bool - flagValidateMigration bool + flagExecutionStateDir string + flagOutputDir string + flagBlockHash string + flagStateCommitment string + flagDatadir string + flagChain string + flagNWorker int + flagNoMigration bool + flagNoReport bool + flagValidateMigration bool + flagLogVerboseValidationError bool ) var Cmd = &cobra.Command{ @@ -62,7 +63,10 @@ func init() { Cmd.Flags().IntVar(&flagNWorker, "n-migrate-worker", 10, "number of workers to migrate payload concurrently") Cmd.Flags().BoolVar(&flagValidateMigration, "validate", false, - "validate migrated Cadence values") + "validate migrated Cadence values (atree migration)") + + Cmd.Flags().BoolVar(&flagLogVerboseValidationError, "log-verbose-validation-error", false, + "log entire Cadence values on validation error (atree migration)") } @@ -141,7 +145,11 @@ func run(*cobra.Command, []string) { } if flagValidateMigration { - log.Warn().Msgf("validation flag is enabled and will increase duration of migration") + log.Warn().Msgf("atree migration validation flag is enabled and will increase duration of migration") + } + + if flagLogVerboseValidationError { + log.Warn().Msgf("atree migration has verbose validation error logging enabled which may increase size of log") } err := extractExecutionState( diff --git a/cmd/util/cmd/execution-state-extract/execution_state_extract.go b/cmd/util/cmd/execution-state-extract/execution_state_extract.go index e2826654021..f379bc2f9ec 100644 --- a/cmd/util/cmd/execution-state-extract/execution_state_extract.go +++ b/cmd/util/cmd/execution-state-extract/execution_state_extract.go @@ -93,6 +93,7 @@ func extractExecutionState( migrators.NewAtreeRegisterMigrator( rwf, flagValidateMigration, + flagLogVerboseValidationError, ), &migrators.DeduplicateContractNamesMigration{}, diff --git a/cmd/util/ledger/migrations/atree_register_migration.go b/cmd/util/ledger/migrations/atree_register_migration.go index 5e4731f47a8..afb04e63f4f 100644 --- a/cmd/util/ledger/migrations/atree_register_migration.go +++ b/cmd/util/ledger/migrations/atree_register_migration.go @@ -36,7 +36,8 @@ type AtreeRegisterMigrator struct { nWorkers int - validateMigratedValues bool + validateMigratedValues bool + logVerboseValidationError bool } var _ AccountBasedMigration = (*AtreeRegisterMigrator)(nil) @@ -45,15 +46,17 @@ var _ io.Closer = (*AtreeRegisterMigrator)(nil) func NewAtreeRegisterMigrator( rwf reporters.ReportWriterFactory, validateMigratedValues bool, + logVerboseValidationError bool, ) *AtreeRegisterMigrator { sampler := util2.NewTimedSampler(30 * time.Second) migrator := &AtreeRegisterMigrator{ - sampler: sampler, - rwf: rwf, - rw: rwf.ReportWriter("atree-register-migrator"), - validateMigratedValues: validateMigratedValues, + sampler: sampler, + rwf: rwf, + rw: rwf.ReportWriter("atree-register-migrator"), + validateMigratedValues: validateMigratedValues, + logVerboseValidationError: logVerboseValidationError, } return migrator @@ -112,7 +115,7 @@ func (m *AtreeRegisterMigrator) MigrateAccount( } if m.validateMigratedValues { - err = validateCadenceValues(address, oldPayloads, newPayloads) + err = validateCadenceValues(address, oldPayloads, newPayloads, m.log, m.logVerboseValidationError) if err != nil { return nil, err } diff --git a/cmd/util/ledger/migrations/atree_register_migration_test.go b/cmd/util/ledger/migrations/atree_register_migration_test.go index 5d02926b857..da6d9f7fdfb 100644 --- a/cmd/util/ledger/migrations/atree_register_migration_test.go +++ b/cmd/util/ledger/migrations/atree_register_migration_test.go @@ -36,7 +36,7 @@ func TestAtreeRegisterMigration(t *testing.T) { migrations.CreateAccountBasedMigration(log, 2, []migrations.AccountBasedMigration{ validation.PreMigration(), - migrations.NewAtreeRegisterMigrator(reporters.NewReportFileWriterFactory(dir, log), true), + migrations.NewAtreeRegisterMigrator(reporters.NewReportFileWriterFactory(dir, log), true, false), validation.PostMigration(), }, ), diff --git a/cmd/util/ledger/migrations/cadence_value_validation.go b/cmd/util/ledger/migrations/cadence_value_validation.go index 004c2a77a28..acd99d01998 100644 --- a/cmd/util/ledger/migrations/cadence_value_validation.go +++ b/cmd/util/ledger/migrations/cadence_value_validation.go @@ -2,6 +2,7 @@ package migrations import ( "fmt" + "strings" "time" "github.com/onflow/atree" @@ -9,6 +10,7 @@ import ( "github.com/onflow/cadence/runtime" "github.com/onflow/cadence/runtime/common" "github.com/onflow/cadence/runtime/interpreter" + "github.com/rs/zerolog" "go.opentelemetry.io/otel/attribute" "github.com/onflow/flow-go/cmd/util/ledger/util" @@ -22,6 +24,8 @@ func validateCadenceValues( address common.Address, oldPayloads []*ledger.Payload, newPayloads []*ledger.Payload, + log zerolog.Logger, + verboseLogging bool, ) error { // Create all the runtime components we need for comparing Cadence values. oldRuntime, err := newReadonlyStorageRuntime(oldPayloads) @@ -36,7 +40,7 @@ func validateCadenceValues( // Iterate through all domains and compare cadence values. for _, domain := range domains { - err := validateStorageDomain(address, oldRuntime, newRuntime, domain) + err := validateStorageDomain(address, oldRuntime, newRuntime, domain, log, verboseLogging) if err != nil { return err } @@ -50,6 +54,8 @@ func validateStorageDomain( oldRuntime *readonlyStorageRuntime, newRuntime *readonlyStorageRuntime, domain string, + log zerolog.Logger, + verboseLogging bool, ) error { oldStorageMap := oldRuntime.Storage.GetStorageMap(address, domain, false) @@ -87,20 +93,63 @@ func validateStorageDomain( newValue := newStorageMap.ReadValue(nopMemoryGauge, interpreter.StringStorageMapKey(stringKey)) - if !cadenceValueEqual(oldRuntime.Interpreter, oldValue, newRuntime.Interpreter, newValue) { - return fmt.Errorf("failed to validate domain %s, key %s: old value %v (%T), new value %v (%T)", domain, key, oldValue, oldValue, newValue, newValue) + err := cadenceValueEqual(oldRuntime.Interpreter, oldValue, newRuntime.Interpreter, newValue) + if err != nil { + if verboseLogging { + log.Info(). + Str("address", address.Hex()). + Str("domain", domain). + Str("key", string(stringKey)). + Str("trace", err.Error()). + Str("old value", oldValue.String()). + Str("new value", newValue.String()). + Msgf("failed to validate value") + } + + return fmt.Errorf("failed to validate value for address %s, domain %s, key %s: %s", address.Hex(), domain, key, err.Error()) } } return nil } +type validationError struct { + trace []string + errorMsg string + traceReversed bool +} + +func newValidationErrorf(format string, a ...any) *validationError { + return &validationError{ + errorMsg: fmt.Sprintf(format, a...), + } +} + +func (e *validationError) addTrace(trace string) { + e.trace = append(e.trace, trace) +} + +func (e *validationError) Error() string { + if len(e.trace) == 0 { + return fmt.Sprintf("failed to validate: %s", e.errorMsg) + } + // Reverse trace + if !e.traceReversed { + for i, j := 0, len(e.trace)-1; i < j; i, j = i+1, j-1 { + e.trace[i], e.trace[j] = e.trace[j], e.trace[i] + } + e.traceReversed = true + } + trace := strings.Join(e.trace, ".") + return fmt.Sprintf("failed to validate %s: %s", trace, e.errorMsg) +} + func cadenceValueEqual( vInterpreter *interpreter.Interpreter, v interpreter.Value, otherInterpreter *interpreter.Interpreter, other interpreter.Value, -) bool { +) *validationError { switch v := v.(type) { case *interpreter.ArrayValue: return cadenceArrayValueEqual(vInterpreter, v, otherInterpreter, other) @@ -117,10 +166,23 @@ func cadenceValueEqual( default: oldValue, ok := v.(interpreter.EquatableValue) if !ok { - return false + return newValidationErrorf( + "value doesn't implement interpreter.EquatableValue: %T", + oldValue, + ) + } + if !oldValue.Equal(nil, interpreter.EmptyLocationRange, other) { + return newValidationErrorf( + "values differ: %v (%T) != %v (%T)", + oldValue, + oldValue, + other, + other, + ) } - return oldValue.Equal(nil, interpreter.EmptyLocationRange, other) } + + return nil } func cadenceSomeValueEqual( @@ -128,10 +190,10 @@ func cadenceSomeValueEqual( v *interpreter.SomeValue, otherInterpreter *interpreter.Interpreter, other interpreter.Value, -) bool { +) *validationError { otherSome, ok := other.(*interpreter.SomeValue) if !ok { - return false + return newValidationErrorf("types differ: %T != %T", v, other) } innerValue := v.InnerValue(vInterpreter, interpreter.EmptyLocationRange) @@ -146,36 +208,41 @@ func cadenceArrayValueEqual( v *interpreter.ArrayValue, otherInterpreter *interpreter.Interpreter, other interpreter.Value, -) bool { +) *validationError { otherArray, ok := other.(*interpreter.ArrayValue) if !ok { - return false + return newValidationErrorf("types differ: %T != %T", v, other) } count := v.Count() if count != otherArray.Count() { - return false + return newValidationErrorf("array counts differ: %d != %d", count, otherArray.Count()) } if v.Type == nil { if otherArray.Type != nil { - return false + return newValidationErrorf("array types differ: nil != %s", otherArray.Type) + } + } else { // v.Type != nil + if otherArray.Type == nil { + return newValidationErrorf("array types differ: %s != nil", v.Type) + } else if !v.Type.Equal(otherArray.Type) { + return newValidationErrorf("array types differ: %s != %s", v.Type, otherArray.Type) } - } else if otherArray.Type == nil || - !v.Type.Equal(otherArray.Type) { - return false } for i := 0; i < count; i++ { element := v.Get(vInterpreter, interpreter.EmptyLocationRange, i) otherElement := otherArray.Get(otherInterpreter, interpreter.EmptyLocationRange, i) - if !cadenceValueEqual(vInterpreter, element, otherInterpreter, otherElement) { - return false + err := cadenceValueEqual(vInterpreter, element, otherInterpreter, otherElement) + if err != nil { + err.addTrace(fmt.Sprintf("(%s[%d])", v.Type, i)) + return err } } - return true + return nil } func cadenceCompositeValueEqual( @@ -183,30 +250,42 @@ func cadenceCompositeValueEqual( v *interpreter.CompositeValue, otherInterpreter *interpreter.Interpreter, other interpreter.Value, -) bool { +) *validationError { otherComposite, ok := other.(*interpreter.CompositeValue) if !ok { - return false + return newValidationErrorf("types differ: %T != %T", v, other) } - if !v.StaticType(vInterpreter).Equal(otherComposite.StaticType(otherInterpreter)) || - v.Kind != otherComposite.Kind { - return false + if !v.StaticType(vInterpreter).Equal(otherComposite.StaticType(otherInterpreter)) { + return newValidationErrorf( + "composite types differ: %s != %s", + v.StaticType(vInterpreter), + otherComposite.StaticType(otherInterpreter), + ) } - var foundMismatch bool + if v.Kind != otherComposite.Kind { + return newValidationErrorf( + "composite kinds differ: %d != %d", + v.Kind, + otherComposite.Kind, + ) + } + + var err *validationError v.ForEachField(nopMemoryGauge, func(fieldName string, fieldValue interpreter.Value) bool { otherFieldValue := otherComposite.GetField(otherInterpreter, interpreter.EmptyLocationRange, fieldName) - if !cadenceValueEqual(vInterpreter, fieldValue, otherInterpreter, otherFieldValue) { - foundMismatch = true + err = cadenceValueEqual(vInterpreter, fieldValue, otherInterpreter, otherFieldValue) + if err != nil { + err.addTrace(fmt.Sprintf("(%s.%s)", v.TypeID(), fieldName)) return false } return true }) - return !foundMismatch + return err } func cadenceDictionaryValueEqual( @@ -214,19 +293,18 @@ func cadenceDictionaryValueEqual( v *interpreter.DictionaryValue, otherInterpreter *interpreter.Interpreter, other interpreter.Value, -) bool { - +) *validationError { otherDictionary, ok := other.(*interpreter.DictionaryValue) if !ok { - return false + return newValidationErrorf("types differ: %T != %T", v, other) } if v.Count() != otherDictionary.Count() { - return false + return newValidationErrorf("dict counts differ: %d != %d", v.Count(), otherDictionary.Count()) } if !v.Type.Equal(otherDictionary.Type) { - return false + return newValidationErrorf("dict types differ: %s != %s", v.Type, otherDictionary.Type) } oldIterator := v.Iterator() @@ -235,20 +313,27 @@ func cadenceDictionaryValueEqual( if key == nil { break } + oldValue, oldValueExist := v.Get(vInterpreter, interpreter.EmptyLocationRange, key) if !oldValueExist { - return false + err := newValidationErrorf("old value doesn't exist with key %v (%T)", key, key) + err.addTrace(fmt.Sprintf("(%s[%s])", v.Type, key)) + return err } newValue, newValueExist := otherDictionary.Get(otherInterpreter, interpreter.EmptyLocationRange, key) if !newValueExist { - return false + err := newValidationErrorf("new value doesn't exist with key %v (%T)", key, key) + err.addTrace(fmt.Sprintf("(%s[%s])", otherDictionary.Type, key)) + return err } - if !cadenceValueEqual(vInterpreter, oldValue, otherInterpreter, newValue) { - return false + err := cadenceValueEqual(vInterpreter, oldValue, otherInterpreter, newValue) + if err != nil { + err.addTrace(fmt.Sprintf("(%s[%s])", otherDictionary.Type, key)) + return err } } - return true + return nil } type readonlyStorageRuntime struct { diff --git a/cmd/util/ledger/migrations/cadence_value_validation_test.go b/cmd/util/ledger/migrations/cadence_value_validation_test.go index 7cad16c2c48..ab52742a5fd 100644 --- a/cmd/util/ledger/migrations/cadence_value_validation_test.go +++ b/cmd/util/ledger/migrations/cadence_value_validation_test.go @@ -1,16 +1,20 @@ package migrations import ( + "bytes" "fmt" "strconv" "testing" "github.com/onflow/cadence/runtime/common" "github.com/onflow/cadence/runtime/interpreter" + "github.com/onflow/flow-go/fvm/environment" "github.com/onflow/flow-go/ledger" "github.com/onflow/flow-go/ledger/common/convert" "github.com/onflow/flow-go/model/flow" + + "github.com/rs/zerolog" "github.com/stretchr/testify/require" ) @@ -20,12 +24,109 @@ func TestValidateCadenceValues(t *testing.T) { domain := common.PathDomainStorage.Identifier() - err = validateCadenceValues( - address, - createTestPayloads(t, address, domain), - createTestPayloads(t, address, domain), - ) - require.NoError(t, err) + t.Run("no mismatch", func(t *testing.T) { + log := zerolog.New(zerolog.NewTestWriter(t)) + + err := validateCadenceValues( + address, + createTestPayloads(t, address, domain), + createTestPayloads(t, address, domain), + log, + false, + ) + require.NoError(t, err) + }) + + t.Run("has mismatch", func(t *testing.T) { + var w bytes.Buffer + log := zerolog.New(&w) + + createPayloads := func(nestedArrayValue interpreter.UInt64Value) []*ledger.Payload { + + // Create account status payload + accountStatus := environment.NewAccountStatus() + accountStatusPayload := ledger.NewPayload( + convert.RegisterIDToLedgerKey( + flow.AccountStatusRegisterID(flow.ConvertAddress(address)), + ), + accountStatus.ToBytes(), + ) + + mr, err := newMigratorRuntime(address, []*ledger.Payload{accountStatusPayload}) + require.NoError(t, err) + + // Create new storage map + storageMap := mr.Storage.GetStorageMap(mr.Address, domain, true) + + // Add Cadence ArrayValue with nested CadenceArray + nestedArray := interpreter.NewArrayValue( + mr.Interpreter, + interpreter.EmptyLocationRange, + interpreter.VariableSizedStaticType{ + Type: interpreter.PrimitiveStaticTypeUInt64, + }, + address, + interpreter.NewUnmeteredUInt64Value(0), + nestedArrayValue, + ) + + storageMap.WriteValue( + mr.Interpreter, + interpreter.StringStorageMapKey(strconv.FormatUint(storageMap.Count(), 10)), + interpreter.NewArrayValue( + mr.Interpreter, + interpreter.EmptyLocationRange, + interpreter.VariableSizedStaticType{ + Type: interpreter.PrimitiveStaticTypeAnyStruct, + }, + address, + nestedArray, + ), + ) + + err = mr.Storage.Commit(mr.Interpreter, false) + require.NoError(t, err) + + // finalize the transaction + result, err := mr.TransactionState.FinalizeMainTransaction() + require.NoError(t, err) + + payloads := make([]*ledger.Payload, 0, len(result.WriteSet)) + for id, value := range result.WriteSet { + key := convert.RegisterIDToLedgerKey(id) + payloads = append(payloads, ledger.NewPayload(key, value)) + } + + return payloads + } + + oldPayloads := createPayloads(interpreter.NewUnmeteredUInt64Value(1)) + newPayloads := createPayloads(interpreter.NewUnmeteredUInt64Value(2)) + wantErrorMsg := "failed to validate value for address 0000000000000001, domain storage, key 0: failed to validate ([AnyStruct][0]).([UInt64][1]): values differ: 1 (interpreter.UInt64Value) != 2 (interpreter.UInt64Value)" + wantVerboseMsg := "{\"level\":\"info\",\"address\":\"0000000000000001\",\"domain\":\"storage\",\"key\":\"0\",\"trace\":\"failed to validate ([AnyStruct][0]).([UInt64][1]): values differ: 1 (interpreter.UInt64Value) != 2 (interpreter.UInt64Value)\",\"old value\":\"[[0, 1]]\",\"new value\":\"[[0, 2]]\",\"message\":\"failed to validate value\"}\n" + + // Disable verbose logging + err := validateCadenceValues( + address, + oldPayloads, + newPayloads, + log, + false, + ) + require.ErrorContains(t, err, wantErrorMsg) + require.Equal(t, 0, w.Len()) + + // Enable verbose logging + err = validateCadenceValues( + address, + oldPayloads, + newPayloads, + log, + true, + ) + require.ErrorContains(t, err, wantErrorMsg) + require.Equal(t, wantVerboseMsg, w.String()) + }) } func createTestPayloads(t *testing.T, address common.Address, domain string) []*ledger.Payload {