Unexpected changes in an account's storage capacity

[chandanworkacct]

Problem

Querying the storage capacity of an account returns different values even though there is no change in the number of FLOW tokens held by the account.

Here is an example transaction.
https://flow-view-source.com/testnet/tx/5f34f968421e7777cfa71583f5f761c903914500992f6881507d1e5776ed1ef1

Please note that a similar transaction doesn't display the issue.
https://flow-view-source.com/testnet/tx/6669920efbc135c6bb8d2871a1b7a27d42d0dc3c1914b86baba45155e4a28f38

Steps to Reproduce

Execute the transaction mentioned in this link:
https://flow-view-source.com/testnet/tx/5f34f968421e7777cfa71583f5f761c903914500992f6881507d1e5776ed1ef1

[turbolent]

Research so far: Not a Cadence issue, likely a FVM issue. Robert will keep investigating, will ask for help from Janez when possible. Also, document process of adding FVM test

[robert-e-davidson3]

Repro in flow-go is showing no error.

• Is it possible to repro on testnet?
• Might be a version mismatch. Which version of flow-go was the testnet running at the time? I tried a few.
• The test I'm using might be missing necessary configuration or setup steps.
• The issue might only arise in the full system instead of just the FVM+Cadence part of the system. My understanding is that a race conditio shouldn't occur here but the bug looks like a race condition...

I tested these versions of flow-go:

• commit 0212da64f9578bd4c5588cba5ae776e82f40ea22 (HEAD, tag: v0.20.0)
• 4bf7baa10 (tag: v0.21.1)
• 656965061 (master)

My test approach was to copy an existing test in fvm/transaction_test.go but use the repro transaction. I left most of the test in place so this isn't a minimal repro attempt.

There's a panic call at the end to ensure that panics are percolating up. If the wrong panic causes the test to fail then reproduction failed. The wrong panic in this case is panicking throws an error.

Test code I used:

	t.Run("OneOffTest", func(t *testing.T) {
		rt := fvm.NewInterpreterRuntime()
		log := zerolog.Nop()
		vm := fvm.NewVirtualMachine(rt)
		// create default context
		context := fvm.NewContext(log)
		programsStorage := programs.NewEmptyPrograms()

		ledger := testutil.RootBootstrappedLedger(vm, context)

		privateKeys, err := testutil.GenerateAccountPrivateKeys(2)
		require.NoError(t, err)

		// Bootstrap a ledger, creating accounts with the provided private keys and the root account.
		accounts, err := testutil.CreateAccounts(vm, ledger, programsStorage, privateKeys, context.Chain)
		require.NoError(t, err)

		address := accounts[0]
		target := accounts[1]

		code := fmt.Sprintf(`
			import FungibleToken from 0xf233dcee88fe0abe

			transaction {
				prepare(signer: AuthAccount) {
					let vaultRef = signer.borrow<&{FungibleToken.Provider}>(from: /storage/flowTokenVault)
						?? panic("Could not borrow reference to the owner's Vault!")
	
					let recipient = getAccount(0x%s)
					let receiverRef = recipient.getCapability(/public/flowTokenReceiver).borrow<&{FungibleToken.Receiver}>()
						?? panic("Could not borrow receiver reference to the recipient's Vault")
	
					receiverRef.deposit(from: <- vaultRef.withdraw(amount: 1.0))

					var storageCapacity1: UInt64 = signer.storageCapacity
					var storageUsed1: UInt64 = signer.storageUsed
					var storageCapacity2: UInt64 = signer.storageCapacity
					var storageUsed2: UInt64 = signer.storageUsed
					
					if (storageCapacity1 != storageCapacity2) || (storageUsed1 != storageUsed2) {
						panic(storageCapacity1.toString().concat(" vs ").concat(storageCapacity2.toString()).concat(", ").concat(storageUsed1.toString()).concat(" vs ").concat(storageUsed2.toString()))
					}

					panic("panicking throws an error")
				}
				execute {
					setAccountFrozen(0x%s, true)
				}
			}
		`, target.String(), address.String())

		txBody := &flow.TransactionBody{Script: []byte(code)}
		txBody.SetPayer(accounts[0])
		txBody.SetProposalKey(accounts[0], 0, 0)

		err = testutil.SignEnvelope(txBody, accounts[0], privateKeys[0])
		require.NoError(t, err)

		tx := fvm.Transaction(txBody, 0)
		err = vm.Run(context, tx, ledger, programsStorage)
		require.NoError(t, err)
		require.Error(t, tx.Err)

		require.Contains(t, tx.Err.Error(), "cannot find")
		require.Contains(t, tx.Err.Error(), "setAccountFrozen")
		require.Equal(t, (&errors.CadenceRuntimeError{}).Code(), tx.Err.Code())

		// sign tx by service account now
		txBody = &flow.TransactionBody{Script: []byte(code)}
		txBody.AddAuthorizer(serviceAddress)
		txBody.SetPayer(serviceAddress)
		txBody.SetProposalKey(serviceAddress, 0, 0)

		err = testutil.SignEnvelope(txBody, serviceAddress, unittest.ServiceAccountPrivateKey)
		require.NoError(t, err)

		tx = fvm.Transaction(txBody, 0)
		err = vm.Run(context, tx, ledger, programsStorage)
		require.NoError(t, err)

		require.NoError(t, tx.Err)
	})

[robert-e-davidson3]

The links are broken. Here are some that work:

• https://testnet.flowscan.org/transaction/5f34f968421e7777cfa71583f5f761c903914500992f6881507d1e5776ed1ef1/script
• https://testnet.flowscan.org/transaction/6669920efbc135c6bb8d2871a1b7a27d42d0dc3c1914b86baba45155e4a28f38/script

[turbolent]

@janezpodhostnik Could you or someone else from EN/FVM help Robert with reproducing the problem? Maybe we can replay the particular transaction in question using the remote debugger?

[janezpodhostnik]

Perhaps it has something to do with this:

cadence/runtime/runtime.go

Line 1841 in 929eabb

err := storage.Commit(inter, commitContractUpdates)

and the lack of this commit when asking for storage capacity...

@robert-e-davidson3 Lets get together next week and try using the remote debugger.

[robert-e-davidson3]

There's a more basic bug here: signer.storageCapacity does not update when the flow token balance changes:

				var cap0: UInt64 = signer.storageCapacity
				receiverRef.deposit(from: <- vaultRef.withdraw(amount: 1.0))
				var cap1: UInt64 = signer.storageCapacity
				panic("cap0=".concat(cap0.toString()).concat("; cap1=").concat(cap1.toString()).concat("; diff=").concat((cap0 - cap1).toString()))

panic: cap0=1192313051173589; cap1=1192313051173589; diff=0

This bug report is so weird because it does update when signer.storageUsed is called:

				var cap0: UInt64 = signer.storageCapacity
				receiverRef.deposit(from: <- vaultRef.withdraw(amount: 1.0))

				signer.storageUsed

				var cap1: UInt64 = signer.storageCapacity
				panic("cap0=".concat(cap0.toString()).concat("; cap1=").concat(cap1.toString()).concat("; diff=").concat((cap0 - cap1).toString()))

panic: cap0=1192313051173589; cap1=1192312951173589; diff=100000000

(I tested using remote debugging against testnet.)

[turbolent]

Great analysis @robert-e-davidson3!

I think we had not considered that the storageCapacity may also change during program execution, if the account received FLOW. Storage changes are not committed until the end of program execution. Because of that, storageUsed already commits changes when it is accessed. The solution here might be to also commit when storageCapacity is accessed.