eth_getStorageAt fails between forge and hardhat, but not BSC mainnet

[aathan]

Please see foundry-rs/foundry#1287

TL;DR
I've forked the BSC mainnet using the following hardhat network config. Calling cast call --rpc-url http://127.0.0.1:8545 "totalSupply()(uint256)" works fine, but Foundry's forge test using Solidity calls to print out the same information fail with 0 returned by totalSupply().

The exact same test code works fine when pointing forge directly to the BSC full node used to seed the hardhard fork.

It's believed the eth_getStorageAt RPC used by Foundry is failing for unknown reasons. Any clues as to how I may be able to turn on detailed logging in hardhat or where to look? The --verbose flag seems to do nothing.

npx hardhat node --verbose --network hardhat

        hardhat: {
            chainId: 56,
            gasPrice: 5000000000,
            forking: {
                //url: "https://bsc-dataseed.binance.org/",
                //url: "https://bsc-dataseed2.defibit.io/",
                //url: "https://bsc-dataseed1.binance.org",
                url: "https://speedy-nodes-nyc.moralis.io/<key>/bsc/mainnet/archive",
                enabled: true,
                blockNUmber: 16018498
            }
        }

The Forge log of the eth_getStorageAt request to hardhart (sorry about the ANSI codes, can't seem to turn that off):

^[[2m2022-04-13T14:28:27.775705Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mhyper::client::pool^[[0m^[[2m:^[[0m put; add idle connection for ("http", 127.0.0.1:8545)
^[[2m2022-04-13T14:28:27.775717Z^[[0m ^[[34mDEBUG^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mhyper::client::pool^[[0m^[[2m:^[[0m pooling idle connection for ("http", 127.0.0.1:8545)
^[[2m2022-04-13T14:28:27.775723Z^[[0m ^[[34mDEBUG^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mreqwest::async_impl::client^[[0m^[[2m:^[[0m response '200 OK' for http://127.0.0.1:8545/
^[[2m2022-04-13T14:28:27.775742Z^[[0m ^[[35mTRACE^[[0m ^[[2mbackendhandler^[[0m^[[2m:^[[0m Failed to get storage for 0xe9e7…7d56 at 3

The same part of the log when foundry goes directly to moralis full node:

^[[2m2022-04-13T14:26:27.622640Z^[[0m ^[[34mDEBUG^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mreqwest::async_impl::client^[[0m^[[2m:^[[0m response '200 OK' for https://speedy-nodes-nyc.moralis.io/<key>/bsc/mainnet/archive
^[[2m2022-04-13T14:26:27.622651Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mh2::proto::streams::recv^[[0m^[[2m:^[[0m release_capacity; size=103
^[[2m2022-04-13T14:26:27.622655Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mh2::proto::streams::recv^[[0m^[[2m:^[[0m release_connection_capacity; size=103, connection in_flight_data=103
^[[2m2022-04-13T14:26:27.622659Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mh2::proto::streams::recv^[[0m^[[2m:^[[0m release_capacity; size=0
^[[2m2022-04-13T14:26:27.622662Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mh2::proto::streams::recv^[[0m^[[2m:^[[0m release_connection_capacity; size=0, connection in_flight_data=0
^[[2m2022-04-13T14:26:27.622667Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mh2::proto::streams::streams^[[0m^[[2m:^[[0m drop_stream_ref; stream=Stream { id: StreamId(85), state: State { inner: Closed(EndStream) }, is_counted: false, ref_c\
ount: 1, next_pending_send: None, is_pending_send: false, send_flow: FlowControl { window_size: Window(65347), available: Window(0) }, requested_send_capacity: 0, buffered_send_data: 0, send_task: Some(Waker { data: 0x\
7f68e801a150, vtable: 0x55f7c9a51e58 }), pending_send: Deque { indices: None }, next_pending_send_capacity: None, is_pending_send_capacity: false, send_capacity_inc: true, next_open: None, is_pending_open: false, is_pe\
nding_push: false, next_pending_accept: None, is_pending_accept: false, recv_flow: FlowControl { window_size: Window(2097049), available: Window(2097152) }, in_flight_recv_data: 0, next_window_update: None, is_pending_\
window_update: false, reset_at: None, next_reset_expire: None, pending_recv: Deque { indices: None }, recv_task: None, pending_push_promises: Queue { indices: None, _p: PhantomData }, content_length: Omitted }
^[[2m2022-04-13T14:26:27.622676Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2mh2::proto::streams::counts^[[0m^[[2m:^[[0m transition_after; stream=StreamId(85); state=State { inner: Closed(EndStream) }; is_closed=true; pending_send_empty=tru\
e; buffered_send_data=0; num_recv=0; num_send=0
^[[2m2022-04-13T14:26:27.622688Z^[[0m ^[[35mTRACE^[[0m ^[[1mrpc^[[0m^[[1m{^[[0mmethod="eth_getStorageAt" params="[\"0xe9e7cea3dedca5984780bafc599bd69add087d56\",\"0x00000000000000000000000000000000000000000000000000000\
00000000003\",\"0xf46c42\"]"^[[1m}^[[0m^[[2m:^[[0m ^[[2methers_providers::provider^[[0m^[[2m:^[[0m ^[[3mrx^[[0m^[[2m=^[[0m"\"0x00000000000000000000000000000000000000000faca713cb3c91f8aa929157\""

[aathan]

Looks like this is just another case of:

foundry-rs/foundry#385

which hopefully is fixed by #2581