missing logs in eth_getLogs

pik694 commented 6 years ago

System information

Geth version: 1.8.18-stable OS & Version: Ubuntu 18.04.1 LTS Chain: rinkeby testnet

On one machine work one geth instance as well as two services. The first service sends transactions to geth, the other reads logs. Both services connected to the very same geth instance.

Expected behaviour

When using JSON RPC eth_getLogs endpoint with parameters given such as:

address;
fromblock;
toBlock;
topics; it should return all logs from the given range of blocks.
Actual behaviour

I am always asking for logs from the last 20 blocks. It sees all the logs correctly for a time, but then it does not return one log from the range. Then I keep asking for the corrupted range and the result keeps missing the same log. When I restart geth instance the missing log is back.

Steps to reproduce the behaviour

I'm deploying the contract on rinkeby testnet and one my services is sending transactions to it (lets say one per block) and the other check the events. For a couple of hours it works just fine, when suddenly geth does not return one of the event (via eth_getLogs). It does return events from the transactions that where mined after the one which logs are missing as well as from the transactions before. When I try to call eth.getTransactionReceipt from geth console it returns null, even though the transaction is seen by other nodes and on etherscan as well. On some other node I also call eth_getLogs and it returns the logs with the missing one.

What is more - when I kill the corrupted geth instance and restart it (I do not wipe out the data) the new instance returns correct results.

What is also strange is the fact that the first service (the one sending transactions) did see receipt.

I was able to reproduce this behaviour a couple of times so far.

Backtrace

This is a log from my code on corrupted geth

iex(10)> RootChain.get_block_submitted_events({3417982, 3418003})                                          
{:ok,
 [
   %{blknum: 4894000, eth_height: 3417982},
   %{blknum: 4895000, eth_height: 3417983},
   %{blknum: 4896000, eth_height: 3417984},
   %{blknum: 4897000, eth_height: 3417985},
   %{blknum: 4898000, eth_height: 3417986},
   %{blknum: 4899000, eth_height: 3417987},
   %{blknum: 4900000, eth_height: 3417988},
   %{blknum: 4901000, eth_height: 3417989},
   %{blknum: 4902000, eth_height: 3417990},
   %{blknum: 4903000, eth_height: 3417991},
   %{blknum: 4904000, eth_height: 3417992},
   %{blknum: 4905000, eth_height: 3417993},
   %{blknum: 4906000, eth_height: 3417994},
   %{blknum: 4907000, eth_height: 3417995},
   %{blknum: 4908000, eth_height: 3417996},
   %{blknum: 4909000, eth_height: 3417997},
   %{blknum: 4910000, eth_height: 3417998},
   %{blknum: 4911000, eth_height: 3417999},
   %{blknum: 4912000, eth_height: 3418000},
   %{blknum: 4913000, eth_height: 3418001},
   %{blknum: 4915000, eth_height: 3418003} <-- missing blknum 4914000 which was submitted to block no 3418002
 ]}
iex(11)> Ethereumex.HttpClient.eth_get_logs(%{fromBlock: OMG.Eth.Encoding.to_hex(3417982), toBlock: Eth.Encoding.to_hex(3418003), address: contract}) |> elem(1) |> length
21

From geth console:

>eth.getTransactionReceipt("0xd02b54f463e469a517025b5752d5e807f2c98fcc936e64dfb5a5b9865ded3877")
null

When I restart geth:

iex(18)> RootChain.get_block_submitted_events({3417982, 3418003})
{:ok,
 [
   %{blknum: 4894000, eth_height: 3417982},
   %{blknum: 4895000, eth_height: 3417983},
   %{blknum: 4896000, eth_height: 3417984},
   %{blknum: 4897000, eth_height: 3417985},
   %{blknum: 4898000, eth_height: 3417986},
   %{blknum: 4899000, eth_height: 3417987},
   %{blknum: 4900000, eth_height: 3417988},
   %{blknum: 4901000, eth_height: 3417989},
   %{blknum: 4902000, eth_height: 3417990},
   %{blknum: 4903000, eth_height: 3417991},
   %{blknum: 4904000, eth_height: 3417992},
   %{blknum: 4905000, eth_height: 3417993},
   %{blknum: 4906000, eth_height: 3417994},
   %{blknum: 4907000, eth_height: 3417995},
   %{blknum: 4908000, eth_height: 3417996},
   %{blknum: 4909000, eth_height: 3417997},
   %{blknum: 4910000, eth_height: 3417998},
   %{blknum: 4911000, eth_height: 3417999},
   %{blknum: 4912000, eth_height: 3418000},
   %{blknum: 4913000, eth_height: 3418001},
   %{blknum: 4914000, eth_height: 3418002}, <-- it now appears in logs
   %{blknum: 4915000, eth_height: 3418003}
 ]}
iex(16)> Ethereumex.HttpClient.eth_get_logs(%{fromBlock: OMG.Eth.Encoding.to_hex(3417982), toBlock: Eth.Encoding.to_hex(3418003), address: contract}) |> elem(1) |> length
22

And from geth console

>eth.getTransactionReceipt("0xd02b54f463e469a517025b5752d5e807f2c98fcc936e64dfb5a5b9865ded3877")
{
  blockHash: "0x9f96a9d9d575e2e3d97466017f7f1411dab38eb79546733720ca5f655e77584a",
  blockNumber: 3418002,
  contractAddress: null,
  cumulativeGasUsed: 704548,
  from: "0x7533ec99687aadb867d22bb491dd62f81775995b",
  gasUsed: 76222,
  logs: [{
      address: "0xbb5cb4ed80d44a76035fd4e27807c6248b60fc96",
      blockHash: "0x9f96a9d9d575e2e3d97466017f7f1411dab38eb79546733720ca5f655e77584a",
      blockNumber: 3418002,
      data: "0x00000000000000000000000000000000000000000000000000000000004afb50",
      logIndex: 8,
      removed: false,
      topics: ["0x5a978f4723b249ccf79cd7a658a8601ce1ff8b89fc770251a6be35216351ce32"],
      transactionHash: "0xd02b54f463e469a517025b5752d5e807f2c98fcc936e64dfb5a5b9865ded3877",
      transactionIndex: 5
  }],
  logsBloom: "0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000002000000000000000000000000000000000000000000000002000000000000000000000000000001000000000000000000000000000000000000000000000000000000000000040000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000040000000000000000000000000000000000000000000000000000000000000000000000100000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
  status: "0x1",
  to: "0xbb5cb4ed80d44a76035fd4e27807c6248b60fc96",
  transactionHash: "0xd02b54f463e469a517025b5752d5e807f2c98fcc936e64dfb5a5b9865ded3877",
  transactionIndex: 5
}

pdobacz commented 5 years ago

anyone, any ideas what might cause such behavior? (looks like some receipts can be inaccessible until next time geth is restarted, after which they appear correctly again).

stale[bot] commented 4 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

holiman commented 4 years ago

This is indicative of some sort of race, where our internal receipt-cache is polluted, probably by not properly handling a reorg and updating to the new canon status.

holiman commented 4 years ago

When this happens, it would be good to know if eth.getTransaction{xx} also fails with null, or if it's only the eth.getTransactionReceipt that fails

holiman commented 4 years ago

Oh, https://github.com/omisego/elixir-omg/issues/284 is closed -- I would guess that means this is no longer relevant? Let's auto-close after some time

pdobacz commented 4 years ago

Hello @holiman and thank you for looking into.

Confirming, that the very manifestation of this we used to have is now gone.

So I'm afraid we don't have a chance to reproduce or debug this better. If it resurfaces, we'll let know!

adamschmideg commented 4 years ago

Thank you, closing then for now

ethereum / go-ethereum