RPC getblock resulted in 500 and ReadBlockFromDisk: OpenBlockFile failed for FlatFilePos(nFile=-1, nPos=0) #20978

issue arcivanov openend this issue on January 21, 2021
  1. arcivanov commented at 5:47 pm on January 21, 2021: none

    Invoking HTTP RPC getblock resulted in the following failure:

    0status_code: 500 status: Internal Server Error response_body: {"result":null,"error":{"code":-1,"message":"Block not found on disk"}

    The logs have shown:

    02021-01-21T16:48:53Z Pre-allocating up to position 0x400000 in rev02417.dat
12021-01-21T16:48:53Z UpdateTip: new best=00000000000000000005656edcf6fb5cea1d2fe392841a9bdaa8b1fa821df661 height=667046 version=0x20004000 log2_work=92.608345 tx=608416058 date='2021-01-21T16:48:23Z' progress=1.000000 cache=95.6MiB(725599txo) warning='73 of last 100 blocks have unexpected version'
22021-01-21T16:59:14Z UpdateTip: new best=0000000000000000000383edc4ee51e5e55000c85ae844899e582aedc6d0cb2f height=667047 version=0x2000e000 log2_work=92.608362 tx=608418465 date='2021-01-21T16:58:42Z' progress=1.000000 cache=96.9MiB(735971txo) warning='73 of last 100 blocks have unexpected version'
3
42021-01-21T17:13:25Z ERROR: ReadBlockFromDisk: OpenBlockFile failed for FlatFilePos(nFile=-1, nPos=0)
5
62021-01-21T17:13:25Z UpdateTip: new best=0000000000000000000bc7c177f0ef9fa47492beb5c14250c6d412b12997a56b height=667048 version=0x20000000 log2_work=92.608379 tx=608421018 date='2021-01-21T17:13:24Z' progress=1.000000 cache=98.4MiB(747960txo) warning='72 of last 100 blocks have unexpected version'
72021-01-21T17:16:06Z UpdateTip: new best=000000000000000000034359728a89d359e6859f6908145594888c26f952dcb7 height=667049 version=0x20600000 log2_work=92.608396 tx=608423202 date='2021-01-21T17:15:51Z' progress=1.000000 cache=99.2MiB(754485txo) warning='73 of last 100 blocks have unexpected version'

    Expected behavior

    No error

    Actual behavior

    RPC 500 error returned and ReadBlockFromDisk ERROR logged.

    To reproduce

    Unknown.

    System information

    AWS K8S 4 CPUs/8Gi RAM, GP3 EBS 3000 IOPS/125Mips

     02021-01-21T15:30:54Z Bitcoin Core version v0.20.1 (release build)
 12021-01-21T15:30:54Z Assuming ancestors of block 0000000000000000000f2adce67e49b0b6bdeb9de8b7c3d7e93b21e7fc1e819d have valid signatures.
 22021-01-21T15:30:54Z Setting nMinimumChainWork=00000000000000000000000000000000000000000e1ab5ec9348e9f4b8eb8154
 32021-01-21T15:30:54Z Using the 'shani(1way,2way)' SHA256 implementation
 42021-01-21T15:30:54Z Using RdSeed as additional entropy source
 52021-01-21T15:30:54Z Using RdRand as an additional entropy source
 62021-01-21T15:30:54Z Default data directory /root/.bitcoin
 72021-01-21T15:30:54Z Using data directory /home/bitcoin/.bitcoin
 82021-01-21T15:30:54Z Config file: /home/bitcoin/.bitcoin/bitcoin.conf (not found, skipping)
 92021-01-21T15:30:54Z Command-line arg: datadir="/home/bitcoin/.bitcoin"
102021-01-21T15:30:54Z Command-line arg: rpcallowip="100.64.0.0/10"
112021-01-21T15:30:54Z Command-line arg: rpcbind=****
122021-01-21T15:30:54Z Command-line arg: rpcpassword=****
132021-01-21T15:30:54Z Command-line arg: rpcport="18332"
142021-01-21T15:30:54Z Command-line arg: rpcuser=****
152021-01-21T15:30:54Z Command-line arg: rpcworkqueue="4096"
162021-01-21T15:30:54Z Command-line arg: server=""
172021-01-21T15:30:54Z Command-line arg: txindex="1"
182021-01-21T15:30:54Z Using at most 125 automatic connections (1048576 file descriptors available)
192021-01-21T15:30:54Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
202021-01-21T15:30:54Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
212021-01-21T15:30:54Z Script verification uses 7 additional threads
222021-01-21T15:30:54Z scheduler thread start
232021-01-21T15:30:54Z WARNING: the RPC server is not safe to expose to untrusted networks such as the public internet
242021-01-21T15:30:54Z HTTP: creating work queue of depth 4096
252021-01-21T15:30:54Z Config options rpcuser and rpcpassword will soon be deprecated. Locally-run instances may remove rpcuser to use cookie-based auth, or may be replaced with rpcauth. Please see share/rpcauth for rpcauth auth generation.
262021-01-21T15:30:54Z HTTP: starting 4 worker threads
272021-01-21T15:30:54Z Using wallet directory /home/bitcoin/.bitcoin
282021-01-21T15:30:54Z init message: Verifying wallet(s)...
292021-01-21T15:30:54Z Using BerkeleyDB version Berkeley DB 4.8.30: (April  9, 2010)
302021-01-21T15:30:54Z Using wallet /home/bitcoin/.bitcoin
312021-01-21T15:30:54Z BerkeleyEnvironment::Open: LogDir=/home/bitcoin/.bitcoin/database ErrorFile=/home/bitcoin/.bitcoin/db.log
322021-01-21T15:30:54Z init message: Loading banlist...
332021-01-21T15:30:54Z Using /16 prefix for IP bucketing
342021-01-21T15:30:54Z Cache configuration:
352021-01-21T15:30:54Z * Using 2.0 MiB for block index database
362021-01-21T15:30:54Z * Using 56.0 MiB for transaction index database
372021-01-21T15:30:54Z * Using 8.0 MiB for chain state database
382021-01-21T15:30:54Z * Using 384.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
392021-01-21T15:30:54Z init message: Loading block index...
402021-01-21T15:30:54Z Opening LevelDB in /home/bitcoin/.bitcoin/blocks/index
412021-01-21T15:30:54Z Opened LevelDB successfully
422021-01-21T15:30:54Z Using obfuscation key for /home/bitcoin/.bitcoin/blocks/index: 0000000000000000
432021-01-21T15:30:58Z LoadBlockIndexDB: last block file = 2417
442021-01-21T15:30:58Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=6, size=8006735, heights=667029...667034, time=2021-01-21...2021-01-21)
452021-01-21T15:30:58Z Checking all blk files are present...
462021-01-21T15:30:58Z Opening LevelDB in /home/bitcoin/.bitcoin/chainstate
472021-01-21T15:30:58Z Opened LevelDB successfully
482021-01-21T15:30:58Z Using obfuscation key for /home/bitcoin/.bitcoin/chainstate: 8d04dcac7c5beaa0
492021-01-21T15:30:58Z Loaded best chain: hashBestChain=000000000000000000029ce801aba0474f571370c0f12808bae6501cf9ca1cec height=667034 date=2021-01-21T15:13:02Z progress=0.999994
502021-01-21T15:30:58Z init message: Rewinding blocks...
512021-01-21T15:30:58Z FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
522021-01-21T15:30:58Z FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
532021-01-21T15:30:58Z init message: Verifying blocks...
542021-01-21T15:30:58Z Verifying last 6 blocks at level 3
552021-01-21T15:30:58Z [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE].
562021-01-21T15:31:03Z No coin database inconsistencies in last 6 blocks (11765 transactions)
572021-01-21T15:31:03Z  block index            9520ms
582021-01-21T15:31:03Z Opening LevelDB in /home/bitcoin/.bitcoin/indexes/txindex
592021-01-21T15:31:03Z Opened LevelDB successfully
602021-01-21T15:31:03Z Using obfuscation key for /home/bitcoin/.bitcoin/indexes/txindex: 0000000000000000
612021-01-21T15:31:03Z init message: Loading wallet...
622021-01-21T15:31:03Z txindex thread start
632021-01-21T15:31:03Z txindex is enabled at height 667034
642021-01-21T15:31:03Z txindex thread exit
652021-01-21T15:31:03Z BerkeleyEnvironment::Open: LogDir=/home/bitcoin/.bitcoin/database ErrorFile=/home/bitcoin/.bitcoin/db.log
662021-01-21T15:31:03Z [default wallet] Wallet File Version = 169900
672021-01-21T15:31:03Z [default wallet] Keys: 2001 plaintext, 0 encrypted, 2001 w/ metadata, 2001 total. Unknown wallet records: 0
682021-01-21T15:31:03Z [default wallet] Wallet completed loading in              35ms
692021-01-21T15:31:03Z [default wallet] setKeyPool.size() = 2000
702021-01-21T15:31:03Z [default wallet] mapWallet.size() = 0
712021-01-21T15:31:03Z [default wallet] m_address_book.size() = 0
722021-01-21T15:31:03Z block tree size = 667038
732021-01-21T15:31:03Z nBestHeight = 667034
742021-01-21T15:31:03Z torcontrol thread start
752021-01-21T15:31:03Z Bound to [::]:8333
762021-01-21T15:31:03Z Bound to 0.0.0.0:8333
772021-01-21T15:31:03Z init message: Loading P2P addresses...
  2. arcivanov added the label Bug on Jan 21, 2021
  3. maflcko commented at 5:50 pm on January 21, 2021: member
    What was the argument passed to getblock?
  4. arcivanov commented at 5:53 pm on January 21, 2021: none

    Can’t tell you, not in the logs. I have a theory, because we have N load-balanced BTC nodes and it may have learned about the block from one of the nodes that had it but then requested it from the other that hasn’t yet had it.

    But in that case it shouldn’t be 500, more like 400 Bad Request - it’s not the user that failed, it’s the client that requested a non-existing block. But again, it’s only a theory.

  5. arcivanov commented at 5:54 pm on January 21, 2021: none
    Let me check other logs to see if I can find the block in question.
  6. arcivanov commented at 6:17 pm on January 21, 2021: none 
    02021-01-21 16:59:18.661  INFO 1   btc.state: {"current_block":667047}
12021-01-21 17:13:30.565  INFO 1   btc.state: {"current_block":667048}

    So I suspect current block was 667048.

  7. sipa commented at 6:18 pm on January 21, 2021: member
    Do you have pruning enabled?
  8. arcivanov commented at 6:20 pm on January 21, 2021: none 
    02021-01-21T15:30:54Z Config file: /home/bitcoin/.bitcoin/bitcoin.conf (not found, skipping)
12021-01-21T15:30:54Z Command-line arg: datadir="/home/bitcoin/.bitcoin"
22021-01-21T15:30:54Z Command-line arg: rpcallowip="100.64.0.0/10"
32021-01-21T15:30:54Z Command-line arg: rpcbind=****
42021-01-21T15:30:54Z Command-line arg: rpcpassword=****
52021-01-21T15:30:54Z Command-line arg: rpcport="18332"
62021-01-21T15:30:54Z Command-line arg: rpcuser=****
72021-01-21T15:30:54Z Command-line arg: rpcworkqueue="4096"
82021-01-21T15:30:54Z Command-line arg: server=""
92021-01-21T15:30:54Z Command-line arg: txindex="1"

    Nope.

  9. sipa commented at 6:21 pm on January 21, 2021: member
    Did you ever manually delete a blocks/blk*.dat file?
  10. arcivanov commented at 6:22 pm on January 21, 2021: none
    Nope. This is a sealed container with and EBS volume mounted. Nobody touches the container or volume by hand.
  11. maflcko commented at 6:23 pm on January 21, 2021: member
    • 2021-01-21 17:13:30.565 INFO 1 btc.state: {“current_block”:667048}
    • 2021-01-21T17:13:25Z ERROR: ReadBlockFromDisk: OpenBlockFile failed for FlatFilePos(nFile=-1, nPos=0)
    • 2021-01-21T17:13:25Z UpdateTip: new best=0000000000000000000bc7c177f0ef9fa47492beb5c14250c6d412b12997a56b height=667048 version=0x20000000 log2_work=92.608379 tx=608421018 date=‘2021-01-21T17:13:24Z’ progress=1.000000 cache=98.4MiB(747960txo) warning=‘72 of last 100 blocks have unexpected version’

    Looks like a race on your side

  12. arcivanov commented at 6:23 pm on January 21, 2021: none
    As I mentioned in #20978 (comment) I suspect we learned about the block from one node and requested it from another node via transparent loadbalancing.
  13. maflcko added the label RPC/REST/ZMQ on Jan 21, 2021
  14. arcivanov commented at 6:24 pm on January 21, 2021: none

    Looks like a race on your side

    Entirely possible, as I hypothesized in #20978 (comment), but then the error should be 400 not 500 - the server didn’t fail, the user did.

    Requesting a non-existent block is a failure of the user, not of the server. The node logs should be largely silent about it as well - not exactly a failure of the node.

  15. sipa commented at 6:25 pm on January 21, 2021: member
    I suspect that there was a race on our end too… the node probably had started processing the block when the RPC request came in, and it tried to look for something that it knew about but wasn’t on disk yet.
  16. arcivanov commented at 6:27 pm on January 21, 2021: none

    I suspect that there was a race on our end too..

    Also possible, hence I filed.

  17. adamjonas commented at 8:26 pm on March 9, 2023: member
    @arcivanov any chance you’d be willing to attempt to reproduce with an updated release?
  18. arcivanov commented at 3:23 am on March 10, 2023: none
    I could check the logs to see if it’s still the case.
  19. maflcko commented at 9:59 am on March 10, 2023: member
    @adamjonas See the last commit in #27237 on how to reproduce.
  20. willcl-ark commented at 8:46 pm on April 5, 2023: member

    But in that case it shouldn’t be 500, more like 400 Bad Request - it’s not the user that failed, it’s the client that requested a non-existing block. But again, it’s only a theory.

    This looks to me like it will be fixed by #27101 if requesting using json 2.0 spec, where we will return status code 200 (and only an error field). @pinheadmz might be able to confirm?

  21. pinheadmz commented at 10:48 am on April 6, 2023: member

    Indeed, #27101 will return 200 in this case, if the block is simply missing (see below). However there is also a log message in OP from ReadBlockFromDisk() which was passed a flat file position it was unable to read from (which is a server error, and should be 500 IMO)

     0--> curl -v  http://__cookie__:55e80812a35493cac882b0737da870ae44621120d9dcc0793382bd779b9dba80@127.0.0.1:18443 --data '{"method":"getblock", "params": ["00000000c937983704a73af28acdec37b049d214adbda81d7e2a3dd146f6ed09"], "jsonrpc": "2.0"}'
 1*   Trying 127.0.0.1:18443...
 2* Connected to 127.0.0.1 (127.0.0.1) port 18443 (#0)
 3* Server auth using Basic with user '__cookie__'
 4> POST / HTTP/1.1
 5> Host: 127.0.0.1:18443
 6> Authorization: Basic X19jb29raWVfXzo1NWU4MDgxMmEzNTQ5M2NhYzg4MmIwNzM3ZGE4NzBhZTQ0NjIxMTIwZDlkY2MwNzkzMzgyYmQ3NzliOWRiYTgw
 7> User-Agent: curl/7.79.1
 8> Accept: */*
 9> Content-Length: 119
10> Content-Type: application/x-www-form-urlencoded
11>
12* Mark bundle as not supporting multiuse
13< HTTP/1.1 200 OK
14< Content-Type: application/json
15< Date: Thu, 06 Apr 2023 10:44:27 GMT
16< Content-Length: 76
17<
18{"jsonrpc":"2.0","error":{"code":-5,"message":"Block not found"},"id":null}
19* Connection [#0](/bitcoin-bitcoin/0/) to host 127.0.0.1 left intact
  22. pinheadmz assigned pinheadmz on Jun 2, 2023
  23. fanquake commented at 9:25 am on July 4, 2024: member
    @willcl-ark was this fixed by #27101 ?
  24. maflcko commented at 10:58 am on July 4, 2024: member

    However there is also a log message in OP from ReadBlockFromDisk() which was passed a flat file position it was unable to read from (which is a server error, and should be 500 IMO)

    The issue explained in OP can normally happen in normal operation. See #20978 (comment) on how to reproduce.

    This is still the case. Header exists, but block has no data:

    0$ curl 'http://__cookie__:a@127.0.0.1:18442' --data '{"method":"getblock", "params": ["73df3f8f26b092b4b61ceddff7bd359f3b4591c5404d777e9a3fec6b6dc47b1b"]}'
1{"result":null,"error":{"code":-1,"message":"Block not found on disk"}}

    Header missing:

    0$ curl 'http://__cookie__:a@127.0.0.1:18442' --data '{"method":"getblock", "params": ["ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff"]}'
1{"result":null,"error":{"code":-5,"message":"Block not found"}}
  25. mzumsande commented at 6:18 pm on July 8, 2024: contributor

    If the block is not available anymore, we already throw a specific error: “Block not available (pruned data)”: rpc / rest

    So I think it would only be consistent to add a check for BLOCK_HAVE_DATA, not call ReadRawBlockFromDisk and return a similar error (e.g. “Block not available (not fully downloaded yet”) when the block is not available yet.

  26. mzumsande commented at 4:00 am on July 9, 2024: contributor
    see #30410
  27. achow101 closed this on Sep 16, 2024


arcivanov maflcko sipa adamjonas willcl-ark pinheadmz fanquake mzumsande

Labels
Bug RPC/REST/ZMQ

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-10-30 00:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me